| 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
| ||
|
Message-ID: <20171121110736.xcljt5qcdwjzqbhp@wfg-t540p.sh.intel.com>
Date: Tue, 21 Nov 2017 19:07:36 +0800
From: Fengguang Wu <fengguang.wu@...el.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: Ingo Molnar <mingo@...hat.com>,
Linus Torvalds <torvalds@...ux-foundation.org>,
Joel Fernandes <joelaf@...gle.com>,
Jeremy Linton <jeremy.linton@....com>,
Thomas Gleixner <tglx@...utronix.de>,
Chunyan Zhang <zhang.chunyan@...aro.org>,
Michael Sartain <mikesart@...tmail.com>,
linux-kernel@...r.kernel.org, lkp@...org
Subject: [tracer_init_tracefs] watchdog: BUG: soft lockup - CPU#0 stuck for
23s! [swapper/0:1]
Hello,
FYI this happens in mainline kernel 4.14.0-03308-g670ffcc.
It looks like a new regression after 4.14.
It occurs in 33 out of 60 boots.
[ 26.085387] PCI: Using ACPI for IRQ routing
[ 26.096000] PCI: pci_cache_line_size set to 64 bytes
[ 26.114548] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 26.130464] e820: reserve RAM buffer [mem 0x7ffdc000-0x7fffffff]
[ 26.328772] clocksource: Switched to clocksource kvm-clock
[ 52.797085] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
[ 52.797085] Modules linked in:
[ 52.797085] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.0-03308-g670ffcc #1
[ 52.797085] task: ffff88005ec38000 task.stack: ffff88005ec40000
[ 52.797085] RIP: 0010:update_event_printk+0x286/0x700
[ 52.797085] RSP: 0000:ffff88005ec47d00 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff11
[ 52.797085] RAX: dffffc0000000000 RBX: ffffffff97858b9f RCX: ffffffff94d62d81
[ 52.797085] RDX: 1ffffffff2d3f331 RSI: 0000000000000008 RDI: ffffffff969f9988
[ 52.797085] RBP: 0000000000000002 R08: fffffbfff313545e R09: 226c616d726f4e22
[ 52.797085] R10: 0000000000000000 R11: fffffbfff313545d R12: 0000000000000000
[ 52.797085] R13: ffffffff9939a0f0 R14: 0000000000000000 R15: 0000000000000011
[ 52.797085] FS: 0000000000000000(0000) GS:ffff88005f800000(0000) knlGS:0000000000000000
[ 52.797085] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 52.797085] CR2: 0000000000000000 CR3: 0000000021413001 CR4: 00000000000206f0
[ 52.797085] Call Trace:
[ 52.797085] trace_event_eval_update+0x1fa/0x248:
trace_event_eval_update at kernel/trace/trace_events.c:2227 (discriminator 2)
[ 52.797085] trace_insert_eval_map+0x51/0x5d
[ 52.797085] tracer_init_tracefs+0x24b/0x3cb:
tracer_init_tracefs at kernel/trace/trace.c:8064
[ 52.797085] ? tracer_alloc_buffers+0x9bf/0x9bf:
tracer_init_tracefs at kernel/trace/trace.c:8032
[ 52.797085] do_one_initcall+0x18a/0x386:
do_one_initcall at init/main.c:828
[ 52.797085] ? initcall_blacklisted+0x1c0/0x1c0:
do_one_initcall at init/main.c:817
[ 52.797085] ? print_unlock_imbalance_bug+0x169/0x169:
lock_release at kernel/locking/lockdep.c:4016
[ 52.797085] kernel_init_freeable+0x2f3/0x4f2:
do_initcall_level at init/main.c:894
(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
[ 52.797085] ? rest_init+0x1d4/0x1d4:
kernel_init at init/main.c:992
[ 52.797085] kernel_init+0x13/0x2d0:
kernel_init at init/main.c:995
[ 52.797085] ? rest_init+0x1d4/0x1d4:
kernel_init at init/main.c:992
[ 52.797085] ret_from_fork+0x1f/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
[ 52.797085] Code: 41 bc 01 00 00 00 eb 17 48 ff 05 87 ec 1f 05 40 80 fd 5f 74 eb 48 ff 05 82 ec 1f 05 45 31 e4 49 63 ec be 08 00 00 00 48 83 c5 02 <48> 8d 3c ed 88 a2 9a 98 e8 b9 55 17 00 48 ff 04 ed 88 a2 9a 98
[ 53.138843] Kernel panic - not syncing: softlockup: hung tasks
[ 53.138843] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G L 4.14.0-03308-g670ffcc #1
[ 53.138843] Call Trace:
[ 53.138843] <IRQ>
[ 53.138843] dump_stack+0x11a/0x178:
dump_stack at lib/dump_stack.c:55
[ 53.138843] panic+0x23c/0x59d:
panic at kernel/panic.c:192
[ 53.138843] ? refcount_error_report+0x22f/0x22f:
panic at kernel/panic.c:133
[ 53.138843] ? kasan_check_write+0x1e/0x26:
kasan_check_write at mm/kasan/kasan.c:278
[ 53.138843] ? watchdog_timer_fn+0x589/0x5d3:
watchdog_timer_fn at kernel/watchdog.c:442
[ 53.138843] watchdog_timer_fn+0x5b4/0x5d3:
watchdog_timer_fn at kernel/watchdog.c:444
[ 53.138843] ? watchdog+0x29/0x29:
watchdog_timer_fn at kernel/watchdog.c:340
[ 53.138843] __run_hrtimer+0x747/0xbb4:
__run_hrtimer at kernel/time/hrtimer.c:1211 (discriminator 9)
[ 53.138843] hrtimer_run_queues+0x203/0x264:
__hrtimer_run_queues at kernel/time/hrtimer.c:1275
(inlined by) hrtimer_run_queues at kernel/time/hrtimer.c:1414
[ 53.138843] ? hrtimer_get_next_event+0x193/0x193:
hrtimer_run_queues at kernel/time/hrtimer.c:1393
[ 53.138843] ? __asan_loadN+0x19/0x21
[ 53.138843] ? ftrace_likely_update+0x99/0xc3:
ftrace_likely_update at kernel/trace/trace_branch.c:223
[ 53.138843] run_local_timers+0x31/0x147:
run_local_timers at kernel/time/timer.c:1694
[ 53.138843] update_process_times+0x31/0xaf:
update_process_times at kernel/time/timer.c:1624
[ 53.138843] tick_nohz_handler+0x245/0x308:
tick_sched_handle at kernel/time/tick-sched.c:163
(inlined by) tick_nohz_handler at kernel/time/tick-sched.c:1065
[ 53.138843] ? tick_do_update_jiffies64+0x30b/0x30b:
tick_nohz_handler at kernel/time/tick-sched.c:1057
[ 53.138843] smp_apic_timer_interrupt+0x3ca/0x6ca:
local_apic_timer_interrupt at arch/x86/kernel/apic/apic.c:1025
(inlined by) smp_apic_timer_interrupt at arch/x86/kernel/apic/apic.c:1050
[ 53.138843] apic_timer_interrupt+0xac/0xc0:
apic_timer_interrupt at arch/x86/entry/entry_64.S:791
[ 53.138843] </IRQ>
[ 53.138843] RIP: 0010:update_event_printk+0x286/0x700
[ 53.138843] RSP: 0000:ffff88005ec47d00 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff11
[ 53.138843] RAX: dffffc0000000000 RBX: ffffffff97858b9f RCX: ffffffff94d62d81
[ 53.138843] RDX: 1ffffffff2d3f331 RSI: 0000000000000008 RDI: ffffffff969f9988
[ 53.138843] RBP: 0000000000000002 R08: fffffbfff313545e R09: 226c616d726f4e22
[ 53.138843] R10: 0000000000000000 R11: fffffbfff313545d R12: 0000000000000000
[ 53.138843] R13: ffffffff9939a0f0 R14: 0000000000000000 R15: 0000000000000011
[ 53.138843] ? update_event_printk+0x23a/0x700
[ 53.138843] trace_event_eval_update+0x1fa/0x248:
trace_event_eval_update at kernel/trace/trace_events.c:2227 (discriminator 2)
[ 53.138843] trace_insert_eval_map+0x51/0x5d
[ 53.138843] tracer_init_tracefs+0x24b/0x3cb:
tracer_init_tracefs at kernel/trace/trace.c:8064
[ 53.138843] ? tracer_alloc_buffers+0x9bf/0x9bf:
tracer_init_tracefs at kernel/trace/trace.c:8032
[ 53.138843] do_one_initcall+0x18a/0x386:
do_one_initcall at init/main.c:828
[ 53.138843] ? initcall_blacklisted+0x1c0/0x1c0:
do_one_initcall at init/main.c:817
[ 53.138843] ? print_unlock_imbalance_bug+0x169/0x169:
lock_release at kernel/locking/lockdep.c:4016
[ 53.138843] kernel_init_freeable+0x2f3/0x4f2:
do_initcall_level at init/main.c:894
(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
[ 53.138843] ? rest_init+0x1d4/0x1d4:
kernel_init at init/main.c:992
[ 53.138843] kernel_init+0x13/0x2d0:
kernel_init at init/main.c:995
[ 53.138843] ? rest_init+0x1d4/0x1d4:
kernel_init at init/main.c:992
[ 53.138843] ret_from_fork+0x1f/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
View attachment "dmesg-vm-lkp-wsx03-2G-17:20171115100944:x86_64-randconfig-g0-10270533:4.14.0-03308-g670ffcc:1" of type "text/plain" (28101 bytes)
View attachment ".config" of type "text/plain" (127649 bytes)
View attachment "job-script" of type "text/plain" (4351 bytes)
View attachment "reproduce-vm-lkp-wsx03-2G-17:20171115100944:x86_64-randconfig-g0-10270533:4.14.0-03308-g670ffcc:1" of type "text/plain" (2263 bytes)
Powered by blists - more mailing lists