[PATCH] tracing: Fix lockdep warning in global_clock()

[PATCH] tracing: Fix lockdep warning in global_clock()

[Li Zefan]

 # echo 1 > events/enable
 # echo global > trace_clock

------------[ cut here ]------------
WARNING: at kernel/lockdep.c:3162 check_flags+0xb2/0x190()
...
---[ end trace 3f86734a89416623 ]---
possible reason: unannotated irqs-on.
...

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
---
 kernel/trace/trace_clock.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
index 84a3a7b..11563c9 100644
--- a/kernel/trace/trace_clock.c
+++ b/kernel/trace/trace_clock.c
@@ -83,7 +83,7 @@ u64 notrace trace_clock_global(void)
 	int this_cpu;
 	u64 now;
 
-	raw_local_irq_save(flags);
+	local_irq_save(flags);
 
 	this_cpu = raw_smp_processor_id();
 	now = cpu_clock(this_cpu);
@@ -109,7 +109,7 @@ u64 notrace trace_clock_global(void)
 	arch_spin_unlock(&trace_clock_struct.lock);
 
  out:
-	raw_local_irq_restore(flags);
+	local_irq_restore(flags);
 
 	return now;
 }
-- 
1.6.3

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Ingo Molnar]

* Li Zefan <lizf@cn.fujitsu.com> wrote:

>  # echo 1 > events/enable
>  # echo global > trace_clock
> 
> ------------[ cut here ]------------
> WARNING: at kernel/lockdep.c:3162 check_flags+0xb2/0x190()
> ...
> ---[ end trace 3f86734a89416623 ]---
> possible reason: unannotated irqs-on.
> ...
> 
> Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
> ---
>  kernel/trace/trace_clock.c |    4 ++--
>  1 files changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
> index 84a3a7b..11563c9 100644
> --- a/kernel/trace/trace_clock.c
> +++ b/kernel/trace/trace_clock.c
> @@ -83,7 +83,7 @@ u64 notrace trace_clock_global(void)
>  	int this_cpu;
>  	u64 now;
>  
> -	raw_local_irq_save(flags);
> +	local_irq_save(flags);

Hm, wont this cause problems when we trace inside lockdep? Have you tried the 
lockdep events - do they still work?

	Ingo

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Li Zefan]

Ingo Molnar wrote:
> * Li Zefan <lizf@cn.fujitsu.com> wrote:
> 
>>  # echo 1 > events/enable
>>  # echo global > trace_clock
>>
>> ------------[ cut here ]------------
>> WARNING: at kernel/lockdep.c:3162 check_flags+0xb2/0x190()
>> ...
>> ---[ end trace 3f86734a89416623 ]---
>> possible reason: unannotated irqs-on.
>> ...
>>
>> Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
>> ---
>>  kernel/trace/trace_clock.c |    4 ++--
>>  1 files changed, 2 insertions(+), 2 deletions(-)
>>
>> diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
>> index 84a3a7b..11563c9 100644
>> --- a/kernel/trace/trace_clock.c
>> +++ b/kernel/trace/trace_clock.c
>> @@ -83,7 +83,7 @@ u64 notrace trace_clock_global(void)
>>  	int this_cpu;
>>  	u64 now;
>>  
>> -	raw_local_irq_save(flags);
>> +	local_irq_save(flags);
> 
> Hm, wont this cause problems when we trace inside lockdep? Have you tried the 
> lockdep events - do they still work?
> 

Yes, they still work.

trace_clock_global() calls cpu_clock() which calls local_irq_save(),
which causes this lockdep warning.

And I noticed this commit:

===============================================
commit 2d452c9b10caeec455eb5e56a0ef4ed485178213
Author: Ingo Molnar <mingo@elte.hu>
Date:   Sun Jun 29 15:01:59 2008 +0200

    sched: sched_clock_cpu() based cpu_clock(), lockdep fix

    Vegard Nossum reported:

    > WARNING: at kernel/lockdep.c:2738 check_flags+0x142/0x160()

    which happens due to:

     unsigned long long cpu_clock(int cpu)
     {
             unsigned long long clock;
             unsigned long flags;

             raw_local_irq_save(flags);

    as lower level functions can take locks, we must not do that, use
    proper lockdep-annotated irq save/restore.

    Reported-by: Vegard Nossum <vegard.nossum@gmail.com>
    Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index ed5a8c4..60094e2 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -250,9 +250,9 @@ unsigned long long cpu_clock(int cpu)
        unsigned long long clock;
        unsigned long flags;

-       raw_local_irq_save(flags);
+       local_irq_save(flags);
        clock = sched_clock_cpu(cpu);
-       raw_local_irq_restore(flags);
+       local_irq_restore(flags);

        return clock;
 }
