Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

STB: primary CPU thread not aborting immedaitely after a secondary CPU job got abort. #148

Open
pridhiviraj opened this issue Feb 8, 2018 · 3 comments

Comments

@pridhiviraj
Copy link
Contributor

 66.01168|====================[   66.011887081,5] OPAL skiboot-v5.9-240-g081882690163-pcbedce4 starting...
[   66.011894300,7] initial console log level: memory 7, driver 5
[   66.011896673,6] CPU: P9 generation processor (max 4 threads/core)
[   66.011898763,7] CPU: Boot CPU PIR is 0x0004 PVR is 0x004e1200
[   66.011901029,7] CPU: Initial max PIR set to 0x7fff
[   66.013275671,7] OPAL table: 0x300f3430 .. 0x300f3980, branch table: 0x30002000
[   66.013279680,7] Assigning physical memory map table for nimbus
[   66.013282901,7] Parsing HDAT...
[   66.013284388,5] SPIRA-S found.
[   66.013287548,6] BMC #0: HW version 3, SW version 2, chip DD1.0
[   66.013594020,6] SP Family is ibm,ast2500,supermicro
[   66.013601470,7] LPC: IOPATH chip id = 0
[   66.013602989,7] LPC: FW BAR       = f0000000
[   66.013604654,7] LPC: MEM BAR      = e0000000
[   66.013606323,7] LPC: IO BAR       = d0010000
[   66.013607996,7] LPC: Internal BAR = c0012000
[   66.013621312,7] LPC UART: base addr = 3f8 (3f8) size = 1 clk = 1843200, baud = 115200
[   66.013624456,7] LPC: BT [0, 0] sms_int: 0, bmc_int: 0
[   66.069159648,5] UART: Using UART at 0x60300d00103f8
[   66.074079250,3] I2C: v2 found, but not supported. Parsing as v1
[   66.077302945,3] I2C: v2 found, but not supported. Parsing as v1
[   66.082093710,5] P9 DD2.00 detected
[   66.083712465,5] CHIP: Chip ID 0000 type: P9N DD2.0
[   66.086219502,5] P9 DD2.00 detected
[   66.088692685,5] CHIP: Chip ID 0008 type: P9N DD2.0
[   66.091625140,5] PLAT: Using���m�����r�ʚ������b���
                                                     �('H�outing irq 9, policy: 0 (r=1)
[   66.093776222,7] LPC: SerIRQ 9 using route 0 targetted at OPAL
[   66.099718681,5] PLAT: Detected p9dsu2u platform
[   66.102200394,5] PLAT: Detected BMC platform SMC
[   66.133107624,5] CPU: All 128 processors called in...
[   68.004878257,3] MBOX-FLASH: Bad response code from BMC 2
[   68.007064573,3] MBOX-FLASH: Error waiting for BMC
[   68.420329767,5] FLASH: Found system flash:  id:0
[   68.422313593,5] BT: Interface initialized, IO 0x00e4
[   68.425131211,7] LPC: Routing irq 10, policy: 0 (r=1)
[   68.425132341,7] LPC: SerIRQ 10 using route 1 targetted at OPAL
[   69.483549221,0] STB: VERSION NOT VERIFIED, invalid param. buf=0x305ed9e0, len=4096 key-hash=0x0 hash-size=0
[   69.489470246,5] NVRAM: Size is 576 KB
[   70.079277952,5] console: Setting driver log level to 7
[   70.079287356,7] LPC-MBOX: Sending BMC interrupt
[   70.079383270,6] BT: seq 0x05 netfn 0x06 cmd 0x06: IPMI MSG done
[   70.079437430,6] BT: seq 0x06 netfn 0x06 cmd 0x2e: Message sent to host
[   70.090028497,7] NVRAM: 'log-level-memory' not found
[   70.092866731,5] STB: Found ibm,secureboot-v2
[   70.094995784,7] NVRAM: Searched for 'force-secure-mode' found 'always'
[   70.098544526,5] STB: secure mode on (FORCED by nvram)
[   70.100682149,6] STB: Found CVC @ 203ffd260000-203ffd26ffff
[   70.103520390,6] STB: Found CVC-sha512 @ 203ffd260040, version=1
[   70.107065944,6] STB: Found CVC-verify @ 203ffd260050, version=1
[   70.109907450,7] NVRAM: 'force-trusted-mode' not found
[   70.112745453,5] STB: trusted mode off
[   70.114170054,5] OPAL: Using OPAL UART console
[   70.117004278,7] NVRAM: 'uart-con-policy' not found
[   70.119141261,7] LPC: Routing irq 4, policy: 0 (r=1)
[   70.119142308,7] LPC: SerIRQ 4 using route 2 targetted at OPAL
[   70.124816744,7] SLW: Init chip 0x0
[   70.126240442,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.129789010,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.133335923,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.136179875,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.139729120,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.143276085,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.146825633,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.149668887,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.153217803,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.156764344,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.159610267,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.163156883,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.166706109,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.169549685,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.173096936,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.176645879,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.179495069,5] SLW: Configuring self-restore for HRMOR
[   70.182251252,6] BT: seq 0x06 netfn 0x06 cmd 0x2e: IPMI MSG done
[   70.182331312,6] BT: seq 0x07 netfn 0x04 cmd 0x30: Message sent to host
[   70.182334006,7] blocklevel_read: 0x0	0x31c03b20	0x30
[   70.182335298,7] blocklevel_raw_read: 0x0	0x31c03b20	0x30
[   70.182345173,7] FFS: Partition map size: 0x1000
[   70.182346088,7] blocklevel_read: 0x0	0x306c1528	0x1000
[   70.182347281,7] blocklevel_raw_read: 0x0	0x306c1528	0x1000
[   70.185117604,7] FLASH: IMA_CATALOG partition has ECC
[   70.185118664,7] blocklevel_read: 0x3149000	0x3067f0e0	0x1000
[   70.185119959,7] blocklevel_read: region has ECC
[   70.185120931,7] blocklevel_raw_read: 0x3149000	0x306c2ee8	0x1200
[   70.186501582,7] FLASH: IMA_CATALOG partition is signed
[   70.186502607,7] blocklevel_read: 0x314a200	0x306800e0	0x11000
[   70.186503951,7] blocklevel_read: region has ECC
[   70.186504940,7] blocklevel_raw_read: 0x314a200	0x306c2ee8	0x13200
[   70.206092674,7] FLASH: flash subpartition eyecatcher IMCC
[   70.220219562,6] STB: IMA_CATALOG verified
[   70.233916665,7] SLW: Init chip 0x8
[   70.235335577,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.238880075,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.242426979,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.245272651,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.248819587,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.252368600,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.255212713,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.258759644,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.262308532,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.265855425,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.268701347,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.272248342,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.275796841,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.278640491,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.282188293,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.285736918,7] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[   70.288580223,5] SLW: Configuring self-restore for HRMOR
[   70.291426805,7] CPU idle state device tree init
[   70.293552940,5] SLW: Enabling: stop0_lite
[   70.295680896,5] SLW: Enabling: stop0
[   70.297808226,5] SLW: Enabling: stop1_lite
[   70.299937395,5] SLW: Enabling: stop1
[   70.302064889,5] SLW: Enabling: stop2_lite
[   70.304196026,5] SLW: Enabling: stop2
[   70.305622012,7] NVRAM: 'pcie-max-link-speed' not found
[   70.308514601,6] CAPI: Preloading ucode 200d1
[   70.310587790,7] FLASH: Queueing preload of 2/200d1
[   70.313424552,7] FLASH: Queueing preload of 0/0
[   70.313435935,7] LPC-MBOX: Sending BMC interrupt
[   70.313953433,6] BT: seq 0x07 netfn 0x04 cmd 0x30: IPMI MSG done
[   70.320530204,7] FLASH: Queueing preload of 1/0
[   70.324363352,5] VAS: Initialized chip 0
[   70.326546454,5] VAS: Initialized chip 8
[   70.327950838,6] NX RNG[0] pace:2000
[   70.330018665,6] NX0: Crypto at 0x2010000
[   70.332148306,6] NX0: POWER9 nx-crypto not yet supported
[   70.334987225,6] NX0: 842 at 0x2010000
[   70.336411628,5] Found ibm,power9-nx
[   70.338538963,7] NX0: UMAC VAS MMIO BAR, 0x0006019100000000, xcfg 0x20110d4
[   70.342089619,7] NX0: DMA VAS MMIO BAR, 0x0006019100000000, xcfg 0x201105e
[   70.345639486,7] NX0: UMAC SEND WC BAR, 0x0000000054800000, xcfg 0x20110d2
[   70.349189354,7] NX0: Setting UMAC Status Control 0x7000000000000000
[   70.352032632,7] NX0:   DMA 0x00ffc1987f800080
[   70.354166191,7] NX0: Setting UMAC FIFO bar 0x0000000055008280
[   70.357708346,7] NX0: Setting UMAC notify match 0x0fff000003000011
[   70.360556859,7] NX0: Setting UMAC FIFO bar 0x0000000055018280
[   70.363393269,7] NX0: Setting UMAC notify match 0x0fff000003000021
[   70.366938314,7] NX0:   Engine Enable 0x8000000000000067
[   70.369074010,6] NX0: 842 Coprocessor Enabled
[   70.371907441,6] NX0: gzip at 0x2010000
[   70.373333041,7] NX0:   DMA 0x00ffc1987f800080
[   70.376168852,7] NX0:   Engine Enable 0x8000000000000067
[   70.378307171,7] NX0: Setting UMAC FIFO bar 0x0000000055028280
[   70.381848391,7] NX0: Setting UMAC notify match 0x0fff000002000011
[   70.384693846,7] NX0: Setting UMAC FIFO bar 0x0000000055038280
[   70.387532115,7] NX0: Setting UMAC notify match 0x0fff000002000021
[   70.391078681,6] NX0: gzip Coprocessor Enabled
[   70.393217334,6] NX RNG[8] pace:2000
[   70.394631897,6] NX8: Crypto at 0x2010000
[   70.396762524,6] NX8: POWER9 nx-crypto not yet supported
[   70.399600984,6] NX8: 842 at 0x2010000
[   70.401728748,5] Found ibm,power9-nx
[   70.403152608,7] NX8: UMAC VAS MMIO BAR, 0x0006219100000000, xcfg 0x20110d4
[   70.406702212,7] NX8: DMA VAS MMIO BAR, 0x0006219100000000, xcfg 0x201105e
[   70.410252419,7] NX8: UMAC SEND WC BAR, 0x0000200003000000, xcfg 0x20110d2
[   70.413802977,7] NX8: Setting UMAC Status Control 0x7000000000000000
[   70.416628054,7] blocklevel_read: 0x0	0x31c03b20	0x30
[   70.416629523,7] blocklevel_raw_read: 0x0	0x31c03b20	0x30
[   70.416651644,7] FFS: Partition map size: 0x1000
[   70.416652593,7] blocklevel_read: 0x0	0x306e2628	0x1000
[   70.416653901,7] blocklevel_raw_read: 0x0	0x306e2628	0x1000
[   70.418395117,7] FLASH: CAPP partition has ECC
[   70.418395993,7] blocklevel_read: 0x3104000	0x306c1940	0x1000
[   70.418397444,7] blocklevel_read: region has ECC
[   70.418398473,7] blocklevel_raw_read: 0x3104000	0x306e3fe8	0x1200
[   70.419297347,7] FLASH: CAPP partition is signed
[   70.419298195,7] blocklevel_read: 0x3105200	0x306c2940	0x1a000
[   70.419299623,7] blocklevel_read: region has ECC
[   70.419300621,7] blocklevel_raw_read: 0x3105200	0x306e3fe8	0x1d400
[   70.446049356,7] FLASH: flash subpartition eyecatcher CAPP
[   70.446052897,0] STB: CAPP verification FAILED. log=0xffffffffffff8160
[   70.446054261,0] STB: secure mode enforced, aborting.
[   70.446055097,0] Aborting!
CPU 0000 Backtrace:
 S: 0000000031c039c0 R: 00000000300136d8   .backtrace+0x48
 S: 0000000031c03a60 R: 0000000030019ed0   ._abort+0x4c
 S: 0000000031c03ae0 R: 000000003009cf14   .secureboot_enforce+0x3c
 S: 0000000031c03b50 R: 000000003009d334   .secureboot_verify+0xc0
 S: 0000000031c03bf0 R: 000000003002ec6c   .flash_load_resources+0x680
 S: 0000000031c03d40 R: 0000000030018088   .cpu_process_jobs+0xdc
 S: 0000000031c03e00 R: 0000000030014d38   .__secondary_cpu_entry+0x44
 S: 0000000031c03e80 R: 0000000030014d8c   .secondary_cpu_entry+0x34
 S: 0000000031c03f00 R: 0000000030002748   secondary_wait+0x8c
[   70.447972204,6] BT: seq 0x08 netfn 0x0a cmd 0x42: Message sent to host
[   70.497879816,7] NX8:   DMA 0x00ffc1987f800080
[   70.500013673,7] NX8: Setting UMAC FIFO bar 0x0000200003808280
[   70.503554992,7] NX8: Setting UMAC notify match 0x0fff000003000031
[   70.506402421,7] NX8: Setting UMAC FIFO bar 0x0000200003818280
[   70.509240545,7] NX8: Setting UMAC notify match 0x0fff000003000041
[   71.000786474,7] NX8:   Engine Enable 0x8000000000000067
[   71.002919939,6] NX8: 842 Coprocessor Enabled
[   71.005754314,6] NX8: gzip at 0x2010000
[   71.007181634,7] NX8:   DMA 0x00ffc1987f800080
[   71.010014825,7] NX8:   Engine Enable 0x8000000000000067
[   71.012154705,7] NX8: Setting UMAC FIFO bar 0x0000200003828280
[   71.015695972,7] NX8: Setting UMAC notify match 0x0fff000002000031
[   71.018541672,7] NX8: Setting UMAC FIFO bar 0x0000200003838280
[   71.021379595,7] NX8: Setting UMAC notify match 0x0fff000002000041
[   71.024926790,6] NX8: gzip Coprocessor Enabled
[   71.029938937,7] NVRAM: 'pci-eeh-verbose' not found
[   71.031773211,6] PHB4: Verbose EEH enabled
[   71.033902854,7] NVRAM: 'pci-tracing' not found
[   71.036033057,7] NVRAM: 'pci-eeh-mmio' not found
[   71.038870083,7] NVRAM: 'pci-retry-all' not found
[   71.041038795,6] PHB: Chip 0 Found PHB4 PBCQ0 Stack 0 at /xscom@603fc00000000/pbcq@4010c00/stack@0
[   71.045967979,7] PHB[0:0] X[PE]=0x04010c00/0x04010c40 X[PCI]=0x0d010800/0x0d010840 X[ETU]=0x0d010900
[   71.050235612,7] ETU reset: 0
[   71.052172905,7] Version reg: 0x000000a400000002
[   71.054493938,6] PHB: Chip 0 Found PHB4 PBCQ1 Stack 0 at /xscom@603fc00000000/pbcq@4011000/stack@0
[   71.058750538,7] PHB[0:1] X[PE]=0x04011000/0x04011040 X[PCI]=0x0e010800/0x0e010840 X[ETU]=0x0e010900
[   71.064246280,6] PHB: Chip 0 Found PHB4 PBCQ1 Stack 1 at /xscom@603fc00000000/pbcq@4011000/stack@1
[   71.068339826,7] PHB[0:2] X[PE]=0x04011000/0x04011080 X[PCI]=0x0e010800/0x0e010880 X[ETU]=0x0e010940
[   71.073837089,6] PHB: Chip 0 Found PHB4 PBCQ2 Stack 0 at /xscom@603fc00000000/pbcq@4011400/stack@0
[   71.077929824,7] PHB[0:3] X[PE]=0x04011400/0x04011440 X[PCI]=0x0f010800/0x0f010840 X[ETU]=0x0f010900
[   71.083426089,6] PHB: Chip 0 Found PHB4 PBCQ2 Stack 1 at /xscom@603fc00000000/pbcq@4011400/stack@1
[   71.087519212,7] PHB[0:4] X[PE]=0x04011400/0x04011480 X[PCI]=0x0f010800/0x0f010880 X[ETU]=0x0f010940
[   71.093015101,6] PHB: Chip 0 Found PHB4 PBCQ2 Stack 2 at /xscom@603fc00000000/pbcq@4011400/stack@2
[   71.097109192,7] PHB[0:5] X[PE]=0x04011400/0x040114c0 X[PCI]=0x0f010800/0x0f0108c0 X[ETU]=0x0f010980
[   71.102610713,6] PHB: Chip 8 Found PHB4 PBCQ0 Stack 0 at /xscom@623fc00000000/pbcq@4010c00/stack@0
[   71.106707787,7] PHB[8:0] X[PE]=0x04010c00/0x04010c40 X[PCI]=0x0d010800/0x0d010840 X[ETU]=0x0d010900
[   71.112205058,6] PHB: Chip 8 Found PHB4 PBCQ1 Stack 0 at /xscom@623fc00000000/pbcq@4011000/stack@0
[   71.116301498,7] PHB[8:1] X[PE]=0x04011000/0x04011040 X[PCI]=0x0e010800/0x0e010840 X[ETU]=0x0e010900
[   71.121797681,6] PHB: Chip 8 Found PHB4 PBCQ1 Stack 1 at /xscom@623fc00000000/pbcq@4011000/stack@1
[   71.125890813,7] PHB[8:2] X[PE]=0x04011000/0x04011080 X[PCI]=0x0e010800/0x0e010880 X[ETU]=0x0e010940
[   71.131388535,6] PHB: Chip 8 Found PHB4 PBCQ2 Stack 0 at /xscom@623fc00000000/pbcq@4011400/stack@0
[   71.135485160,7] PHB[8:3] X[PE]=0x04011400/0x04011440 X[PCI]=0x0f010800/0x0f010840 X[ETU]=0x0f010900
[   71.141024044,7] PHB#0000:00:00.0 PCI: Registered PHB
[   71.142989929,6] PHB#0000[0:0]: Found /pciex@600c3c0000000 @0x600c3c0000000
[   71.146538679,6] PHB#0000[0:0]:   M32 [0x000600c000000000..0x000600c07fffffff]
[   71.150090117,6] PHB#0000[0:0]:   M64 [0x0006000000000000..0x0006003fffffffff]
[   71.154345736,7] PHB#0000[0:0]: Base location code not found !
[   71.157188099,7] PHB#0000[0:0]: Core revision 0xa40002
[   71.159320976,7] PHB#0000[0:0]: Found 512 max PEs and 4096 IRQs 
[   71.162866717,6] PHB#0000[0:0]: Max link speed: GEN3
[   71.165000455,7] PHB#0000[0:0]: Override lane equalization settings:
[   71.168546373,7] PHB#0000[0:0]:   0x5454545454545454 0x5454545454545454
[   71.172095303,7] PHB#0000[0:0]:   0x5454545454545454 0x5454545454545454
[   71.174940748,7] PHB#0000[0:0]:   0x7777777777777777 0x7777777777777777
[   71.178619664,7] PHB#0000[0:0]: Initializing PHB4...
[   71.181326050,7] PHB#0000[0:0]: Default system config: 0x4410000040400000
[   71.184874899,7] PHB#0000[0:0]: New system config    : 0x4410000030400000
[   71.187720648,7] PHB#0000[0:0]: Initial PHB CRESET is 0xe000000000000000
[   71.191270834,7] PHB#0000[0:0]: Waiting for DLP PG reset to complete...
[   71.194817863,7] PHB#0000[0:0]: Reset state SRC_ID: 0ff8000000000000
[   71.198691675,7] PHB#0000[0:0]: Initialization complete
[   71.200660905,6] BT: seq 0x08 netfn 0x0a cmd 0x42: IPMI MSG done
[   71.204210336,6] BT: seq 0x09 netfn 0x3a cmd 0xf0: Message sent to host
[   71.243410813,6] IPMI: sending chassis control request 0x03
[   71.309793356,6] BT: seq 0x09 netfn 0x3a cmd 0xf0: IPMI MSG done
[   71.312613789,6] BT: seq 0x0b netfn 0x3a cmd 0xf0: Message sent to host
[   71.418187877,6] BT: seq 0x0b netfn 0x3a cmd 0xf0: IPMI MSG done
[   71.420965776,6] BT: seq 0x0c netfn 0x3a cmd 0xf0: Message sent to host
[   72.015248657,6] BT: seq 0x0c netfn 0x3a cmd 0xf0: IPMI MSG done
[   72.017981573,6] BT: seq 0x0d netfn 0x3a cmd 0xf0: Message sent to host
[   72.124259483,6] BT: seq 0x0d netfn 0x3a cmd 0xf0: IPMI MSG done
[   72.126949917,6] BT: seq 0x0e netfn 0x3a cmd 0xf0: Message sent to host
[   72.233227650,6] BT: seq 0x0e netfn 0x3a cmd 0xf0: IPMI MSG done
[   72.235874037,6] BT: seq 0x0f netfn 0x3a cmd 0xf0: Message sent to host
[   72.342149867,6] BT: seq 0x0f netfn 0x3a cmd 0xf0: IPMI MSG done
[   72.344752196,6] BT: seq 0x10 netfn 0x3a cmd 0xf0: Message sent to host
[   72.451030532,6] BT: seq 0x10 netfn 0x3a cmd 0xf0: IPMI MSG done
[   72.453587030,6] BT: seq 0x11 netfn 0x3a cmd 0xf0: Message sent to host
[   73.047864242,6] BT: seq 0x11 netfn 0x3a cmd 0xf0: IPMI MSG done
[   73.050377755,6] BT: seq 0x12 netfn 0x3a cmd 0xf0: Message sent to host
[   73.156654250,6] BT: seq 0x12 netfn 0x3a cmd 0xf0: IPMI MSG done
[   73.159124165,6] BT: seq 0x13 netfn 0x3a cmd 0xf0: Message sent to host
[   73.265400379,6] BT: seq 0x13 netfn 0x3a cmd 0xf0: IPMI MSG done
[   73.267825788,6] BT: seq 0x14 netfn 0x3a cmd 0xf0: Message sent to host
[   73.374102117,6] BT: seq 0x14 netfn 0x3a cmd 0xf0: IPMI MSG done
[   73.376482637,6] BT: seq 0x15 netfn 0x3a cmd 0xf0: Message sent to host
[   73.482760323,6] BT: seq 0x15 netfn 0x3a cmd 0xf0: IPMI MSG done
[   73.485099725,6] BT: seq 0x16 netfn 0x3a cmd 0xf0: Message sent to host
[   74.079376786,6] BT: seq 0x16 netfn 0x3a cmd 0xf0: IPMI MSG done
[   74.081673281,6] BT: seq 0x17 netfn 0x3a cmd 0xf0: Message sent to host
[   74.187949448,6] BT: seq 0x17 netfn 0x3a cmd 0xf0: IPMI MSG done
[   74.190905659,6] BT: seq 0x18 netfn 0x3a cmd 0xf0: Message sent to host
[   74.296478585,6] BT: seq 0x18 netfn 0x3a cmd 0xf0: IPMI MSG done
[   74.299390386,6] BT: seq 0x19 netfn 0x3a cmd 0xf0: Message sent to host
[   74.404962901,6] BT: seq 0x19 netfn 0x3a cmd 0xf0: IPMI MSG done
[   74.407830502,6] BT: seq 0x1a netfn 0x3a cmd 0xf0: Message sent to host
[   75.001403963,6] BT: seq 0x1a netfn 0x3a cmd 0xf0: IPMI MSG done
[   75.004224409,6] BT: seq 0x1b netfn 0x3a cmd 0xf0: Message sent to host
[   75.109799146,6] BT: seq 0x1b netfn 0x3a cmd 0xf0: IPMI MSG done
[   75.112575361,6] BT: seq 0x1c netfn 0x3a cmd 0xf0: Message sent to host
[   75.218853641,6] BT: seq 0x1c netfn 0x3a cmd 0xf0: IPMI MSG done
[   75.221583085,6] BT: seq 0x1d netfn 0x3a cmd 0xf0: Message sent to host
[   75.327871991,6] BT: seq 0x1d netfn 0x3a cmd 0xf0: IPMI MSG done
[   75.330549114,6] BT: seq 0x1e netfn 0x0a cmd 0x44: Message sent to host
[   75.436837860,6] BT: seq 0x1e netfn 0x0a cmd 0x44: IPMI MSG done
[   75.439466772,6] IPMI: SEL: New event logged [ID : 02d]
[   75.442307465,6] BT: seq 0x0a netfn 0x00 cmd 0x02: Message sent to host
[   76.035894135,6] BT: seq 0x0a netfn 0x00 cmd 0x02: IPMI MSG done


--== Welcome to Hostboot  ==--

  2.73076|secure|SecureROM valid - enabling functionality
 13.83996|secure|Booting in non-secure mode.
 14.56856|Ignoring boot flags, incorrect version 0x0
 14.57840|Booting from SBE side 0 on master proc=00050000
 14.73354|ISTEP  6. 5 - host_init_fsi
 14.81271|ISTEP  6. 6 - host_set_ipl_parms

If there are multiple flash resources pre-load requests came, before one CPU job gets abort the other CPU can download the PNOR resource. @cclaudio @stewart-ibm Please have a look at it.

@pridhiviraj
Copy link
Contributor Author

Primary main thread took additional 6 seconds to abort the boot process, after secondary job gets abort.

@ghost
Copy link

ghost commented Feb 8, 2018

Ouch. We should probably think about a better way to deal with that.

@debmc
Copy link
Collaborator

debmc commented Feb 7, 2019

Adding cross reference -> https://bugzilla.linux.ibm.com/show_bug.cgi?id=165960

ruscur pushed a commit to ruscur/skiboot that referenced this issue Feb 28, 2020
Here is a proposal to collect OPAL call statistics, counts and duration,
and track areas we could possibly improve.

With a small Linux driver to dump the stats in debugfs, here is what
we get on a P9 after boot:

OPAL_CONSOLE_WRITE : #22318 0/0/47
OPAL_RTC_READ : open-power#9 0/4/15
OPAL_READ_NVRAM : #3468 0/0/6
OPAL_HANDLE_INTERRUPT : #4724 0/57/10026
OPAL_POLL_EVENTS : #508 2/141/10033
OPAL_PCI_CONFIG_READ_BYTE : #3623 0/0/4
OPAL_PCI_CONFIG_READ_HALF_WORD : #5579 0/0/8
OPAL_PCI_CONFIG_READ_WORD : #6156 0/0/7
OPAL_PCI_CONFIG_WRITE_BYTE : open-power#2 0/0/0
OPAL_PCI_CONFIG_WRITE_HALF_WORD : #1282 0/0/1
OPAL_PCI_CONFIG_WRITE_WORD : #1335 0/0/1
OPAL_PCI_EEH_FREEZE_STATUS : #11123 0/0/2
OPAL_CONSOLE_WRITE_BUFFER_SPACE : #139088 0/0/11
OPAL_PCI_EEH_FREEZE_CLEAR : open-power#148 1/2/8
OPAL_PCI_PHB_MMIO_ENABLE : open-power#22 0/0/0
OPAL_PCI_SET_PHB_MEM_WINDOW : open-power#22 0/0/1
OPAL_PCI_MAP_PE_MMIO_WINDOW : open-power#56 0/0/0
OPAL_PCI_SET_PE : open-power#44 279/284/293
OPAL_PCI_SET_PELTV : open-power#66 0/0/0
OPAL_PCI_SET_XIVE_PE : #1123 0/0/1
OPAL_GET_MSI_64 : #1120 0/0/0
OPAL_START_CPU : open-power#238 8/21/35
OPAL_QUERY_CPU_STATUS : #357 0/11/69
OPAL_PCI_MAP_PE_DMA_WINDOW : open-power#16 0/0/1
OPAL_PCI_MAP_PE_DMA_WINDOW_REAL : open-power#16 0/0/1
OPAL_PCI_RESET : open-power#35 0/471/851
OPAL62 : open-power#6 0/10/46
OPAL_XSCOM_READ : open-power#26 0/0/2
OPAL_XSCOM_WRITE : open-power#8 0/0/1
OPAL_REINIT_CPUS : open-power#4 348/8247/11061
OPAL_CHECK_TOKEN : #134112 0/0/0
OPAL_GET_MSG : open-power#30 0/0/1
OPAL87 : open-power#1 0/0/0
OPAL_PCI_SET_PHB_CAPI_MODE : open-power#2 0/60/121
OPAL_SLW_SET_REG : #1080 3/3/13
OPAL_IPMI_SEND : open-power#53 0/5/11
OPAL_IPMI_RECV : open-power#53 0/0/2
OPAL_I2C_REQUEST : open-power#20 6/10/19
OPAL_FLASH_READ : open-power#10 19/10452/58305
OPAL_PRD_MSG : open-power#1 0/3/3
OPAL_CONSOLE_FLUSH : #134079 0/0/12
OPAL_PCI_GET_PRESENCE_STATE : open-power#7 1/1/3
OPAL_PCI_GET_POWER_STATE : open-power#9 0/0/0
OPAL_PCI_TCE_KILL : open-power#20 1/8/133
OPAL_NMMU_SET_PTCR : open-power#3 253/255/257
OPAL_XIVE_RESET : open-power#3 0/114709/115403
OPAL_XIVE_GET_IRQ_INFO : #1427 0/0/6
OPAL_XIVE_SET_IRQ_CONFIG : #1113 0/125/2810
OPAL_XIVE_GET_QUEUE_INFO : open-power#240 0/0/2
OPAL_XIVE_SET_QUEUE_INFO : #360 0/60/1216
OPAL_XIVE_ALLOCATE_VP_BLOCK : open-power#2 0/59/60
OPAL_XIVE_GET_VP_INFO : open-power#240 0/0/0
OPAL_XIVE_SET_VP_INFO : #360 0/298/3080
OPAL_XIVE_ALLOCATE_IRQ : open-power#240 0/0/3
OPAL140 : open-power#119 0/253/1109
OPAL_IMC_COUNTERS_INIT : open-power#60 9/10/20
OPAL_IMC_COUNTERS_STOP : open-power#36 0/0/2
OPAL_PCI_GET_PBCQ_TUNNEL_BAR : open-power#1 2/2/2
OPAL_PCI_SET_PBCQ_TUNNEL_BAR : open-power#1 1/1/1
OPAL_NX_COPROC_INIT : open-power#2 3/4/5

Signed-off-by: Cédric Le Goater <clg@kaod.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants