[PATCH]: Use cmpxchg() in WARN_*_ONCE() functions

[PATCH]: Use cmpxchg() in WARN_*_ONCE() functions

[Prarit Bhargava]

An issue popped up where WARN_ON_ONCE() was used in a callback function
in smp_call_function().  This resulted in the WARN_ON executing multiple times
when it should have only executed once.

We cannot use a lock in the WARN_*_ONCE functions because it is far too heavy
for the code in question.  Don Zickus suggested using cmpxchg(), which resolves
the problem of the multiple outputs.

The question surrounding cmpxchg(), of course, is one of performance.  It
appears that, at least on x86, it isn't a concern.

I ran the following test in a simple module:

void prarit_callback(void *info)
{
        WARN_ON_ONCE(1);
}

        for (j = 0; j < 10; j++)
                for (i = 0; i < 1000000; i++)
                        prarit_callback(NULL);

With the current code in place an average of 10 runs was .219s.  Doing just
a (!cmpxchg(&__warned, 0, 1)) the time jumps to .402s.  Adding in a check
for the __warned flag, (!__warned && !cmpxchg(&__warned, 0, 1)), results in
an average of .220s.

I then did

        for (i = 0; i < 1000000; i++)
                on_each_cpu(prarit_callback, NULL, 0);

The current code, of course, explodes :).  That's the bug I'm trying to fix.
What is interesting in this test, however, is the impact that checking the
!__warned flag has [Aside: Checking the !__warned flag is an enhancement
and is not explicitly required for this code].

A run with just (!cmpxchg(&__warned, 0, 1)) results in an average of 21.323s,
and a run with  (!__warned && !cmpxchg(&__warned, 0, 1)) results in an
average of 20.233s.  Of course, the !__warned is not necessary for the code
to work properly but it seems to be a significant impact to the time to run
this code.

P.

WARN_ON_ONCE() is used in callback functions in smp_call_function().  This
results in races through the WARN_ON() code.

Use cmxchg() in the WARN_*_ON functions in order to guarantee single
execution of the WARN_ONs.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>

diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
index f2d2faf..cbefd54 100644
--- a/include/asm-generic/bug.h
+++ b/include/asm-generic/bug.h
@@ -133,30 +133,32 @@ extern void warn_slowpath_null(const char *file, const int line);
 #endif
 
 #define WARN_ON_ONCE(condition)	({				\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
-		if (WARN_ON(!__warned)) 			\
-			__warned = true;			\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN_ON(1);				\
 	unlikely(__ret_warn_once);				\
 })
 
 #define WARN_ONCE(condition, format...)	({			\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
-		if (WARN(!__warned, format)) 			\
-			__warned = true;			\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN(1, format);			\
 	unlikely(__ret_warn_once);				\
 })
 
 #define WARN_TAINT_ONCE(condition, taint, format...)	({	\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN_TAINT(1, taint, format);		\
 		if (WARN_TAINT(!__warned, taint, format))	\
 			__warned = true;			\
 	unlikely(__ret_warn_once);				\

Re: [PATCH]: Use cmpxchg() in WARN_*_ONCE() functions

[Steven Rostedt]

On Thu, Mar 31, 2011 at 08:46:07AM -0400, Prarit Bhargava wrote:
> An issue popped up where WARN_ON_ONCE() was used in a callback function
> in smp_call_function().  This resulted in the WARN_ON executing multiple times
> when it should have only executed once.

But that is just once per cpu, correct?

> 
> I then did
> 
>         for (i = 0; i < 1000000; i++)
>                 on_each_cpu(prarit_callback, NULL, 0);
> 
> The current code, of course, explodes :).  That's the bug I'm trying to fix.

How exactly does it explode? How many CPUs do you have, and does this
still just print once per CPU?

> What is interesting in this test, however, is the impact that checking the
> !__warned flag has [Aside: Checking the !__warned flag is an enhancement
> and is not explicitly required for this code].
> 
> A run with just (!cmpxchg(&__warned, 0, 1)) results in an average of 21.323s,
> and a run with  (!__warned && !cmpxchg(&__warned, 0, 1)) results in an
> average of 20.233s.  Of course, the !__warned is not necessary for the code
> to work properly but it seems to be a significant impact to the time to run
> this code.

Yes adding the check for !__warned first should have obvious benefits.

I really do not see anything wrong with this patch, but personally, I
would rather fix what caused the WARN_ON_ONCE() than fix the warning
itself, as long as the warning itself does not really break anything
else.

-- Steve

Re: [PATCH]: Use cmpxchg() in WARN_*_ONCE() functions

[Prarit Bhargava]

Hey Steve,

On 03/31/2011 11:23 AM, Steven Rostedt wrote:
> On Thu, Mar 31, 2011 at 08:46:07AM -0400, Prarit Bhargava wrote:
>   
>> An issue popped up where WARN_ON_ONCE() was used in a callback function
>> in smp_call_function().  This resulted in the WARN_ON executing multiple times
>> when it should have only executed once.
>>     
> But that is just once per cpu, correct?
>   

Not always.  Sometimes I see a subset of CPUs ... maybe a cacheflush or
something hits that finally causes the remaining cpus to see __warned? 
I dunno...