===============================================

I guess it's still true that lower level functions can take locks?

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Peter Zijlstra]

On Mon, 2009-12-21 at 15:36 +0800, Li Zefan wrote:

> +++ b/kernel/sched_clock.c
> @@ -250,9 +250,9 @@ unsigned long long cpu_clock(int cpu)
>         unsigned long long clock;
>         unsigned long flags;
> 
> -       raw_local_irq_save(flags);
> +       local_irq_save(flags);
>         clock = sched_clock_cpu(cpu);
> -       raw_local_irq_restore(flags);
> +       local_irq_restore(flags);
> 
>         return clock;
>  }
> ===============================================
> 
> I guess it's still true that lower level functions can take locks?

No, I removed the locks from cpu_clock a while back.

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Steven Rostedt]

On Mon, 2009-12-21 at 15:40 +0100, Peter Zijlstra wrote:
> On Mon, 2009-12-21 at 15:36 +0800, Li Zefan wrote:
> 
> > +++ b/kernel/sched_clock.c
> > @@ -250,9 +250,9 @@ unsigned long long cpu_clock(int cpu)
> >         unsigned long long clock;
> >         unsigned long flags;
> > 
> > -       raw_local_irq_save(flags);
> > +       local_irq_save(flags);
> >         clock = sched_clock_cpu(cpu);
> > -       raw_local_irq_restore(flags);
> > +       local_irq_restore(flags);
> > 
> >         return clock;
> >  }
> > ===============================================
> > 
> > I guess it's still true that lower level functions can take locks?
> 
> No, I removed the locks from cpu_clock a while back.
> 

The problem isn't with locks, it's with disabling interrupts. Lockdep
keeps track of every time interrupts are disabled. If something disables
interrupts with raw_* but then calls something that disables interrupts
the normal way, lockdep will detect that interrupts are being disabled
but they already are disabled. The internal irq disabled variable in
lockdep wont match reality, and this will blow up (well, disable
lockdep).

So if cpu_clock disables interrupts with local_irq_* then so must
trace_clock_global.

-- Steve

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Li Zefan]

Steven Rostedt wrote:
> On Mon, 2009-12-21 at 15:40 +0100, Peter Zijlstra wrote:
>> On Mon, 2009-12-21 at 15:36 +0800, Li Zefan wrote:
>>
>>> +++ b/kernel/sched_clock.c
>>> @@ -250,9 +250,9 @@ unsigned long long cpu_clock(int cpu)
>>>         unsigned long long clock;
>>>         unsigned long flags;
>>>
>>> -       raw_local_irq_save(flags);
>>> +       local_irq_save(flags);
>>>         clock = sched_clock_cpu(cpu);
>>> -       raw_local_irq_restore(flags);
>>> +       local_irq_restore(flags);
>>>
>>>         return clock;
>>>  }
>>> ===============================================
>>>
>>> I guess it's still true that lower level functions can take locks?
>> No, I removed the locks from cpu_clock a while back.
>>
> 
> The problem isn't with locks, it's with disabling interrupts. Lockdep
> keeps track of every time interrupts are disabled. If something disables
> interrupts with raw_* but then calls something that disables interrupts
> the normal way, lockdep will detect that interrupts are being disabled
> but they already are disabled. The internal irq disabled variable in
> lockdep wont match reality, and this will blow up (well, disable
> lockdep).
> 
> So if cpu_clock disables interrupts with local_irq_* then so must
> trace_clock_global.
> 

Looking into sched_clock.c, seems the only place that can trigger lockdep
is the local_irq_* in cpu_clock(), though I'm not sure for architecture-
specific sched_clock().

