| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Tue, 21 Nov 2017 19:52:28 +0800
From: Fengguang Wu <fengguang.wu@...el.com>
To: netdev@...r.kernel.org
Cc: Phil Sutter <phil@....cc>, Thomas Graf <tgraf@...g.ch>,
Herbert Xu <herbert@...dor.apana.org.au>,
"David S. Miller" <davem@...emloft.net>,
Florian Westphal <fw@...len.de>, linux-kernel@...r.kernel.org,
Linus Torvalds <torvalds@...ux-foundation.org>, lkp@...org
Subject: [test_rht_init] INFO: task swapper/0:1 blocked for more than 120
seconds.
Here is a different call trace related to rhashtable.
It occurs in 17 out of 90 boots.
[ 342.666234] Writes: Total: 4 Max/Min: 0/0 Fail: 0
[ 381.918047] INFO: task swapper/0:1 blocked for more than 120 seconds.
[ 382.060710] Not tainted 4.14.0-03453-ge37e0ee #20
[ 382.087844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 382.165167] swapper/0 D 0 1 0 0x80000000
[ 382.238700] Call Trace:
[ 382.275049] ? __schedule+0x81a/0x84b:
context_switch at kernel/sched/core.c:2801
(inlined by) __schedule at kernel/sched/core.c:3374
[ 382.342821] ? 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)
[ 382.378572] ? schedule_timeout+0x1b/0xb9:
schedule_timeout at kernel/time/timer.c:1766
[ 382.435137] ? preempt_schedule_common+0x3c/0x48:
preempt_schedule_common at kernel/sched/core.c:3521 (discriminator 1)
[ 382.504484] ? ___preempt_schedule+0x8/0xc:
___preempt_schedule at arch/x86/entry/thunk_32.S:38
[ 382.561458] ? _raw_spin_unlock_irq+0x63/0x6a:
_raw_spin_unlock_irq at kernel/locking/spinlock.c:200
[ 382.611614] ? __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
[ 382.661392] ? console_conditional_schedule+0x3c/0x3c:
schedule_timeout at kernel/time/timer.c:1751
[ 382.724874] ? do_task_dead+0x46/0x46:
default_wake_function at kernel/sched/core.c:3626
[ 382.774886] ? wait_for_completion+0x19/0x1c:
wait_for_completion at kernel/sched/completion.c:145
[ 382.821445] ? kthread_stop+0x196/0x326:
kthread_stop at kernel/kthread.c:531
[ 382.868216] ? test_rht_init+0x79a/0x805:
test_rht_init at lib/test_rhashtable.c:422
[ 382.935157] ? ___siphash_aligned+0x10/0x10
[ 382.994854] ? ___siphash_aligned+0x10/0x10
[ 383.078167] ? list_sort_test+0x27f/0x27f:
test_rht_init at lib/test_rhashtable.c:340
[ 383.134797] ? do_one_initcall+0x96/0x19b:
do_one_initcall at init/main.c:828
[ 383.178838] ? parse_args+0x19d/0x250:
parse_one at kernel/params.c:156
(inlined by) parse_args at kernel/params.c:191
[ 383.241532] ? kernel_init_freeable+0xd2/0x1b8:
do_initcall_level at init/main.c:887
(inlined by) do_initcalls at init/main.c:902
(inlined by) do_basic_setup at init/main.c:920
(inlined by) kernel_init_freeable at init/main.c:1068
[ 383.298429] ? kernel_init_freeable+0xee/0x1b8:
do_initcall_level at init/main.c:893
(inlined by) do_initcalls at init/main.c:902
(inlined by) do_basic_setup at init/main.c:920
(inlined by) kernel_init_freeable at init/main.c:1068
[ 383.344714] ? rest_init+0xb3/0xb3:
kernel_init at init/main.c:992
[ 383.398150] ? kernel_init+0xd/0x15f:
kernel_init at init/main.c:997
[ 383.448403] ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[ 383.484740]
[ 383.484740] Showing all locks held in the system:
[ 383.555130] 2 locks held by khungtaskd/24:
[ 383.562185] #0: (rcu_read_lock){....}, at: [<7911d8f1>] 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
[ 383.575830] #1: (tasklist_lock){.+.+}, at: [<790bb026>] debug_show_all_locks+0x3a/0x13d:
debug_show_all_locks at kernel/locking/lockdep.c:4557
[ 383.591347]
[ 383.594725] =============================================
[ 383.594725]
[ 383.908638] NMI backtrace for cpu 0
[ 383.915181] CPU: 0 PID: 24 Comm: khungtaskd Not tainted 4.14.0-03453-ge37e0ee #20
[ 383.917710] Call Trace:
[ 383.917710] ? show_stack+0x5e/0x66:
show_stack at arch/x86/kernel/dumpstack.c:179
[ 383.917710] ? dump_stack+0xc1/0x121:
__dump_stack at lib/dump_stack.c:17
(inlined by) dump_stack at lib/dump_stack.c:53
[ 383.917710] ? nmi_cpu_backtrace+0xf7/0x110:
nmi_cpu_backtrace at lib/nmi_backtrace.c:106
[ 383.917710] ? 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
[ 383.917710] ? lapic_can_unplug_cpu+0xb5/0xb5:
nmi_raise_cpu_backtrace at arch/x86/kernel/apic/hw_nmi.c:32
[ 383.917710] ? 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
[ 383.917710] ? kthread+0x154/0x159:
kthread at kernel/kthread.c:238
[ 383.917710] ? rcu_read_lock+0x6c/0x6c:
rootfs_mount at init/do_mounts.c:610
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:126
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
[ 383.917710] ? queuing_blocked+0x68/0x68:
kthread at kernel/kthread.c:198
[ 383.917710] ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[ 383.989633] Sending NMI from CPU 0 to CPUs 1:
[ 383.996684] NMI backtrace for cpu 1
[ 383.996717] CPU: 1 PID: 131 Comm: rhashtable_thra Not tainted 4.14.0-03453-ge37e0ee #20
[ 383.996779] task: 88c5a500 task.stack: 89560000
[ 383.996813] EIP: ftrace_likely_update+0x0/0x55:
ftrace_likely_update at kernel/trace/trace_branch.c:207
[ 383.996833] EFLAGS: 00200046 CPU: 1
[ 383.996833] EAX: 79da67d0 EBX: 00000000 ECX: 00000001 EDX: 00000000
[ 383.996833] ESI: 00000000 EDI: 10cf1913 EBP: 89561d5c ESP: 89561d48
[ 383.996833] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 383.996833] CR0: 80050033 CR2: ffffffff CR3: 02221000 CR4: 00000690
[ 383.996833] Call Trace:
[ 383.996833] ? is_ftrace_trampoline+0x74/0x116:
is_ftrace_trampoline at kernel/trace/ftrace.c:1203
[ 383.996833] ? kernel_text_address+0x5a/0x9c:
kernel_text_address at kernel/extable.c:148
[ 383.996833] ? __kernel_text_address+0x10/0x54:
__kernel_text_address at kernel/extable.c:107
[ 383.996833] ? unwind_next_frame+0x36/0x83:
unwind_next_frame at arch/x86/kernel/unwind_guess.c:38 (discriminator 2)
[ 383.996833] ? __save_stack_trace+0x104/0x123:
__save_stack_trace at arch/x86/kernel/stacktrace.c:43 (discriminator 1)
[ 383.996833] ? save_stack_trace+0x1b/0x1e:
save_stack_trace at arch/x86/kernel/stacktrace.c:61
[ 383.996833] ? __lock_acquire+0xaef/0xc9f:
add_xhlock at kernel/locking/lockdep.c:4882
(inlined by) check_add_xhlock at kernel/locking/lockdep.c:4909
(inlined by) lock_acquire_crosslock at kernel/locking/lockdep.c:4981
(inlined by) __lock_acquire at kernel/locking/lockdep.c:3506
[ 383.996833] ? __lock_acquire+0x453/0xc9f:
__lock_acquire at kernel/locking/lockdep.c:3500
[ 383.996833] ? rhashtable_insert_slow+0x18a/0x3d8:
rhashtable_try_insert at lib/rhashtable.c:652
(inlined by) rhashtable_insert_slow at lib/rhashtable.c:676
[ 383.996833] ? lock_acquire+0x13d/0x17b:
get_current at arch/x86/include/asm/current.h:17
(inlined by) lock_acquire at kernel/locking/lockdep.c:4009
[ 383.996833] ? rhashtable_insert_slow+0x18a/0x3d8:
rhashtable_try_insert at lib/rhashtable.c:652
(inlined by) rhashtable_insert_slow at lib/rhashtable.c:676
[ 383.996833] ? _raw_spin_lock_nested+0x28/0x6d:
_raw_spin_lock_nested at kernel/locking/spinlock.c:364
[ 383.996833] ? rhashtable_insert_slow+0x18a/0x3d8:
rhashtable_try_insert at lib/rhashtable.c:652
(inlined by) rhashtable_insert_slow at lib/rhashtable.c:676
[ 383.996833] ? ___siphash_aligned+0x10/0x10
[ 383.996833] ? insert_retry+0x17a/0x497
[ 383.996833] ? trace_hardirqs_on_thunk+0xc/0x10:
trace_hardirqs_on_thunk at arch/x86/entry/thunk_32.S:33
[ 383.996833] ? ___siphash_aligned+0x10/0x10
[ 383.996833] ? threadfunc+0x85/0x277:
threadfunc at lib/test_rhashtable.c:290
[ 383.996833] ? ___siphash_aligned+0x10/0x10
[ 383.996833] ? _raw_spin_unlock_irqrestore+0x58/0x9c:
__raw_spin_unlock_irqrestore at include/linux/spinlock_api_smp.h:167
(inlined by) _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
[ 383.996833] ? schedule+0x78/0x84:
schedule at kernel/sched/core.c:3435 (discriminator 1)
[ 383.996833] ? kthread+0x154/0x159:
kthread at kernel/kthread.c:238
[ 383.996833] ? __rhashtable_remove_fast+0x318/0x318
[ 383.996833] ? queuing_blocked+0x68/0x68:
kthread at kernel/kthread.c:198
[ 383.996833] ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[ 383.996833] Code: ff ff ff ff 73 10 ff 73 0c 89 c7 68 5f a1 c0 79 56 e8 e8 d0 0d 00 89 f0 89 f9 89 da e8 a4 fe ff ff 8d 65 f4 31 c0 5b 5e 5f 5d c3 <55> 89 e5 57 56 8b 75 08 53 31 db 85 f6 0f 95 c3 89 df 8b 1c 9d
[ 383.996833] INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.417 msecs
[ 384.687929] Kernel panic - not syncing: hung_task: blocked tasks
[ 384.690456] CPU: 0 PID: 24 Comm: khungtaskd Not tainted 4.14.0-03453-ge37e0ee #20
[ 384.690456] Call Trace:
[ 384.690456] ? show_stack+0x5e/0x66:
show_stack at arch/x86/kernel/dumpstack.c:179
[ 384.690456] ? dump_stack+0xc1/0x121:
__dump_stack at lib/dump_stack.c:17
(inlined by) dump_stack at lib/dump_stack.c:53
[ 384.690456] ? panic+0xec/0x2b6:
panic at kernel/panic.c:192
[ 384.690456] ? 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
[ 384.690456] ? kthread+0x154/0x159:
kthread at kernel/kthread.c:238
[ 384.690456] ? rcu_read_lock+0x6c/0x6c:
rootfs_mount at init/do_mounts.c:610
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:126
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
[ 384.690456] ? queuing_blocked+0x68/0x68:
kthread at kernel/kthread.c:198
[ 384.690456] ? ret_from_fork+0x19/0x24:
ret_from_fork at arch/x86/entry/entry_32.S:299
[ 384.690456] Kernel Offset: disabled
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
View attachment "dmesg-vm-lkp-wsx03-yocto-i386-7:20171117093643:i386-randconfig-i0-201746:4.14.0-03453-ge37e0ee:20" of type "text/plain" (40732 bytes)
View attachment ".config" of type "text/plain" (91391 bytes)
View attachment "job-script" of type "text/plain" (3821 bytes)
View attachment "reproduce-vm-lkp-wsx03-yocto-i386-7:20171117093643:i386-randconfig-i0-201746:4.14.0-03453-ge37e0ee:20" of type "text/plain" (2134 bytes)
Powered by blists - more mailing lists