[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <yt9dh7p78d8l.fsf@linux.ibm.com>
Date: Mon, 30 Nov 2020 09:23:22 +0100
From: Sven Schnelle <svens@...ux.ibm.com>
To: Peter Zijlstra <peterz@...radead.org>
Cc: Linus Torvalds <torvalds@...ux-foundation.org>,
Thomas Gleixner <tglx@...utronix.de>,
"Paul E. McKenney" <paulmck@...nel.org>,
Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
the arch/x86 maintainers <x86@...nel.org>
Subject: Re: [GIT pull] locking/urgent for v5.10-rc6
Hi Peter,
Peter Zijlstra <peterz@...radead.org> writes:
> On Sun, Nov 29, 2020 at 11:31:41AM -0800, Linus Torvalds wrote:
>> On Sun, Nov 29, 2020 at 5:38 AM Thomas Gleixner <tglx@...utronix.de> wrote:
>> >
>> > Yet two more places which invoke tracing from RCU disabled regions in the
>> > idle path. Similar to the entry path the low level idle functions have to
>> > be non-instrumentable.
>>
>> This really seems less than optimal.
>>
>> In particular, lookie here:
>>
>> > @@ -94,9 +94,35 @@ void __cpuidle default_idle_call(void)
>> >
>> > trace_cpu_idle(1, smp_processor_id());
>> > stop_critical_timings();
>> > +
>> > + /*
>> > + * arch_cpu_idle() is supposed to enable IRQs, however
>> > + * we can't do that because of RCU and tracing.
>> > + *
>> > + * Trace IRQs enable here, then switch off RCU, and have
>> > + * arch_cpu_idle() use raw_local_irq_enable(). Note that
>> > + * rcu_idle_enter() relies on lockdep IRQ state, so switch that
>> > + * last -- this is very similar to the entry code.
>> > + */
>> > + trace_hardirqs_on_prepare();
>> > + lockdep_hardirqs_on_prepare(_THIS_IP_);
>> > rcu_idle_enter();
>> > + lockdep_hardirqs_on(_THIS_IP_);
>> > +
>> > arch_cpu_idle();
>> > +
>> > + /*
>> > + * OK, so IRQs are enabled here, but RCU needs them disabled to
>> > + * turn itself back on.. funny thing is that disabling IRQs
>> > + * will cause tracing, which needs RCU. Jump through hoops to
>> > + * make it 'work'.
>> > + */
>> > + raw_local_irq_disable();
>> > + lockdep_hardirqs_off(_THIS_IP_);
>> > rcu_idle_exit();
>> > + lockdep_hardirqs_on(_THIS_IP_);
>> > + raw_local_irq_enable();
>> > +
>> > start_critical_timings();
>> > trace_cpu_idle(PWR_EVENT_EXIT, smp_processor_id());
>> > }
>>
>> And look at what the code generation for the idle exit path is when
>> lockdep isn't even on.
>
> Agreed.
>
> The idea was to flip all of arch_cpu_idle() to not enable interrupts.
>
> This is suboptimal for things like x86 where arch_cpu_idle() is
> basically STI;HLT, but x86 isn't likely to actually use this code path
> anyway, given all the various cpuidle drivers it has.
>
> Many of the other archs are now doing things like arm's:
> wfi();raw_local_irq_enable().
>
> Doing that tree-wide interrupt-state flip was something I didn't want to
> do at this late a stage, the chanse of messing that up is just too high.
>
> After that I need to go look at flipping cpuidle, which is even more
> 'interesting'. cpuidle_enter() has the exact same semantics, and this is
> the code path that x86 actually uses, and here it's inconsitent at best.
On s390 this introduces the following splat:
[ 2.962283] Testing tracer wakeup_rt:
[ 3.017102] sched: DL replenish lagged too much
[ 3.061777] PASSED
[ 3.062076] Testing tracer wakeup_dl: PASSED
[ 3.161296] ------------[ cut here ]------------
[ 3.161301] DEBUG_LOCKS_WARN_ON(current->hardirq_chain_key != current->curr_chain_key)
[ 3.161310] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:4155 lockdep_hardirqs_on+0x1ea/0x1f8
[ 3.161316] Modules linked in:
[ 3.161323] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.0-rc6-07209-g9e30ba6d2d5c #2249
[ 3.161327] Hardware name: IBM 2964 NC9 702 (z/VM 6.4.0)
[ 3.161331] Krnl PSW : 0404d00180000000 0000000000d730fe (lockdep_hardirqs_on+0x1ee/0x1f8)
[ 3.161340] R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 RI:0 EA:3
[ 3.161347] Krnl GPRS: c0000000ffffbfff 0000000080000001 000000000000004a 00000000001e33b8
[ 3.161352] 0000038000007b88 0000038000007b80 ffffffffffffffff 0000000000000000
[ 3.161357] 0000000000000000 000000000151a610 0000000001361500 0000000000d81d40
[ 3.161362] 0000000000010400 0000000000d88010 0000000000d730fa 0000038000007db8
[ 3.161461] Krnl Code: 0000000000d730ee: c0200012d9ad larl %r2,0000000000fce448
[ 3.161461] 0000000000d730f4: c0e5ffff451a brasl %r14,0000000000d5bb28
[ 3.161461] #0000000000d730fa: af000000 mc 0,0
[ 3.161461] >0000000000d730fe: a7f4ff70 brc 15,0000000000d72fde
[ 3.161461] 0000000000d73102: 0707 bcr 0,%r7
[ 3.161461] 0000000000d73104: 0707 bcr 0,%r7
[ 3.161461] 0000000000d73106: 0707 bcr 0,%r7
[ 3.161461] 0000000000d73108: c418002884ec lgrl %r1,0000000001283ae0
[ 3.161518] Call Trace:
[ 3.161526] [<0000000000d730fe>] lockdep_hardirqs_on+0x1ee/0x1f8
[ 3.161532] ([<0000000000d730fa>] lockdep_hardirqs_on+0x1ea/0x1f8)
[ 3.161538] [<0000000000d81da6>] default_idle_call+0x96/0xd8
[ 3.161544] [<0000000000199dba>] do_idle+0xf2/0x1b0
[ 3.161550] [<000000000019a0ee>] cpu_startup_entry+0x36/0x40
[ 3.161604] [<000000000141af2e>] arch_call_rest_init+0x76/0x80
[ 3.161645] INFO: lockdep is turned off.
[ 3.161649] Last Breaking-Event-Address:
[ 3.161661] [<00000000001e436e>] vprintk_emit+0xde/0x1a8
[ 3.161700] irq event stamp: 10315
[ 3.161712] hardirqs last enabled at (10313): [<00000000001aa3ec>] load_balance+0x2ac/0x9c0
[ 3.161751] hardirqs last disabled at (10314): [<0000000000d853c6>] __do_softirq+0x2de/0x3c8
[ 3.161756] softirqs last enabled at (10315): [<0000000000d85384>] __do_softirq+0x29c/0x3c8
[ 3.161767] softirqs last disabled at (10308): [<000000000010dd70>] do_softirq_own_stack+0x70/0x80
[ 3.161802] ---[ end trace 4484b2a7468d1380 ]---
[ 3.161887] Testing tracer function_graph: PASSED
[ 3.353303] prandom32: self test passed (less than 6 bits correlated)
[ 3.353319] prandom: seed boundary self test passed
Haven't looked into it yet.
Regards
Sven
Powered by blists - more mailing lists