Re: [PATCH] s390/idle: Fix suspicious RCU usage

[Sven Schnelle]

Hi Peter,

peterz@xxxxxxxxxxxxx writes:

> After commit eb1f00237aca ("lockdep,trace: Expose tracepoints") the
> lock tracepoints are visible to lockdep and RCU-lockdep is finding a
> bunch more RCU violations that were previously hidden.
>
> Switch the idle->seqcount over to using raw_write_*() to avoid the
> lockdep annotation and thus the lock tracepoints.
>
> Reported-by: Guenter Roeck <linux@xxxxxxxxxxxx>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@xxxxxxxxxxxxx>
> [..]

I'm still seeing the splat below on s390 when irq tracing is enabled:

[ 1273.747948] =============================
[ 1273.747953] WARNING: suspicious RCU usage
[ 1273.747960] 5.9.0-20201006.rc8.git0.162c12a918a1.300.fc32.s390x+debug #1 Not tainted
[ 1273.747965] -----------------------------
[ 1273.747971] include/trace/events/lock.h:74 suspicious rcu_dereference_check() usage!
[ 1273.747976] other info that might help us debug this:
[ 1273.747982] rcu_scheduler_active = 2, debug_locks = 1
[ 1273.747987] RCU used illegally from extended quiescent state!
[ 1273.747993] 1 lock held by swapper/8/0:
[ 1273.747998]  #0: 000000010f7281b8 (max_trace_lock){..-.}-{2:2}, at: check_critical_timing+0x7c/0x1c8
[ 1273.748019] stack backtrace:
[ 1273.748034] CPU: 8 PID: 0 Comm: swapper/8 Not tainted 5.9.0-20201006.rc8.git0.162c12a918a1.300.fc32.s390x+debug #1
[ 1273.748040] Hardware name: IBM 2964 NC9 702 (z/VM 6.4.0)
[ 1273.748045] Call Trace:
[ 1273.748053]  [<000000010e656de0>] show_stack+0x90/0xf8 
[ 1273.748060]  [<000000010eea94da>] dump_stack+0xa2/0xd8 
[ 1273.748068]  [<000000010e711cc8>] trace_lock_acquired+0x178/0x180 
[ 1273.748075]  [<000000010e718ed4>] lock_contended+0x24/0xd8 
[ 1273.748083]  [<000000010f26d148>] _raw_spin_lock_irqsave+0xb0/0xd8 
[ 1273.748089]  [<000000010e7ec404>] check_critical_timing+0x7c/0x1c8 
[ 1273.748096]  [<000000010e7ecaa8>] tracer_hardirqs_on+0x128/0x148 
[ 1273.748103]  [<000000010e7eae0c>] trace_hardirqs_on+0x6c/0x1b0 
[ 1273.748110]  [<000000010e644ba8>] arch_cpu_idle+0x28/0x38 
[ 1273.748116]  [<000000010f26ccd6>] default_idle_call+0x56/0x98 
[ 1273.748124]  [<000000010e6da81a>] do_idle+0xf2/0x1b0 
[ 1273.748130]  [<000000010e6dab4e>] cpu_startup_entry+0x36/0x40 
[ 1273.748137]  [<000000010e6590fa>] smp_start_secondary+0x82/0x88 
[ 1273.748142] 1 lock held by swapper/8/0:
[ 1273.748147]  #0: 000000010f7281b8 (max_trace_lock){..-.}-{2:2}, at: check_critical_timing+0x7c/0x1c8

I think this happens because trace_lock_acquired gets called from idle
context?

Regards
Sven