But I have had 24/24 cpus output the message.

>   
>> I then did
>>
>>         for (i = 0; i < 1000000; i++)
>>                 on_each_cpu(prarit_callback, NULL, 0);
>>
>> The current code, of course, explodes :).  That's the bug I'm trying to fix.
>>     
> How exactly does it explode? How many CPUs do you have, and does this
> still just print once per CPU?
>
>   

It explodes because each cpu spits out a warning (which is the issue I'm
trying to resolve).

24 physical cores is what I tested on, but this has been seen in the
field on a system with 6 on RHEL6 (2.6.32/33/34/35/36/37/38-ish).

>> What is interesting in this test, however, is the impact that checking the
>> !__warned flag has [Aside: Checking the !__warned flag is an enhancement
>> and is not explicitly required for this code].
>>
>> A run with just (!cmpxchg(&__warned, 0, 1)) results in an average of 21.323s,
>> and a run with  (!__warned && !cmpxchg(&__warned, 0, 1)) results in an
>> average of 20.233s.  Of course, the !__warned is not necessary for the code
>> to work properly but it seems to be a significant impact to the time to run
>> this code.
>>     
> Yes adding the check for !__warned first should have obvious benefits.
>
> I really do not see anything wrong with this patch, but personally, I
> would rather fix what caused the WARN_ON_ONCE() than fix the warning
> itself, as long as the warning itself does not really break anything
> else.
>   


The WARN_ON_ONCE was triggering due to bad HW setup.  The system in
question had the APERFMPERF flag only set on the boot cpu and no other
cpus.  This caused the system to generate warnings in the acpi cpufreq code.

The HW issue was resolved by modifying a BIOS setting which was found to
clear the APERFMPERF cpu flag setting on the !boot cpus.  Yes, this
means the HW is busted.

But ... that still leaves the possibility that WARN_ON_ONCE spits out
many warnings instead of just one.  Hence, the patch.

P.

Re: [PATCH]: Use cmpxchg() in WARN_*_ONCE() functions

[Prarit Bhargava]

Missed deleting a chunk at the end of the patch...

An issue popped up where WARN_ON_ONCE() was used in a callback function
in smp_call_function().  This resulted in the WARN_ON executing multiple times
when it should have only executed once.

We cannot use a lock in the WARN_*_ONCE functions because it is far too heavy
for the code in question.  Don Zickus suggested using cmpxchg(), which resolves
the problem of the multiple outputs.

The question surrounding cmpxchg(), of course, is one of performance.  It
appears that, at least on x86, it isn't a concern.

I ran the following test in a simple module:

void prarit_callback(void *info)
{
        WARN_ON_ONCE(1);
}

        for (j = 0; j < 10; j++)
                for (i = 0; i < 1000000; i++)
                        prarit_callback(NULL);

With the current code in place an average of 10 runs was .219s.  Doing just
a (!cmpxchg(&__warned, 0, 1)) the time jumps to .402s.  Adding in a check
for the __warned flag, (!__warned && !cmpxchg(&__warned, 0, 1)), results in
an average of .220s.

I then did

        for (i = 0; i < 1000000; i++)
                on_each_cpu(prarit_callback, NULL, 0);

The current code, of course, explodes :).  That's the bug I'm trying to fix.
What is interesting in this test, however, is the impact that checking the
!__warned flag has [Aside: Checking the !__warned flag is an enhancement
and is not explicitly required for this code].

A run with just (!cmpxchg(&__warned, 0, 1)) results in an average of 21.323s,
and a run with  (!__warned && !cmpxchg(&__warned, 0, 1)) results in an
average of 20.233s.  Of course, the !__warned is not necessary for the code
to work properly but it seems to be a significant impact to the time to run
this code.

P.

WARN_ON_ONCE() is used in callback functions in smp_call_function().  This
results in races through the WARN_ON() code.

Use cmxchg() in the WARN_*_ON functions in order to guarantee single
execution of the WARN_ONs.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>

diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
index f2d2faf..1825fd7 100644
--- a/include/asm-generic/bug.h
+++ b/include/asm-generic/bug.h
@@ -133,32 +133,32 @@ extern void warn_slowpath_null(const char *file, const int line);
 #endif
 
 #define WARN_ON_ONCE(condition)	({				\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
-		if (WARN_ON(!__warned)) 			\
-			__warned = true;			\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN_ON(1);				\
 	unlikely(__ret_warn_once);				\
 })
 
 #define WARN_ONCE(condition, format...)	({			\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
-		if (WARN(!__warned, format)) 			\
-			__warned = true;			\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN(1, format);			\
 	unlikely(__ret_warn_once);				\
 })
 
 #define WARN_TAINT_ONCE(condition, taint, format...)	({	\
-	static bool __warned;					\
+	static int __warned;					\
 	int __ret_warn_once = !!(condition);			\
 								\
 	if (unlikely(__ret_warn_once))				\
-		if (WARN_TAINT(!__warned, taint, format))	\
-			__warned = true;			\
+		if (!__warned && !cmpxchg(&__warned, 0, 1))	\
+			WARN_TAINT(1, taint, format);		\
 	unlikely(__ret_warn_once);				\
 })