Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Thu, 13 Apr 2023 16:03:51 +0800
From:   Pengfei Xu <pengfei.xu@intel.com>
To:     Hillf Danton <hdanton@sina.com>
CC:     <lihuafei1@huawei.com>, <rostedt@goodmis.org>,
        <linux-kernel@vger.kernel.org>, <lkp@intel.com>,
        <frederic@kernel.org>, <quic_neeraju@quicinc.com>,
        <paulmck@kernel.org>, <heng.su@intel.com>
Subject: Re: [Syzkaller & bisect] There is "task hung in synchronize_rcu
 bisect" in v6.3-rc2 kernel
Message-ID: <ZDe3Z2WD5hxeQFTn@xpf.sh.intel.com>
References: <ZBG4HOCQIlGFFcIn@xpf.sh.intel.com>
 <20230413070042.1479-1-hdanton@sina.com>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
In-Reply-To: <20230413070042.1479-1-hdanton@sina.com>
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?s4XoR7WqEKzf02YjYOX0zOPCcV56TY8A4/GWn0ZOAVT7z5wQy32aw4YMlooU?=
 =?us-ascii?Q?poV/2gs4EY9Vd8Cafs+4Cpr7HTvo0KwhawLjj/qzrPEbHTGyPLX0SpbpaYAf?=
 =?us-ascii?Q?giW+lTMPSRfT7T6+Ejc0vEWLgGB0WwL0qRJkPx6Zs0MdYCmqRjpXREHD+xT0?=
 =?us-ascii?Q?J2iWFHChS4M6vEmJfpS/jjVzTdW0XQY15QxFw4EBZK9/14BY9qsgFUcg2xyq?=
 =?us-ascii?Q?G923Uf8xYhhxh5zClCDxBfB54KY6udprA761XCd4G/QoXsrfO70ev5B9a7uW?=
 =?us-ascii?Q?tT1Tvt1jdkmI6gHzrodPBD5B34M02MSoG67eHcr/++EOwRcY8izENesBw9Zs?=
 =?us-ascii?Q?2C6+bgqA78hV73UZShF0GHQA+bsY3uGA9AZUcWd7jeN41Njjwa9OCu1YwTg5?=
 =?us-ascii?Q?daN3IExtZzgVIRLSehMCXLfUNrWGVI4zVfmXm8uP6a8pK6K9j5LSAkrEBKjB?=
 =?us-ascii?Q?YwIhpxHg97LGH9sxRwsMlc9lQz23vXNjMCjf6A1jwPKP1PRscbL7MoeUZQ9V?=
 =?us-ascii?Q?YM21C3B+NepkOt+1SbVASN0HblSYZzQJsw14DCynTZ7e4ke7vhc3nvXqxgHl?=
 =?us-ascii?Q?gPx19eTX3Q2YqHFaQWnqOO6cft5Jfsce1pofvGsQ8T4DJARnBnMVW8cH4n5R?=
 =?us-ascii?Q?b2NlILCXiEoXdhwRtc12GiiZNEqhsakvfYIi96zwLjyyQYu8lsMJ1thiZXKZ?=
 =?us-ascii?Q?vfV3kJkUxl519BzEXl2KrnhS6uwxcHa06+FmASfh7w0cctEAJJEGA6+GaqjR?=
 =?us-ascii?Q?VkCx2ZZCg8AmPKX5akuL1obqYk7q0v5zd84UEXQAfgdCGOCNG9drwqLCGN9P?=
 =?us-ascii?Q?wMbsZxuA57y6dIvSH39eyEYc40kozBMPmUuoXBw0KV+mbPQkd23qg7SeSBgE?=
 =?us-ascii?Q?byS8CxqQvgAwziPF9F00kJlyDQPgHiXOc/aqcfvLmC/4I/HWdOI3Os9VFzr/?=
 =?us-ascii?Q?AvW+We8AypnIBrT2mDMsJY5grLS+7mXfgOXtzw+5bFQ8jPE6ebHoEpeViy6h?=
 =?us-ascii?Q?/domWfDRNWUsCMmP3cKD9m3HXwfSXIeRzpUtDdqGBvN6giXShKGWYm+0l+K8?=
 =?us-ascii?Q?BCODCM9AjAhqmUZC/NEXdJtotIQL7ckwBpqdSWR5DpbMkw9PlyEjZqzwDvTR?=
 =?us-ascii?Q?OXUL3sYrQJ/BBPSxwZZb+ftJ+EGJEDz4MRGxmxxfwAwy0NMa4yePK6p7o25v?=
 =?us-ascii?Q?bydiYOdD6G1y71qWZDH0Aa6HaJPkNjsb7yaZexjD41fslE18zZjJH3SojP5G?=
 =?us-ascii?Q?NwSe7k/wGHUd6h1oQQoR9n3+EIeaFpZw4aVZnOZvlzyslGj4R1+UEE+sTydK?=
 =?us-ascii?Q?AP8QBZcaA9RCueQHfcuQwgtxKcIPhLcJNwqL803+Uzn6tPnsGbFpBsmFg5Lc?=
 =?us-ascii?Q?/VzLyvDK9Er5x2mylbaljNUob2/nS4wJmvNB96qjNibm2TJAzela7sFK07Es?=
 =?us-ascii?Q?8KeFKdPC6TyhtYXIiENFgnwc/Y58iLmoENe0IW5Lzk29clPtvpHqQ4yfwmd0?=
 =?us-ascii?Q?VHOWfCBAhzCt26O0gQz73b7NLxmBg/BaeVVTq4mWIJfDlclufNUcokKOWCCz?=
 =?us-ascii?Q?NGwFUSvw2drekxfluCAQ3VzAkitCz29RYxTKCBaI?=
X-MS-Exchange-CrossTenant-Network-Message-Id: 8b487040-3982-4b9d-d41f-08db3bf566ad
X-MS-Exchange-CrossTenant-AuthSource: PH0PR11MB4839.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 13 Apr 2023 08:02:18.1225
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 46c98d88-e344-4ed4-8496-4ed7712e255d
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: LI3zgda1YJvvxSGrW9fUyNu/ocqibMkKbAdQbTMhCAJptcTtKsPwhTJWiN6Hqad/LeCeWh/9M8PBkB03ORWxYg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: PH8PR11MB6804
X-OriginatorOrg: intel.com
X-Spam-Status: No, score=-4.4 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH,
        DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_MED,
        SPF_HELO_NONE,SPF_NONE,URIBL_BLOCKED autolearn=ham autolearn_force=no
        version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

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 */