Date:   Tue, 21 Nov 2017 19:19:07 +0800
From:   Fengguang Wu <fengguang.wu@...el.com>
To:     netdev@...r.kernel.org
Cc:     Thomas Graf <tgraf@...g.ch>,
        Herbert Xu <herbert@...dor.apana.org.au>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        "David S. Miller" <davem@...emloft.net>,
        Florian Westphal <fw@...len.de>, linux-kernel@...r.kernel.org,
        lkp@...org
Subject: [rht_deferred_worker] BUG: workqueue lockup - pool cpus=0 node=0
 flags=0x0 nice=0 stuck for 62s!

Hello,

FYI this happens in mainline kernel 4.14.0-10859-gcf9b077.
It at least dates back to v4.5 .

It occurs in 2 out of 2 boots.

[  204.036012] Average test time: 28300548370
[  204.045272] Testing concurrent rhashtable access from 10 threads
[  206.134970] Writes:  Total: 2  Max/Min: 0/0   Fail: 0
[  267.575158] Writes:  Total: 2  Max/Min: 0/0   Fail: 0
[  329.015853] Writes:  Total: 2  Max/Min: 0/0   Fail: 0
[  368.268565] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 62s!
[  368.294584] Showing busy workqueues and worker pools:
[  368.303142] workqueue events: flags=0x0
[  368.310492]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=4/256
[  368.312885]     in-flight: 3:rht_deferred_worker
[  368.312885]     pending: rht_deferred_worker, tsc_refine_calibration_work, vmstat_shepherd
[  368.342255] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=62s workers=2 idle: 16
[  368.356480] INFO: task swapper/0:1 blocked for more than 120 seconds.
[  368.451098]       Not tainted 4.14.0-10859-gcf9b077 #13
[  368.564524] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  368.726003] swapper/0       D    0     1      0 0x80000000
[  368.845359] Call Trace:
[  368.908714]  ? __schedule+0x81a/0x84b:
context_switch at kernel/sched/core.c:2801
  (inlined by) __schedule at kernel/sched/core.c:3374
[  368.984507]  ? schedule+0x59/0x84:
__preempt_count_sub at arch/x86/include/asm/preempt.h:107 (discriminator 1)
  (inlined by) schedule at kernel/sched/core.c:3434 (discriminator 1)
[  369.067920]  ? schedule_timeout+0x1b/0xb9:
schedule_timeout at kernel/time/timer.c:1766
[  369.155414]  ? _raw_spin_unlock_irq+0x28/0x6a:
__raw_spin_unlock_irq at include/linux/spinlock_api_smp.h:168
  (inlined by) _raw_spin_unlock_irq at kernel/locking/spinlock.c:199
[  369.241353]  ? _raw_spin_unlock_irq+0x4a/0x6a:
__raw_spin_unlock_irq at include/linux/spinlock_api_smp.h:182
  (inlined by) _raw_spin_unlock_irq at kernel/locking/spinlock.c:199
[  369.334592]  ? __wait_for_common+0x186/0x24a:
do_wait_for_common at kernel/sched/completion.c:91
  (inlined by) __wait_for_common at kernel/sched/completion.c:112
[  369.431098]  ? console_conditional_schedule+0x3c/0x3c:
schedule_timeout at kernel/time/timer.c:1751
[  369.557839]  ? do_task_dead+0x46/0x46:
default_wake_function at kernel/sched/core.c:3626
[  369.651937]  ? wait_for_completion+0x19/0x1c:
wait_for_completion at kernel/sched/completion.c:145
[  369.752007]  ? kthread_stop+0x196/0x326:
kthread_stop at kernel/kthread.c:531
[  369.847831]  ? test_rht_init+0x963/0x9da:
test_rht_init at lib/test_rhashtable.c:663
[  369.942078]  ? ___siphash_aligned+0x10/0x10
[  370.077915]  ? test_rhltable+0xd1e/0xd1e:
test_rht_init at lib/test_rhashtable.c:565
[  370.171118]  ? do_one_initcall+0x96/0x19b:
do_one_initcall at init/main.c:827
[  370.272905]  ? parse_args+0x19d/0x250:
parse_one at kernel/params.c:156
  (inlined by) parse_args at kernel/params.c:191
[  370.358882]  ? kernel_init_freeable+0xd2/0x1b8:
do_initcall_level at init/main.c:886
  (inlined by) do_initcalls at init/main.c:901
  (inlined by) do_basic_setup at init/main.c:919
  (inlined by) kernel_init_freeable at init/main.c:1067
[  370.465397]  ? kernel_init_freeable+0xee/0x1b8:
do_initcall_level at init/main.c:892
  (inlined by) do_initcalls at init/main.c:901
  (inlined by) do_basic_setup at init/main.c:919
  (inlined by) kernel_init_freeable at init/main.c:1067
[  370.571169]  ? rest_init+0xb3/0xb3:
kernel_init at init/main.c:991
[  370.658826]  ? kernel_init+0xd/0x15f:
kernel_init at init/main.c:996
[  370.746031]  ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[  370.839497]
[  370.839497] Showing all locks held in the system:
[  370.978033] 2 locks held by khungtaskd/17:
[  370.985872]  #0:  (rcu_read_lock){....}, at: [<7911eae2>] rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628

