We encountered a system hang issue while doing the tests. The callstack
is as following
schedule+0x80/0x100
schedule_timeout+0x48/0x138
wait_for_common+0xa4/0x134
wait_for_completion+0x1c/0x2c
kthread_flush_work+0x114/0x1cc
kthread_cancel_work_sync.llvm.16514401384283632983+0xe8/0x144
kthread_cancel_delayed_work_sync+0x18/0x2c
xxxx_pm_notify+0xb0/0xd8
blocking_notifier_call_chain_robust+0x80/0x194
pm_notifier_call_chain_robust+0x28/0x4c
suspend_prepare+0x40/0x260
enter_state+0x80/0x3f4
pm_suspend+0x60/0xdc
state_store+0x108/0x144
kobj_attr_store+0x38/0x88
sysfs_kf_write+0x64/0xc0
kernfs_fop_write_iter+0x108/0x1d0
vfs_write+0x2f4/0x368
ksys_write+0x7c/0xec
When we started investigating, we found race between
kthread_mod_delayed_work vs kthread_cancel_delayed_work_sync. The race's
result could be simply reproduced as a kthread_mod_delayed_work with
a following kthread_flush_work call.
Thing is we release kthread_mod_delayed_work kspin_lock in
__kthread_cancel_work so it opens a race window for
kthread_cancel_delayed_work_sync to change the canceling count used to
prevent dwork from being requeued before calling kthread_flush_work.
However, we don't check the canceling count after returning from
__kthread_cancel_work and then insert the dwork to the worker. It
results the following kthread_flush_work inserts flush work to dwork's
tail which is at worker's dealyed_work_list. Therefore, flush work will
never get moved to the worker's work_list to be executed. Finally,
kthread_cancel_delayed_work_sync will NOT be able to get completed and
wait forever. The code sequence diagram is as following
Thread A Thread B
kthread_mod_delayed_work
spin_lock
__kthread_cancel_work
canceling = 1
spin_unlock
kthread_cancel_delayed_work_sync
spin_lock
kthread_cancel_work
canceling = 2
spin_unlock
del_timer_sync
spin_lock
canceling = 1 // canceling count gets update in ThreadB before
queue_delayed_work // dwork is put into the woker’s dealyed_work_list
without checking the canceling count
spin_unlock
kthread_flush_work
spin_lock
Insert flush work // at the tail of the
dwork which is at
the worker’s
dealyed_work_list
spin_unlock
wait_for_completion // Thread B stuck here as
flush work will never
get executed
The canceling count could change in __kthread_cancel_work as the spinlock
get released and regained in between, let's check the count again before
we queue the delayed work to avoid the race.
Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
Tested-by: David Chao <[email protected]>
Signed-off-by: Martin Liu <[email protected]>
---
kernel/kthread.c | 13 +++++++++++++
1 file changed, 13 insertions(+)
diff --git a/kernel/kthread.c b/kernel/kthread.c
index fe3f2a40d61e..064eae335c1f 100644
--- a/kernel/kthread.c
+++ b/kernel/kthread.c
@@ -1181,6 +1181,19 @@ bool kthread_mod_delayed_work(struct kthread_worker *worker,
goto out;
ret = __kthread_cancel_work(work, true, &flags);
+
+ /*
+ * Canceling could run in parallel from kthread_cancel_delayed_work_sync
+ * and change work's canceling count as the spinlock is released and regain
+ * in __kthread_cancel_work so we need to check the count again. Otherwise,
+ * we might incorrectly queue the dwork and further cause
+ * cancel_delayed_work_sync thread waiting for flush dwork endlessly.
+ */
+ if (work->canceling) {
+ ret = false;
+ goto out;
+ }
+
fast_queue:
__kthread_queue_delayed_work(worker, dwork, delay);
out:
--
2.31.1.607.g51e8a6a459-goog
Hi Folks,
Could I get some help for reviewing this patch? Thank you.
On Thu, May 13, 2021 at 02:54:57PM +0800, Martin Liu wrote:
> We encountered a system hang issue while doing the tests. The callstack
> is as following
>
> schedule+0x80/0x100
> schedule_timeout+0x48/0x138
> wait_for_common+0xa4/0x134
> wait_for_completion+0x1c/0x2c
> kthread_flush_work+0x114/0x1cc
> kthread_cancel_work_sync.llvm.16514401384283632983+0xe8/0x144
> kthread_cancel_delayed_work_sync+0x18/0x2c
> xxxx_pm_notify+0xb0/0xd8
> blocking_notifier_call_chain_robust+0x80/0x194
> pm_notifier_call_chain_robust+0x28/0x4c
> suspend_prepare+0x40/0x260
> enter_state+0x80/0x3f4
> pm_suspend+0x60/0xdc
> state_store+0x108/0x144
> kobj_attr_store+0x38/0x88
> sysfs_kf_write+0x64/0xc0
> kernfs_fop_write_iter+0x108/0x1d0
> vfs_write+0x2f4/0x368
> ksys_write+0x7c/0xec
>
> When we started investigating, we found race between
> kthread_mod_delayed_work vs kthread_cancel_delayed_work_sync. The race's
> result could be simply reproduced as a kthread_mod_delayed_work with
> a following kthread_flush_work call.
>
> Thing is we release kthread_mod_delayed_work kspin_lock in
> __kthread_cancel_work so it opens a race window for
> kthread_cancel_delayed_work_sync to change the canceling count used to
> prevent dwork from being requeued before calling kthread_flush_work.
> However, we don't check the canceling count after returning from
> __kthread_cancel_work and then insert the dwork to the worker. It
> results the following kthread_flush_work inserts flush work to dwork's
> tail which is at worker's dealyed_work_list. Therefore, flush work will
> never get moved to the worker's work_list to be executed. Finally,
> kthread_cancel_delayed_work_sync will NOT be able to get completed and
> wait forever. The code sequence diagram is as following
>
> Thread A Thread B
> kthread_mod_delayed_work
> spin_lock
> __kthread_cancel_work
> canceling = 1
> spin_unlock
> kthread_cancel_delayed_work_sync
> spin_lock
> kthread_cancel_work
> canceling = 2
> spin_unlock
> del_timer_sync
> spin_lock
> canceling = 1 // canceling count gets update in ThreadB before
> queue_delayed_work // dwork is put into the woker’s dealyed_work_list
> without checking the canceling count
> spin_unlock
> kthread_flush_work
> spin_lock
> Insert flush work // at the tail of the
> dwork which is at
> the worker’s
> dealyed_work_list
> spin_unlock
> wait_for_completion // Thread B stuck here as
> flush work will never
> get executed
>
> The canceling count could change in __kthread_cancel_work as the spinlock
> get released and regained in between, let's check the count again before
> we queue the delayed work to avoid the race.
>
> Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
> Tested-by: David Chao <[email protected]>
> Signed-off-by: Martin Liu <[email protected]>
> ---
> kernel/kthread.c | 13 +++++++++++++
> 1 file changed, 13 insertions(+)
>
> diff --git a/kernel/kthread.c b/kernel/kthread.c
> index fe3f2a40d61e..064eae335c1f 100644
> --- a/kernel/kthread.c
> +++ b/kernel/kthread.c
> @@ -1181,6 +1181,19 @@ bool kthread_mod_delayed_work(struct kthread_worker *worker,
> goto out;
>
> ret = __kthread_cancel_work(work, true, &flags);
> +
> + /*
> + * Canceling could run in parallel from kthread_cancel_delayed_work_sync
> + * and change work's canceling count as the spinlock is released and regain
> + * in __kthread_cancel_work so we need to check the count again. Otherwise,
> + * we might incorrectly queue the dwork and further cause
> + * cancel_delayed_work_sync thread waiting for flush dwork endlessly.
> + */
> + if (work->canceling) {
> + ret = false;
> + goto out;
> + }
> +
> fast_queue:
> __kthread_queue_delayed_work(worker, dwork, delay);
> out:
> --
> 2.31.1.607.g51e8a6a459-goog
>
On Thu 2021-05-13 14:54:57, Martin Liu wrote:
> We encountered a system hang issue while doing the tests. The callstack
> is as following
>
> schedule+0x80/0x100
> schedule_timeout+0x48/0x138
> wait_for_common+0xa4/0x134
> wait_for_completion+0x1c/0x2c
> kthread_flush_work+0x114/0x1cc
> kthread_cancel_work_sync.llvm.16514401384283632983+0xe8/0x144
> kthread_cancel_delayed_work_sync+0x18/0x2c
> xxxx_pm_notify+0xb0/0xd8
> blocking_notifier_call_chain_robust+0x80/0x194
> pm_notifier_call_chain_robust+0x28/0x4c
> suspend_prepare+0x40/0x260
> enter_state+0x80/0x3f4
> pm_suspend+0x60/0xdc
> state_store+0x108/0x144
> kobj_attr_store+0x38/0x88
> sysfs_kf_write+0x64/0xc0
> kernfs_fop_write_iter+0x108/0x1d0
> vfs_write+0x2f4/0x368
> ksys_write+0x7c/0xec
>
> When we started investigating, we found race between
> kthread_mod_delayed_work vs kthread_cancel_delayed_work_sync. The race's
> result could be simply reproduced as a kthread_mod_delayed_work with
> a following kthread_flush_work call.
>
> Thing is we release kthread_mod_delayed_work kspin_lock in
> __kthread_cancel_work so it opens a race window for
> kthread_cancel_delayed_work_sync to change the canceling count used to
> prevent dwork from being requeued before calling kthread_flush_work.
> However, we don't check the canceling count after returning from
> __kthread_cancel_work and then insert the dwork to the worker. It
> results the following kthread_flush_work inserts flush work to dwork's
> tail which is at worker's dealyed_work_list. Therefore, flush work will
> never get moved to the worker's work_list to be executed. Finally,
> kthread_cancel_delayed_work_sync will NOT be able to get completed and
> wait forever. The code sequence diagram is as following
>
> Thread A Thread B
> kthread_mod_delayed_work
> spin_lock
> __kthread_cancel_work
> canceling = 1
> spin_unlock
> kthread_cancel_delayed_work_sync
> spin_lock
> kthread_cancel_work
> canceling = 2
> spin_unlock
> del_timer_sync
> spin_lock
> canceling = 1 // canceling count gets update in ThreadB before
> queue_delayed_work // dwork is put into the woker’s dealyed_work_list
> without checking the canceling count
> spin_unlock
> kthread_flush_work
> spin_lock
> Insert flush work // at the tail of the
> dwork which is at
> the worker’s
> dealyed_work_list
> spin_unlock
> wait_for_completion // Thread B stuck here as
> flush work will never
> get executed
>
> The canceling count could change in __kthread_cancel_work as the spinlock
> get released and regained in between, let's check the count again before
> we queue the delayed work to avoid the race.
>
> Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
> Tested-by: David Chao <[email protected]>
> Signed-off-by: Martin Liu <[email protected]>
Great catch! The patch makes perfect sense.
Reviewed-by: Petr Mladek <[email protected]>
Andrew, could you please queue it via -mm tree?
Best Regards,
Petr
PS: I am sorry for the late review. I was somehow busy last week
it it has fallen too low in the mailbox :-(
On Thu 2021-05-13 14:54:57, Martin Liu wrote:
> We encountered a system hang issue while doing the tests. The callstack
> is as following
>
> schedule+0x80/0x100
> schedule_timeout+0x48/0x138
> wait_for_common+0xa4/0x134
> wait_for_completion+0x1c/0x2c
> kthread_flush_work+0x114/0x1cc
> kthread_cancel_work_sync.llvm.16514401384283632983+0xe8/0x144
> kthread_cancel_delayed_work_sync+0x18/0x2c
> xxxx_pm_notify+0xb0/0xd8
> blocking_notifier_call_chain_robust+0x80/0x194
> pm_notifier_call_chain_robust+0x28/0x4c
> suspend_prepare+0x40/0x260
> enter_state+0x80/0x3f4
> pm_suspend+0x60/0xdc
> state_store+0x108/0x144
> kobj_attr_store+0x38/0x88
> sysfs_kf_write+0x64/0xc0
> kernfs_fop_write_iter+0x108/0x1d0
> vfs_write+0x2f4/0x368
> ksys_write+0x7c/0xec
>
> When we started investigating, we found race between
> kthread_mod_delayed_work vs kthread_cancel_delayed_work_sync. The race's
> result could be simply reproduced as a kthread_mod_delayed_work with
> a following kthread_flush_work call.
One more thing.
This scenario might mean that the kthread_worker API is used a wrong way.
kthread_cancel_delayed_work_sync() is typically called when the work
should never run any longer. But the parallel
kthread_mod_delayed_work() might queue it right after
kthread_cancel_delayed_work_sync() succeded. As a result that work
might get procced even when it was cancelled.
The API caller should prevent this race. It should have its own logic
around kthread_worker_queue*() and kthread_worker_mod_delayed_work()
calls that will prevent calling these when the work should
stay cancelled. For example, see
if (clamping && w_data->clamping && cpu_online(w_data->cpu))
kthread_queue_delayed_work(w_data->worker,
&w_data->idle_injection_work,
sleeptime);
in clamp_idle_injection_func().
Best Regards,
Petr
On Thu, 13 May 2021 14:54:57 +0800 Martin Liu <[email protected]> wrote:
> We encountered a system hang issue while doing the tests. The callstack
> is as following
>
> ...
>
> Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
Thanks. I added a cc:stable to this and shall hold it in -mm for a
couple of weeks to get exposure and testing before sending it to Linus
for 5.13.
On Thu 2021-05-20 14:48:45, Andrew Morton wrote:
> On Thu, 13 May 2021 14:54:57 +0800 Martin Liu <[email protected]> wrote:
>
> > We encountered a system hang issue while doing the tests. The callstack
> > is as following
> >
> > ...
> >
> > Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
>
> Thanks. I added a cc:stable to this and shall hold it in -mm for a
> couple of weeks to get exposure and testing before sending it to Linus
> for 5.13.
Sounds good to me. Thanks for taking care of it.
Best Regards,
Petr
On Fri, May 21, 2021 at 09:12:30AM +0200, Petr Mladek wrote:
> On Thu 2021-05-20 14:48:45, Andrew Morton wrote:
> > On Thu, 13 May 2021 14:54:57 +0800 Martin Liu <[email protected]> wrote:
> >
> > > We encountered a system hang issue while doing the tests. The callstack
> > > is as following
> > >
> > > ...
> > >
> > > Fixes: 37be45d49dec2 ("kthread: allow to cancel kthread work")
> >
> > Thanks. I added a cc:stable to this and shall hold it in -mm for a
> > couple of weeks to get exposure and testing before sending it to Linus
> > for 5.13.
>
> Sounds good to me. Thanks for taking care of it.
>
> Best Regards,
> Petr
Hi Petr, Andrew
Thanks for your help! :)