Re: [Syzkaller & bisect] There is "task hung in synchronize_rcu bisect" in v6.3-rc2 kernel

[Pengfei Xu <pengfei.xu@intel.com>]

Hi Danton,

On 2023-04-13 at 15:00:42 +0800, Hillf Danton wrote:
> On 13 Apr 2023 10:45:35 +0800 Pengfei Xu <pengfei.xu@intel.com>
> > Hi Huafei and kernel experts,
> > 
> > It's a soft remind.
> > This issue could be reproduced in v6.3-rc6 kernel.
> > It could be reproduced on Alder lake, Raptor lake and so on x86 platforms.
> > After reverted the commit "0e792b89e6800c:ftrace: Fix use-after-free for
> > dynamic ftrace_ops" on top of v6.3-rc6 kernel, this issue was gone.
> > 
> > New syzkaller reproduced code, repro.report, bisect_info.log and detailed logs
> > are in link: https://github.com/xupengfe/syzkaller_logs/tree/main/230412_031722_synchronize_rcu
> > 
> > Thanks!
> > BR.
> > 
> > On 2023-03-15 at 20:20:44 +0800, Pengfei Xu wrote:
> > > Hi Li Huafei and kernel experts,
> > > 
> > > Greeting!
> > > 
> > > Platform: x86 platforms
> > > There is "task hung in synchronize_rcu bisect" in v6.3-rc2 kernel in guest:
> > > 
> > > All detailed info: https://github.com/xupengfe/syzkaller_logs/tree/main/230315_023443_synchronize_rcu
> > > Reproduced code: https://github.com/xupengfe/syzkaller_logs/blob/main/230315_023443_synchronize_rcu/repro.c
> > > Kconfig: https://github.com/xupengfe/syzkaller_logs/blob/main/230315_023443_synchronize_rcu/kconfig_origin
> > > Bisect info: https://github.com/xupengfe/syzkaller_logs/blob/main/230315_023443_synchronize_rcu/bisect_info.log
> > > v6.3-rc2 issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/230315_023443_synchronize_rcu/eeac8ede17557680855031c6f305ece2378af326_dmesg.log
> > > "
> > > [   24.844767] memfd_create() without MFD_EXEC nor MFD_NOEXEC_SEAL, pid=330 'systemd'
> > > [   31.392668] hrtimer: interrupt took 10726570 ns
> 
> What hrtimer/s triggered this print? And for what? The hrtimer trace helps here.
> Info like that helps work out the cause of the task hang.
> Feel free to fold in the debug diff below if it makes sense to you.
> 
  Thanks for your debug patch.

  I newly updated previous alder lake S reproduced syzkaller repro.prog and
  machineInfo0(vm info) info in log link:
https://github.com/xupengfe/syzkaller_logs/tree/main/230315_023443_synchronize_rcu