rcu_read_lock+0x0/0x6c:
rcu_read_lock at include/linux/rcupdate.h:628
[  370.999617]  #1:  (tasklist_lock){.+.+}, at: [<790bb514>] debug_show_all_locks+0x3a/0x13d:
debug_show_all_locks at kernel/locking/lockdep.c:4554
[  371.014651]
[  371.018049] =============================================
[  371.018049]
[  371.651885] NMI backtrace for cpu 0
[  371.668798] CPU: 0 PID: 17 Comm: khungtaskd Not tainted 4.14.0-10859-gcf9b077 #13
[  371.670706] Call Trace:
[  371.670706]  ? show_stack+0x5e/0x66:
show_stack at arch/x86/kernel/dumpstack.c:179
[  371.670706]  ? dump_stack+0xc1/0x121:
__dump_stack at lib/dump_stack.c:17
  (inlined by) dump_stack at lib/dump_stack.c:53
[  371.670706]  ? nmi_cpu_backtrace+0xf7/0x110:
nmi_cpu_backtrace at lib/nmi_backtrace.c:106
[  371.670706]  ? nmi_trigger_cpumask_backtrace+0xcf/0x1b2:
cpumask_empty at include/linux/cpumask.h:494
  (inlined by) nmi_trigger_cpumask_backtrace at lib/nmi_backtrace.c:67
[  371.670706]  ? lapic_can_unplug_cpu+0xb5/0xb5:
nmi_raise_cpu_backtrace at arch/x86/kernel/apic/hw_nmi.c:32
[  371.670706]  ? watchdog+0x524/0x593:
check_hung_task at kernel/hung_task.c:133
  (inlined by) check_hung_uninterruptible_tasks at kernel/hung_task.c:190
  (inlined by) watchdog at kernel/hung_task.c:249
[  371.670706]  ? kthread+0x154/0x159:
kthread at kernel/kthread.c:238
[  371.670706]  ? rcu_read_lock+0x6c/0x6c:
rootfs_mount at init/do_mounts.c:609

rcu_read_lock+0x6c/0x6c:
rcu_read_unlock at include/linux/rcupdate.h:682

rcu_read_lock+0x6c/0x6c:
ptrace_event_pid at include/linux/ptrace.h:172

rcu_read_lock+0x6c/0x6c:
write_seqlock at include/linux/seqlock.h:448

rcu_read_lock+0x6c/0x6c:
copy_overflow at include/linux/thread_info.h:125

rcu_read_lock+0x6c/0x6c:
__ptrace_may_access at kernel/ptrace.c:272

rcu_read_lock+0x6c/0x6c:
__sigqueue_alloc at kernel/signal.c:368
[  371.670706]  ? queuing_blocked+0x68/0x68:
kthread at kernel/kthread.c:198
[  371.670706]  ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[  372.922491] Kernel panic - not syncing: hung_task: blocked tasks
[  372.923689] CPU: 0 PID: 17 Comm: khungtaskd Not tainted 4.14.0-10859-gcf9b077 #13
[  372.923689] Call Trace:
[  372.923689]  ? show_stack+0x5e/0x66:
show_stack at arch/x86/kernel/dumpstack.c:179
[  372.923689]  ? dump_stack+0xc1/0x121:
__dump_stack at lib/dump_stack.c:17
  (inlined by) dump_stack at lib/dump_stack.c:53
[  372.923689]  ? panic+0xec/0x2b6:
panic at kernel/panic.c:192
[  372.923689]  ? watchdog+0x52e/0x593:
__read_once_size at include/linux/compiler.h:178
  (inlined by) check_hung_uninterruptible_tasks at kernel/hung_task.c:180
  (inlined by) watchdog at kernel/hung_task.c:249
[  372.923689]  ? kthread+0x154/0x159:
kthread at kernel/kthread.c:238
[  372.923689]  ? rcu_read_lock+0x6c/0x6c:
rootfs_mount at init/do_mounts.c:609

rcu_read_lock+0x6c/0x6c:
rcu_read_unlock at include/linux/rcupdate.h:682

rcu_read_lock+0x6c/0x6c:
ptrace_event_pid at include/linux/ptrace.h:172

rcu_read_lock+0x6c/0x6c:
write_seqlock at include/linux/seqlock.h:448

rcu_read_lock+0x6c/0x6c:
copy_overflow at include/linux/thread_info.h:125

rcu_read_lock+0x6c/0x6c:
__ptrace_may_access at kernel/ptrace.c:272

rcu_read_lock+0x6c/0x6c:
__sigqueue_alloc at kernel/signal.c:368
[  372.923689]  ? queuing_blocked+0x68/0x68:
kthread at kernel/kthread.c:198
[  372.923689]  ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[  372.923689] Kernel Offset: disabled

Attached the full dmesg, kconfig and reproduce scripts.

Thanks,
Fengguang

View attachment "dmesg-vm-lkp-wsx03-openwrt-i386-21:20171117091656:i386-randconfig-i0-201746:4.14.0-10859-gcf9b077:13" of type "text/plain" (38757 bytes)

View attachment ".config" of type "text/plain" (91660 bytes)

View attachment "job-script" of type "text/plain" (3732 bytes)

View attachment "reproduce-vm-lkp-wsx03-openwrt-i386-21:20171117091656:i386-randconfig-i0-201746:4.14.0-10859-gcf9b077:13" of type "text/plain" (2182 bytes)

Powered by blists - more mailing lists