WARN_ONCE does not warn once

Hello,

on powernv with 5.3.8 kernel I get flood of messages on boot.

The messages match WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");

------------[ cut here ]------------
opal: OPAL_CONSOLE_FLUSH missing.
WARNING: CPU: 0 PID: 0 at ../arch/powerpc/platforms/powernv/opal.c:435 __opal_flush_console+0xfc/0x110
Modules linked in:
Supported: No, Unreleased kernel
CPU: 0 PID: 0 Comm: swapper Not tainted 5.3.8-11.gea9b07d-default #1 SLE15-SP2 (unreleased)
NIP:  c0000000000b9b9c LR: c0000000000b9b98 CTR: c000000000c06ca0
REGS: c00000000158b8c0 TRAP: 0700   Not tainted  (5.3.8-11.gea9b07d-default)
MSR:  9000000000021033 <SF,HV,ME,IR,DR,RI,LE>  CR: 28004222  XER: 20000000
CFAR: c000000000132df0 IRQMASK: 1 
GPR00: c0000000000b9b98 c00000000158bb50 c00000000158c600 0000000000000022 
GPR04: c000000000e63b7a 0000000000000002 4f534e4f435f4c41 4853554c465f454c 
GPR08: 676e697373696d20 0000000000000000 0000000000000027 9000000000001033 
GPR12: c0000000001cc080 c000000002150000 0000000000000000 0000000000000000 
GPR16: 00003ffff13114c0 0000000000000000 c0000000014641e0 0000000000000000 
GPR20: 0000000000000000 c000000001765738 c000000001763738 0000000000000001 
GPR24: c0000000015c1ed8 c000000001763318 c000000001762dec 0000000000000001 
GPR28: 0000000000000000 c000000002130d18 0000000000000000 0000000000000000 
NIP [c0000000000b9b9c] __opal_flush_console+0xfc/0x110
LR [c0000000000b9b98] __opal_flush_console+0xf8/0x110
Call Trace:
[c00000000158bb50] [c0000000000b9b98] __opal_flush_console+0xf8/0x110 (unreliable)
[c00000000158bbd0] [c0000000000b9dbc] opal_flush_console+0x2c/0x60
[c00000000158bc00] [c00000000080c180] udbg_opal_putc+0x80/0xd0
[c00000000158bc50] [c000000000033660] udbg_write+0x90/0x140
[c00000000158bc90] [c0000000001c888c] console_unlock+0x32c/0x820
[c00000000158bd70] [c0000000001c9768] register_console+0x5d8/0x790
[c00000000158be10] [c000000000fb9dcc] register_early_udbg_console+0x9c/0xb4
[c00000000158be80] [c000000000fb99c8] setup_arch+0x78/0x39c
[c00000000158bef0] [c000000000fb3c00] start_kernel+0xb4/0x6bc
[c00000000158bf90] [c00000000000c4d4] start_here_common+0x1c/0x20
Instruction dump:
60000000 3860fffe 4bffffa8 60000000 60000000 3c62ff8d 39200001 3d42fff6 
38637558 992afea8 480791f5 60000000 <0fe00000> 4bffff54 48079715 60000000 
random: get_random_bytes called from print_oops_end_marker+0x6c/0xa0 with crng_init=0
---[ end trace 0000000000000000 ]---

This is reapated numerous times and the kernel eventually boots.

Is that an issue with the WARN_ONCE implementation?

Thanks

Michal

On Thu, Nov 14, 2019 at 05:46:55PM +0100, Michal Suchánek wrote:

Hello,

on powernv with 5.3.8 kernel I get flood of messages on boot.

The messages match WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");

Asking around it was pointed out that WARN_ONCE warns up to as many
times as you have CPUs.

Did not bother counting the messages but it may very well be the case it
is printed once for each CPU.

Thanks

Michal

Michal Suchánek [off-list ref] writes:

On Thu, Nov 14, 2019 at 05:46:55PM +0100, Michal Suchánek wrote:

quoted

Hello,

on powernv with 5.3.8 kernel I get flood of messages on boot.

The messages match WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");

Asking around it was pointed out that WARN_ONCE warns up to as many
times as you have CPUs.

Does it?

Did not bother counting the messages but it may very well be the case it
is printed once for each CPU.

The way it's implemented is slightly racy, but I'd be surprised if every
CPU hit that race all at once.

Can you give us the full dmesg?

cheers

On Fri, Nov 15, 2019 at 03:43:24PM +1100, Michael Ellerman wrote:

Michal Suchánek [off-list ref] writes:

quoted

On Thu, Nov 14, 2019 at 05:46:55PM +0100, Michal Suchánek wrote:

quoted

Hello,

on powernv with 5.3.8 kernel I get flood of messages on boot.

The messages match WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");

Asking around it was pointed out that WARN_ONCE warns up to as many
times as you have CPUs.

Does it?

quoted

Did not bother counting the messages but it may very well be the case it
is printed once for each CPU.

The way it's implemented is slightly racy, but I'd be surprised if every
CPU hit that race all at once.

Printing a warn_once this early probably forces some peculiar timing.
grep  WARN.*__opal_flush_console dmesg.txt | wc -l gives exactly the
number of CPUs as shown by lscpu.

Can you give us the full dmesg?

Attaching.

Thanks

Michal

On Fri, Nov 15, 2019 at 09:44:34AM +0100, Michal Suchánek wrote:

On Fri, Nov 15, 2019 at 03:43:24PM +1100, Michael Ellerman wrote:

quoted

Michal Suchánek [off-list ref] writes:

quoted

On Thu, Nov 14, 2019 at 05:46:55PM +0100, Michal Suchánek wrote:

quoted

Hello,

on powernv with 5.3.8 kernel I get flood of messages on boot.

The messages match WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");

Asking around it was pointed out that WARN_ONCE warns up to as many
times as you have CPUs.

Does it?

quoted

Did not bother counting the messages but it may very well be the case it
is printed once for each CPU.

The way it's implemented is slightly racy, but I'd be surprised if every
CPU hit that race all at once.

Printing a warn_once this early probably forces some peculiar timing.
grep  WARN.*__opal_flush_console dmesg.txt | wc -l gives exactly the
number of CPUs as shown by lscpu.

And this dose not change with enforcing once using an atomic.

diff --git a/arch/powerpc/platforms/powernv/opal.c b/arch/powerpc/platforms/powernv/opal.c
index d271accf224b..dd870124b804 100644
--- a/arch/powerpc/platforms/powernv/opal.c
+++ b/arch/powerpc/platforms/powernv/opal.c

@@ -425,6 +425,7 @@ static s64 __opal_flush_console(uint32_t vtermno)
 	s64 rc;
 
 	if (!opal_check_token(OPAL_CONSOLE_FLUSH)) {
+		static atomic_t warned;
 		__be64 evt;
 
 		/*

@@ -432,7 +433,8 @@ static s64 __opal_flush_console(uint32_t vtermno)
 		 * the console can still be flushed by calling the polling
 		 * function while it has OPAL_EVENT_CONSOLE_OUTPUT events.
 		 */
-		WARN_ONCE(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");
+		if (!atomic_xchg(&warned, 1))
+			WARN(1, "opal: OPAL_CONSOLE_FLUSH missing.\n");
 
 		opal_poll_events(&evt);
 		if (!(be64_to_cpu(evt) & OPAL_EVENT_CONSOLE_OUTPUT))

Something more tricky is going on.

Thanks

Michal