Re: WARN_ONCE does not warn once

["Michal Suchánek" <msuchanek@suse.de>]

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:
> > Michal Suchánek <msuchanek@suse.de> writes:
> > > 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.
> > 
> > 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.
> 
> 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