On Wed, 16 Feb 2022 19:39:03 +0100
Sven Schnelle <[email protected]> wrote:
> Hi Steve,
>
> in our CI we see the ftrace selftests crashing. It only happens
> in rare cases - for me i can boot the kernel hundred of times and
> it crashes only once. The oops output looks like this:
>
> [ 3.523720] Running postponed tracer tests:
> [ 3.524184] Testing tracer function: PASSED
> [ 3.801523] Testing dynamic ftrace: PASSED
> [ 4.068009] Testing dynamic ftrace ops #1:
> [ 4.140142] (1 0 1 0 0)
> [ 4.140149] (1 1 2 0 0)
> [ 4.200037] (2 1 3 0 822270)
> [ 4.200046] (2 2 4 0 822402)
> [ 4.232728] (3 2 4 0 1147236)
> [ 4.232740] (3 3 5 0 1147377)
> [ 4.300835] PASSED
> [ 4.300840] Testing dynamic ftrace ops #2:
> [ 4.420423] (1 0 1 582267 0)
> [ 4.420474] (1 1 2 583259 0)
> [ 4.420941] (2 1 3 1 5)
> [ 4.420947] (2 2 4 69 73)
> [ 4.458483] (3 2 4 494199 491341)
> [ 4.458616] (3 3 5 497496 494474)
> [ 4.460091] Unable to handle kernel pointer dereference in virtual kernel address space
> [ 4.460375] Failing address: 6b6b6b6b6b6b6000 TEID: 6b6b6b6b6b6b6803
> [ 4.460458] Fault in home space mode while using kernel ASCE.
> [ 4.460695] AS:000000008561c007 R3:0000000000000024
> [ 4.461143] Oops: 0038 ilc:3 [#1] PREEMPT SMP
> [ 4.461162] Modules linked in:
> [ 4.461175] CPU: 245 PID: 0 Comm: swapper/245 Not tainted 5.17.0-rc4-00051-gc5d9ae265b10-dirty #4
> [ 4.461183] Hardware name: IBM 8561 T01 701 (KVM/Linux)
I this a 390?
> [ 4.461194] Krnl PSW : 0404e00180000000 00000000835a1fe6 (arch_ftrace_ops_list_func+0x96/0x1b0)
> [ 4.461212] R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:2 PM:0 RI:0 EA:3
> [ 4.461226] Krnl GPRS: 0000000000000000 0000000084bbc110 0000000083496f48 00000000834061f2
> [ 4.461237] 000000008a70fa00 0000038000d0fba8 0000000000000001 fffffffffffffeff
> [ 4.461243] 00000000834061f2 0000038000d0fba8 6b6b6b6b6b6b6b6b 0000000083496f48
> [ 4.461250] 0000000000000000 0000000000000000 00000000835a209a 0000038000d0fab8
> [ 4.461269] Krnl Code: 00000000835a1fd4: e310a9380224 stg %r1,10552(%r10)
> 00000000835a1fda: eb0103a8006a asi 936,1
> #00000000835a1fe0: c4a800b0d094 lgrl %r10,0000000084bbc108
> >00000000835a1fe6: e310a0100004 lg %r1,16(%r10)
> 00000000835a1fec: a7110020 tmll %r1,32
> 00000000835a1ff0: a7740012 brc 7,00000000835a2014
> 00000000835a1ff4: a7114000 tmll %r1,16384
> 00000000835a1ff8: a7740031 brc 7,00000000835a205a
> [ 4.461383] Call Trace:
> [ 4.461388] [<00000000835a1fe6>] arch_ftrace_ops_list_func+0x96/0x1b0
> [ 4.461395] ([<00000000835a200e>] arch_ftrace_ops_list_func+0xbe/0x1b0)
> [ 4.461401] [<00000000841700ec>] ftrace_common+0x1c/0x20
> [ 4.461409] [<0000000083496f4e>] preempt_count_sub+0x6/0x138
> [ 4.461418] [<00000000834061f2>] read_tod_clock+0x4a/0xb0
> [ 4.461431] [<0000000083530818>] ktime_get+0xb8/0x178
> [ 4.461441] [<000000008353ec94>] clockevents_program_event+0x6c/0x138
> [ 4.461454] [<000000008352d206>] hrtimer_start_range_ns+0xc6/0x100
> [ 4.461467] [<0000000083541068>] tick_nohz_idle_stop_tick+0x90/0xf8
> [ 4.461479] [<00000000834a9790>] do_idle+0xf0/0x1b0
> [ 4.461495] [<00000000834a9ad6>] cpu_startup_entry+0x36/0x40
> [ 4.461509] [<000000008416e48e>] restart_int_handler+0x6e/0x90
> [ 4.461521] INFO: lockdep is turned off.
> [ 4.461527] Last Breaking-Event-Address:
> [ 4.461533] [<00000000835a2026>] arch_ftrace_ops_list_func+0xd6/0x1b0
> [ 4.461552] Kernel panic - not syncing: Fatal exception: panic_on_oops
>
> The code in question is the ops loop in __ftrace_ops_list_func():
>
> do_for_each_ftrace_op(op, ftrace_ops_list) {
> /* Stub functions don't need to be called nor tested */
> if (op->flags & FTRACE_OPS_FL_STUB)
> continue;
> ...
>
> The register (r10) where op is stored contains 0x6b6b6b6b6b6b6b6b
> (POISON_FREE), so it looks like the list contains a member that is
> already freed.
>
> Looking at unregister_ftrace_function(), i noticed that
> ftrace_shutdown() is called with 0 as command. Given that the ftrace
> function didn't change and ftrace is still enabled, the
> rcu_synchronize() functions in ftrace_shutdown() are silently skipped.
> So the caller frees ops already before other CPUs have gone through
> quiesce, and may therefore use the old (now freed) list entry.
>
> To fix this, i wonder whether we should change the code in
> unregister_ftrace_function() to:
>
> @@ -7827,7 +7837,7 @@ int unregister_ftrace_function(struct ftrace_ops *ops)
> int ret;
>
> mutex_lock(&ftrace_lock);
> - ret = ftrace_shutdown(ops, 0);
> + ret = ftrace_shutdown(ops, FTRACE_UPDATE_TRACE_FUNC);
No, the ftrace_shutdown() will add that flag if it is needed.
> mutex_unlock(&ftrace_lock);
>
> return ret;
>
> I haven't checked whether other callsites of unregister_ftrace_function()
> also need to be adjusted. What do you think about that 'fix'?
But what I'm thinking is, the function is being freed but has yet to be
removed from the list. Or that a synchronization is missed.
That is, shutdown is called, the item is removed from the list and freed,
but something got preempted while on the ftrace trampoline, with a
reference to the item, and then woke up and executed the item that was
freed.
I'll look into it. Thanks for the report.
-- Steve
Steven Rostedt <[email protected]> writes:
> On Wed, 16 Feb 2022 19:39:03 +0100
> Sven Schnelle <[email protected]> wrote:
>> [ 4.460091] Unable to handle kernel pointer dereference in virtual kernel address space
>> [ 4.460375] Failing address: 6b6b6b6b6b6b6000 TEID: 6b6b6b6b6b6b6803
>> [ 4.460458] Fault in home space mode while using kernel ASCE.
>> [ 4.460695] AS:000000008561c007 R3:0000000000000024
>> [ 4.461143] Oops: 0038 ilc:3 [#1] PREEMPT SMP
>> [ 4.461162] Modules linked in:
>> [ 4.461175] CPU: 245 PID: 0 Comm: swapper/245 Not tainted 5.17.0-rc4-00051-gc5d9ae265b10-dirty #4
>> [ 4.461183] Hardware name: IBM 8561 T01 701 (KVM/Linux)
>
> I this a 390?
Yes.
>> Looking at unregister_ftrace_function(), i noticed that
>> ftrace_shutdown() is called with 0 as command. Given that the ftrace
>> function didn't change and ftrace is still enabled, the
>> rcu_synchronize() functions in ftrace_shutdown() are silently skipped.
>> So the caller frees ops already before other CPUs have gone through
>> quiesce, and may therefore use the old (now freed) list entry.
>>
>> To fix this, i wonder whether we should change the code in
>> unregister_ftrace_function() to:
>>
>> @@ -7827,7 +7837,7 @@ int unregister_ftrace_function(struct ftrace_ops *ops)
>> int ret;
>>
>> mutex_lock(&ftrace_lock);
>> - ret = ftrace_shutdown(ops, 0);
>> + ret = ftrace_shutdown(ops, FTRACE_UPDATE_TRACE_FUNC);
>
> No, the ftrace_shutdown() will add that flag if it is needed.
>
>> mutex_unlock(&ftrace_lock);
>>
>> return ret;
>>
>> I haven't checked whether other callsites of unregister_ftrace_function()
>> also need to be adjusted. What do you think about that 'fix'?
>
> But what I'm thinking is, the function is being freed but has yet to be
> removed from the list. Or that a synchronization is missed.
>
> That is, shutdown is called, the item is removed from the list and freed,
> but something got preempted while on the ftrace trampoline, with a
> reference to the item, and then woke up and executed the item that was
> freed.
>
> I'll look into it. Thanks for the report.
With additional debugging i see:
@@ -2967,14 +2974,17 @@ int ftrace_shutdown(struct ftrace_ops *ops, int command)
}
if (!command || !ftrace_enabled) {
+ pr_err("%s: skipping rcu_synchronize(): ops=%pS command=%d ftrace_enabled=%d saved func=%pS ftrace_trace_func=%pS\n",
+ __func__, ops, command, ftrace_enabled, saved_ftrace_func, ftrace_trace_function);
/*
* If these are dynamic or per_cpu ops, they still
* need their data freed. Since, function tracing is
* not currently active, we can just free them
* without synchronizing all CPUs.
*/
[ +0.000011] unregister_ftrace_function: 0x2f6792e00
[ +0.000023] removing ops 00000002f6792e00 trace_selftest_test_dyn_func+0x0/0x18
[ +0.000661] ftrace_shutdown: skipping rcu_synchronize(): ops=0x2f6792e00 command=0 ftrace_enabled=1 saved func=arch_ftrace_ops_list_func+0x0/0x1b0 ft>
[ +0.010032] unregister_ftrace_function: test_probe1+0x0/0x1b0
[ +0.000017] removing ops 000000009d876e40 trace_selftest_test_probe1_func+0x0/0x18
[ +0.000053] ftrace_shutdown: skipping rcu_synchronize(): ops=test_probe1+0x0/0x1b0 command=0 ftrace_enabled=1 saved func=arch_ftrace_ops_list_func+0x>
[ +0.000017] unregister_ftrace_function: test_probe2+0x0/0x1b0
[ +0.000081] removing ops 000000009d876ff0 trace_selftest_test_probe2_func+0x0/0x18
[ +0.000064] ftrace_shutdown: skipping rcu_synchronize(): ops=test_probe2+0x0/0x1b0 command=0 ftrace_enabled=1 saved func=arch_ftrace_ops_list_func+0x>
[ +0.000015] unregister_ftrace_function: test_probe3+0x0/0x1b0
[ +0.000011] removing ops 000000009d8771a0 trace_selftest_test_probe3_func+0x0/0x18
[ +0.000108] unregister_ftrace_function: global_ops+0x0/0x1b0
[ +0.000010] removing ops 000000009d9325b8 trace_selftest_test_global_func+0x0/0x18
[ +0.025759] PASSED
So the rcu_synchronize is definitely skipped. Another thing i was
wondering was whether we need to reset the next pointer in
the to-be-removed entry in remove_ftrace_ops(). But i haven't
investigated that in detail yet.