Sometimes the console output logs with levels 6 and 7

[wongkq]

Sometimes the console output logs with levels 6 and 7。 Here is the console log: [ 270.086308100,7] IRQ: Registering 20fc800..20fcff7 ops @0x30153020 (data 0x0) [ 270.086310391,7] IRQ: Registering 20fcff8..20fcfff ops @0x30153020 (data 0x800003184010) [ 270.086314625,7] PHB#006c:00:00.0 PCI: Registered PHB [ 270.086316822,6] PHB#006c[6:0]: Found /pciex@6c0c3c0000000 @0x6c0c3c0000000 [ 270.086317909,6] PHB#006c[6:0]: M32 [0x0006c0c000000000..0x0006c0c07fffffff] [ 270.086319045,6] PHB#006c[6:0]: M64 [0x0006c00000000000..0x0006c03fffffffff] [ 270.086321409,7] PHB#006c[6:0]: Core revision 0xa50002 [ 270.086322374,7] PHB#006c[6:0]: Found 512 max PEs and 4096 IRQs [ 270.086323808,6] PHB#006c[6:0]: Max link speed: GEN5, max link width 8 [ 270.086324742,7] PHB#006c[6:0]: Override lane equalization settings: [ 270.086325650,7] PHB#006c[6:0]: 0x4444444444444444 0x4444444444444444 [ 270.086326659,7] PHB#006c[6:0]: 0x4444444444444444 0x4444444444444444 [ 270.086327798,7] PHB#006c[6:0]: 0x4444444444444444 0x4444444444444444 [ 270.086328931,7] PHB#006c[6:0]: 0x9999999999999999 0x9999999999999999 [ 270.086462343,7] PHB#006c[6:0]: Initializing PHB... [ 270.086463448,7] PHB#006c[6:0]: Default system config: 0x4410000050400000 [ 270.086464549,7] PHB#006c[6:0]: New system config : 0x4410000050400000 [ 270.086465697,7] PHB#006c[6:0]: Initial PHB CRESET is 0xe000000000000000 [ 270.086467107,7] PHB#006c[6:0]: LINK: Disabling scaled flow control [ 270.086468145,7] PHB#006c[6:0]: Waiting for DLP PG reset to complete... [ 270.086983447,7] PHB#006c[6:0]: store EOI is enabled [ 270.086984308,7] PHB#006c[6:0]: Using ABT mode. ESB: 0x0006c51fc0000000 [ 270.086985521,7] PHB#006c[6:0]: Reset state SRC_ID: 0ff8000000000000 [ 270.087171553,7] PHB#006c[6:0]: Initialization complete [ 270.087172499,7] IRQ: Registering 30fe000..30feff7 ops @0x30153020 (data 0x0) [ 270.087173777,7] IRQ: Registering 30feff8..30fefff ops @0x30153020 (data 0x454c2010) [ 270.087177856,7] PHB#006d:00:00.0 PCI: Registered PHB [ 270.087180021,6] PHB#006d[6:1]: Found /pciex@6c0c3c0100000 @0x6c0c3c0100000 [ 270.087181173,6] PHB#006d[6:1]: M32 [0x0006c0c080000000..0x0006c0c0ffffffff] [ 270.087182384,6] PHB#006d[6:1]: M64 [0x0006c04000000000..0x0006c07fffffffff] [ 270.087184692,7] PHB#006d[6:1]: Core revision 0xa50002 [ 270.087185634,7] PHB#006d[6:1]: Found 256 max PEs and 2048 IRQs [ 270.087186870,6] PHB#006d[6:1]: Max link speed: GEN4, max link width 4 [ 270.087187766,7] PHB#006d[6:1]: Override lane equalization settings: [ 270.087188608,7] PHB#006d[6:1]: 0x4444444444444444 0x4444444444444444 [ 270.087189667,7] PHB#006d[6:1]: 0x4444444444444444 0x4444444444444444 [ 270.087190754,7] PHB#006d[6:1]: 0x4444444444444444 0x4444444444444444 [ 270.087191749,7] PHB#006d[6:1]: 0x9999999999999999 0x9999999999999999 [ 270.087312789,7] PHB#006d[6:1]: Initializing PHB... [ 270.087313874,7] PHB#006d[6:1]: Default system config: 0x4210000050200000 [ 270.087314950,7] PHB#006d[6:1]: New system config : 0x4210000040200000 [ 270.087316081,7] PHB#006d[6:1]: Initial PHB CRESET is 0xe000000000000000 [ 270.087317333,7] PHB#006d[6:1]: LINK: Disabling scaled flow control [ 270.087318434,7] PHB#006d[6:1]: Waiting for DLP PG reset to complete... [ 270.087833635,7] PHB#006d[6:1]: store EOI is enabled [ 270.087834502,7] PHB#006d[6:1]: Using ABT mode. ESB: 0x0006c51fb0000000 [ 270.087835713,7] PHB#006d[6:1]: Reset state SRC_ID: 0ff8000000000000 [ 270.087932992,7] PHB#006d[6:1]: Initialization complete [ 270.087933907,7] IRQ: Registering 30fd800..30fdff7 ops @0x30153020 (data 0x0) [ 270.087935155,7] IRQ: Registering 30fdff8..30fdfff ops @0x30153020 (data 0x45544010) [ 270.087939187,7] PHB#006e:00:00.0 PCI: Registered PHB [ 270.087941715,6] PHB#006e[6:2]: Found /pciex@6c0c3c0200000 @0x6c0c3c0200000 [ 270.087942899,6] PHB#006e[6:2]: M32 [0x0006c0c100000000..0x0006c0c17fffffff] [ 270.087944116,6] PHB#006e[6:2]: M64 [0x0006c08000000000..0x0006c0bfffffffff] [ 270.087946375,7] PHB#006e[6:2]: Core revision 0xa50002 [ 270.087947426,7] PHB#006e[6:2]: Found 256 max PEs and 2048 IRQs [ 270.087948645,6] PHB#006e[6:2]: Max link speed: GEN4, max link width 4 [ 270.087949648,7] PHB#006e[6:2]: Override lane equalization settings: [ 270.087950406,7] PHB#006e[6:2]: 0x4444444444444444 0x4444444444444444 [ 270.087951522,7] PHB#006e[6:2]: 0x4444444444444444 0x4444444444444444 [ 270.087952599,7] PHB#006e[6:2]: 0x4444444444444444 0x4444444444444444 [ 270.087953649,7] PHB#006e[6:2]: 0x9999999999999999 0x9999999999999999 [ 270.088075794,7] PHB#006e[6:2]: Initializing PHB... [ 270.088076727,7] PHB#006e[6:2]: Default system config: 0x4210000050200000 [ 270.088077989,7] PHB#006e[6:2]: New system config : 0x4210000040200000 [ 270.088079030,7] PHB#006e[6:2]: Initial PHB CRESET is 0xe000000000000000 [ 270.088080358,7] PHB#006e[6:2]: LINK: Disabling scaled flow control [ 270.088081540,7] PHB#006e[6:2]: Waiting for DLP PG reset to complete... [ 270.088596722,7] PHB#006e[6:2]: store EOI is enabled [ 270.088597600,7] PHB#006e[6:2]: Using ABT mode. ESB: 0x0006c51fa0000000 [ 270.088598706,7] PHB#006e[6:2]: Reset state SRC_ID: 0ff8000000000000 [ 270.088696007,7] PHB#006e[6:2]: Initialization complete [ 270.088696838,7] IRQ: Registering 30fd000..30fd7f7 ops @0x30153020 (data 0x0) [ 270.088698178,7] IRQ: Registering 30fd7f8..30fd7ff ops @0x30153020 (data 0x455c2010) [ 270.088702182,7] PHB#006f:00:00.0 PCI: Registered PHB [ 270.088704546,6] PHB#006f[6:3]: Found /pciex@6c0c3c0300000 @0x6c0c3c0300000 [ 270.088706480,6] PHB#006f[6:3]: M32 [0x0006c0c180000000..0x0006c0c1ffffffff] [ 270.088707573,6] PHB#006f[6:3]: M64 [0x0006c20000000000..0x0006c23fffffffff] [ 270.088709957,7] PHB#006f[6:3]: Core revision 0xa50002 [ 270.088710915,7] PHB#006f[6:3]: Found 512 max PEs and 4096 IRQs [ 270.088712228,6] PHB#006f[6:3]: Max link speed: GEN5, max link width 16 [ 270.088713233,7] PHB#006f[6:3]: Override lane equalization settings: [ 270.088713984,7] PHB#006f[6:3]: 0x4444444444444444 0x4444444444444444 [ 270.088715124,7] PHB#006f[6:3]: 0x4444444444444444 0x4444444444444444 [ 270.088716145,7] PHB#006f[6:3]: 0x4444444444444444 0x4444444444444444 [ 270.088717313,7] PHB#006f[6:3]: 0x9999999999999999 0x9999999999999999 [ 270.088850311,7] PHB#006f[6:3]: Initializing PHB... [ 270.088851251,7] PHB#006f[6:3]: Default system config: 0x4410000050400000 [ 270.088852485,7] PHB#006f[6:3]: New system config : 0x4410000050400000 [ 270.088853540,7] PHB#006f[6:3]: Initial PHB CRESET is 0xe000000000000000 [ 270.088854934,7] PHB#006f[6:3]: LINK: Disabling scaled flow control [ 270.088855958,7] PHB#006f[6:3]: Waiting for DLP PG reset to complete... [ 270.089371281,7] PHB#006f[6:3]: store EOI is enabled [ 270.089372147,7] PHB#006f[6:3]: Using ABT mode. ESB: 0x0006c51f80000000 [ 270.089373362,7] PHB#006f[6:3]: Reset state SRC_ID: 0ff8000000000000 [ 270.089559605,7] PHB#006f[6:3]: Initialization complete [ 270.089560451,7] IRQ: Registering 30fc000..30fcff7 ops @0x30153020 (data 0x0) [ 270.089561782,7] IRQ: Registering 30fcff8..30fcfff ops @0x30153020 (data 0x45642010) [ 270.089585043,7] HWPROBE: Probing npu2... [ 270.089658145,7] HWPROBE: Probing vas...