And tried debug kernel on alder lake S, there were 2 cpu in guest, and
CPU1 reported "interrupt took 331596 ns", then kernel should not trigger
"rcu_tasks_wait_gp" for this issue.
"
[  104.171591] memfd_create() without MFD_EXEC nor MFD_NOEXEC_SEAL, pid=334 'systemd'
[  126.770981] hrtimer CPU1: interrupt took 331596 ns      //  "rcu_tasks_wait_gp" after 15s
[  141.127282] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 2571 jiffies old.
[  171.272100] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 10107 jiffies old.
[  261.767189] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 32731 jiffies old.
[  300.102911] INFO: task repro_rcu:398 blocked for more than 147 seconds.
[  300.103408]       Not tainted 6.3.0-rc6-dbg-dirty #1
[  300.103743] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  300.104230] task:repro_rcu       state:D stack:0     pid:398   ppid:396    flags:0x00004006
[  300.104780] Call Trace:
[  300.104992]  <TASK>
[  300.105265]  __schedule+0x40a/0xc30
[  300.105706]  ? wait_for_completion+0x7b/0x180
[  300.106041]  schedule+0x5b/0xe0
[  300.106330]  schedule_timeout+0x4db/0x5b0
[  300.106959]  ? schedule_timeout+0x9/0x5b0
[  300.107364]  ? wait_for_completion+0x7b/0x180
[  300.107698]  wait_for_completion+0xa6/0x180
[  300.108141]  __wait_rcu_gp+0x136/0x160
[  300.108474]  ? __pfx_arch_ftrace_ops_list_func+0x10/0x10
[  300.108875]  synchronize_rcu_tasks_generic.part.24+0x3b/0x60
[  300.109263]  ? __pfx_call_rcu_tasks+0x10/0x10
[  300.109592]  ? __pfx_wakeme_after_rcu+0x10/0x10
[  300.110020]  ? verify_cpu+0x10/0x100
[  300.110353]  synchronize_rcu_tasks_generic+0x24/0x70
[  300.110840]  synchronize_rcu_tasks+0x19/0x20
[  300.111173]  ftrace_shutdown+0x1cc/0x410
[  300.111564]  unregister_ftrace_function+0x35/0x230
[  300.111950]  ? __sanitizer_cov_trace_switch+0x57/0xa0
[  300.112380]  perf_ftrace_event_register+0x95/0xf0
[  300.112733]  ? __pfx_tp_perf_event_destroy+0x10/0x10
[  300.113092]  perf_trace_destroy+0x3a/0xa0
[  300.113410]  ? __pfx_tp_perf_event_destroy+0x10/0x10
[  300.113768]  tp_perf_event_destroy+0x1e/0x30
[  300.114109]  _free_event+0x101/0x810
[  300.114470]  put_event+0x3c/0x50
[  300.114920]  perf_event_release_kernel+0x2de/0x360
[  300.115266]  ? perf_event_release_kernel+0x9/0x360
[  300.115685]  ? __pfx_perf_release+0x10/0x10
[  300.116036]  perf_release+0x22/0x30
[  300.116344]  __fput+0x11f/0x450
[  300.116739]  ____fput+0x1e/0x30
[  300.117031]  task_work_run+0xb6/0x120
[  300.117407]  do_exit+0x547/0x12b0
[  300.117739]  ? write_comp_data+0x2f/0x90
[  300.118141]  do_group_exit+0x5e/0xf0
[  300.118498]  get_signal+0x1465/0x14a0
[  300.119142]  arch_do_signal_or_restart+0x33/0x280
[  300.119697]  exit_to_user_mode_prepare+0x13b/0x210
[  300.120078]  syscall_exit_to_user_mode+0x2d/0x60
[  300.120439]  do_syscall_64+0x4a/0x90
[  300.120748]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
[  300.121102] RIP: 0033:0x7f2c55b8a59d
[  300.121389] RSP: 002b:00007ffc6ea72078 EFLAGS: 00000246 ORIG_RAX: 000000000000012a
[  300.121894] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f2c55b8a59d
[  300.122332] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000020000080
[  300.122890] RBP: 00007ffc6ea72090 R08: 0000000000000000 R09: 00007ffc6ea72090
[  300.123327] R10: 00000000ffffffff R11: 0000000000000246 R12: 00000000004011c0
[  300.123765] R13: 00007ffc6ea721b0 R14: 0000000000000000 R15: 0000000000000000
[  300.124479]  </TASK>
[  300.124676] 
               Showing all locks held in the system:
[  300.125063] 1 lock held by rcu_tasks_kthre/11:
[  300.125370]  #0: ffffffff83d63450 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420
[  300.126170] 1 lock held by rcu_tasks_rude_/12:
[  300.126476]  #0: ffffffff83d631d0 (rcu_tasks_rude.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420
[  300.127421] 1 lock held by rcu_tasks_trace/13:
[  300.127728]  #0: ffffffff83d62f10 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420
[  300.128551] 1 lock held by khungtaskd/29:
[  300.128834]  #0: ffffffff83d63e60 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x1b/0x1e0
[  300.129607] 1 lock held by systemd-journal/124:
[  300.129921] 2 locks held by repro_rcu/398:
[  300.130209]  #0: ffffffff83e20668 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0
[  300.131083]  #1: ffffffff83e1cd28 (ftrace_lock){+.+.}-{3:3}, at: unregister_ftrace_function+0x2b/0x230

[  300.132040] =============================================
"

Thanks!
BR.

> +++ b/kernel/time/hrtimer.c
> @@ -1866,7 +1866,7 @@ retry:
>  	else
>  		expires_next = ktime_add(now, delta);
>  	tick_program_event(expires_next, 1);
> -	pr_warn_once("hrtimer: interrupt took %llu ns\n", ktime_to_ns(delta));
> +	pr_warn_once("hrtimer CPU%u: interrupt took %llu ns\n", cpu_base->cpu, ktime_to_ns(delta));
>  }
>  
>  /* called with interrupts disabled */