If so, I think we can use raw_local_irq_* in cpu_clock(). Actually I
tried it and the warning is gone.

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Yong Zhang]

[snip]
>> The problem isn't with locks, it's with disabling interrupts. Lockdep
>> keeps track of every time interrupts are disabled. If something disables
>> interrupts with raw_* but then calls something that disables interrupts
>> the normal way, lockdep will detect that interrupts are being disabled
>> but they already are disabled. The internal irq disabled variable in
>> lockdep wont match reality, and this will blow up (well, disable
>> lockdep).
>>
>> So if cpu_clock disables interrupts with local_irq_* then so must
>> trace_clock_global.
>>
>
> Looking into sched_clock.c, seems the only place that can trigger lockdep
> is the local_irq_* in cpu_clock(), though I'm not sure for architecture-
> specific sched_clock().
>
> If so, I think we can use raw_local_irq_* in cpu_clock(). Actually I
> tried it and the warning is gone.
>

I think the reason is on local_irq_restore():

#define local_irq_restore(flags)			\
	do {						\
		typecheck(unsigned long, flags);	\
		if (raw_irqs_disabled_flags(flags)) {	\
			raw_local_irq_restore(flags);	\
			trace_hardirqs_off();		\                        <======
		} else {				\
			trace_hardirqs_on();		\
			raw_local_irq_restore(flags);	\
		}					\
	} while (0)

If we have a call trace like below:
raw_local_irq_save();
            ...
local_irq_save();
            ...
local_irq_restore();
            ...
raw_locla_irq_save();

Then when we leave from local_irq_restore(), current->hardirqs_enabled will
changed by trace_hardirqs_off() to 0, this will break the all consistent.

Thanks,
Yong

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Peter Zijlstra]

On Tue, 2009-12-22 at 13:17 +0800, Li Zefan wrote:

> Looking into sched_clock.c, seems the only place that can trigger lockdep
> is the local_irq_* in cpu_clock(), though I'm not sure for architecture-
> specific sched_clock().

But why would you want to do that? that reduces the lockdep coverage for
no good reason, just fix up the tracer.

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Li Zefan]

Peter Zijlstra wrote:
> On Tue, 2009-12-22 at 13:17 +0800, Li Zefan wrote:
> 
>> Looking into sched_clock.c, seems the only place that can trigger lockdep
>> is the local_irq_* in cpu_clock(), though I'm not sure for architecture-
>> specific sched_clock().
> 
> But why would you want to do that? that reduces the lockdep coverage for
> no good reason, just fix up the tracer.
> 

Then the proper fix is to use local_irq_* in global_clock(), which
is what this patch does.

Re: [PATCH] tracing: Fix lockdep warning in global_clock()

[Steven Rostedt]

On Mon, 2009-12-21 at 07:43 +0100, Ingo Molnar wrote:
> * Li Zefan <lizf@cn.fujitsu.com> wrote:
> 
> >  # echo 1 > events/enable
> >  # echo global > trace_clock
> > 
> > ------------[ cut here ]------------
> > WARNING: at kernel/lockdep.c:3162 check_flags+0xb2/0x190()
> > ...
> > ---[ end trace 3f86734a89416623 ]---
> > possible reason: unannotated irqs-on.
> > ...
> > 
> > Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
> > ---
> >  kernel/trace/trace_clock.c |    4 ++--
> >  1 files changed, 2 insertions(+), 2 deletions(-)
> > 
> > diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
> > index 84a3a7b..11563c9 100644
> > --- a/kernel/trace/trace_clock.c
> > +++ b/kernel/trace/trace_clock.c
> > @@ -83,7 +83,7 @@ u64 notrace trace_clock_global(void)
> >  	int this_cpu;
> >  	u64 now;
> >  
> > -	raw_local_irq_save(flags);
> > +	local_irq_save(flags);
> 
> Hm, wont this cause problems when we trace inside lockdep? Have you tried the 
> lockdep events - do they still work?


Doesn't the lockdep code protect against this type of recursion.

Working with interrupts and spin locks in the latency code, I found that
I had to remove all the raw_local_irq_save for the normal
local_irq_save. Because if you disable interrupts with raw_* and then
anything that is called must also disable with raw_*, if they don't then
lockdep will blow up.

-- Steve