[rarbab]

Log level 6 is PR_INFO and log level 7 is PR_DEBUG. Could you elaborate a bit what you feel the issue is?

[oohal]

It's a bug with how flushing from the in-memory console to the physical console works. I came up with a fix for this years ago which is basically making skiboot parse its own log headers to figure out on a line-by-line basis whether it should print the output. Turns out past me wrote a decent commit message: https://github.com/open-power/skiboot/commit/66c600ced3a5983590bc282131ba0591714a725a

The full branch is here: https://github.com/oohal/skiboot/tree/console-again hwoever, it's hella old and might be a convoluted rebase. The top few patches which add a OPAL call to let linux scrape the skiboot log as something I was screwing around with at the time and never really made production ready so you should probably drop those.

The main issue with the fix above is that it makes the already complicated logging slightly more complicated. I (and stewart, probably) could never really convince myself adding a bunch of text parsing was a good idea so I just lived with getting bonus debug messages on the console occasionally.

On Thu, Aug 17, 2023 at 4:27 AM Reza Arbab @.***> wrote:

Log level 6 is PR_INFO and log level 7 is PR_DEBUG. Could you elaborate a bit what you feel the issue is?

— Reply to this email directly, view it on GitHub https://github.com/open-power/skiboot/issues/278#issuecomment-1681086720, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAGP6QF5PXGBMVVA5TRYKLXVUGJDANCNFSM6AAAAAA256S2AM . You are receiving this because you are subscribed to this thread.Message ID: @.***>

[rarbab]

Ah, now I get it. Thanks for the background @oohal!

I'm inclined to agree with you and Stewart and just live with the occasional tic of verbosity. FWIW, I don't think I've ever personally seen this happen, so it can't be that frequent.