Re: Regression in linux-next
From: Petri Latvala
Date: Mon Oct 16 2017 - 07:38:17 EST
On 10/16/2017 02:04 PM, Thomas Gleixner wrote:
Can you please pick up linux-next of today and merge the x86/apic branch
from the tip-tree into it:
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git x86/apic
Already merged to next-20171013.
Please enable tracing in the kernel configuration and enable the vector
tracepoints.
# for D in `ls -d /sys/kernel/debug/tracing/events/irq_vectors/vector_*`; do echo 1 > $D/enable; done
Also please do
# echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
That should dump the trace buffer when the bug hits. I try to reproduce
myself.
With those:
# rtcwake -s 15 -m mem
[ 67.069522] kernel BUG at arch/x86/kernel/apic/vector.c:154!
[ 67.075509] invalid opcode: 0000 [#1] PREEMPT SMP
[ 67.080481] Dumping ftrace buffer:
[ 67.084057] ---------------------------------
[ 67.088637] <idle>-0 0d.h4 67078714us : vector_update: irq=25
vector=35 cpu=1 prev_vector=37 prev_cpu=0
[ 67.099143] <idle>-0 0d.h4 67078715us : vector_alloc: irq=25
vector=35 reserved=1 ret=0
[ 67.108281] <idle>-0 0d.h4 67078715us : vector_config: irq=25
vector=35 cpu=1 apicdest=0x00000002
[ 67.118377] <idle>-0 0dNh4 67078735us : vector_update: irq=29
vector=36 cpu=1 prev_vector=42 prev_cpu=0
[ 67.128970] <idle>-0 0dNh4 67078735us : vector_alloc: irq=29
vector=36 reserved=1 ret=0
[ 67.138181] <idle>-0 0dNh4 67078736us : vector_config: irq=29
vector=36 cpu=1 apicdest=0x00000002
[ 67.148244] kworker/-143 0d.h1 67078754us : vector_free_moved:
irq=25 vector=37 is_managed=0
[ 67.157434] kworker/-2500 7d..1 67078997us : vector_deactivate:
irq=30 is_managed=0 can_reserve=1 early=0
[ 67.167751] kworker/-2500 7d..2 67078998us : vector_clear: irq=30
vector=43 cpu=0 prev_vector=0 prev_cpu=0
[ 67.178064] kworker/-2500 7d..2 67078999us : vector_reserve:
irq=30 ret=0
[ 67.185295] kworker/-2500 7d..2 67078999us : vector_config: irq=30
vector=239 cpu=0 apicdest=0x00000001
[ 67.195328] kworker/-2500 7d..1 67079012us : vector_teardown:
irq=30 is_managed=0 has_reserved=1
[ 67.204801] kworker/-2498 4d..1 67079097us : vector_deactivate:
irq=28 is_managed=0 can_reserve=1 early=0
[ 67.215047] kworker/-2498 4d..2 67079097us : vector_clear: irq=28
vector=41 cpu=0 prev_vector=0 prev_cpu=0
[ 67.225477] kworker/-2498 4d..2 67079097us : vector_reserve:
irq=28 ret=0
[ 67.232939] kworker/-2498 4d..2 67079098us : vector_config: irq=28
vector=239 cpu=0 apicdest=0x00000001
[ 67.243044] kworker/-2498 4d..1 67079118us : vector_teardown:
irq=28 is_managed=0 has_reserved=1
[ 67.252589] <idle>-0 0d.h3 67087428us : vector_update: irq=26
vector=33 cpu=6 prev_vector=40 prev_cpu=0
[ 67.263103] <idle>-0 0d.h3 67087428us : vector_alloc: irq=26
vector=33 reserved=1 ret=0
[ 67.272341] <idle>-0 0d.h3 67087429us : vector_config: irq=26
vector=33 cpu=6 apicdest=0x00000040
[ 67.282417] kworker/-2497 3d..1 67099083us : vector_deactivate:
irq=27 is_managed=0 can_reserve=1 early=0
[ 67.292636] kworker/-2497 3d..2 67099084us : vector_clear: irq=27
vector=33 cpu=2 prev_vector=0 prev_cpu=0
[ 67.303088] kworker/-2497 3d..2 67099084us : vector_reserve:
irq=27 ret=0
[ 67.310492] kworker/-2497 3d..2 67099084us : vector_config: irq=27
vector=239 cpu=0 apicdest=0x00000001
[ 67.320630] kworker/-2497 3d..1 67099092us : vector_teardown:
irq=27 is_managed=0 has_reserved=1
[ 67.330190] <idle>-0 0d.h2 67105805us : vector_free_moved:
irq=26 vector=40 is_managed=0
[ 67.339384] <idle>-0 0dNh3 67107060us : vector_update: irq=9
vector=37 cpu=1 prev_vector=33 prev_cpu=0
[ 67.349843] <idle>-0 0dNh3 67107060us : vector_alloc: irq=9
vector=37 reserved=1 ret=0
[ 67.358755] <idle>-0 0dNh3 67107060us : vector_config: irq=9
vector=37 cpu=1 apicdest=0x00000002
[ 67.368623] <idle>-0 0d.h3 67132424us : vector_update: irq=23
vector=33 cpu=4 prev_vector=36 prev_cpu=0
[ 67.379094] <idle>-0 0d.h3 67132426us : vector_alloc: irq=23
vector=33 reserved=1 ret=0
[ 67.388280] <idle>-0 0d.h3 67132426us : vector_config: irq=23
vector=33 cpu=4 apicdest=0x00000010
[ 67.398291] <idle>-0 0d.H3 67132435us : vector_update: irq=16
vector=38 cpu=1 prev_vector=35 prev_cpu=0
[ 67.408875] <idle>-0 0d.H3 67132435us : vector_alloc: irq=16
vector=38 reserved=1 ret=0
[ 67.417936] <idle>-0 0d.H3 67132435us : vector_config: irq=16
vector=38 cpu=1 apicdest=0x00000002
[ 67.428053] <idle>-0 0d.h2 67132539us : vector_free_moved:
irq=23 vector=36 is_managed=0
[ 67.437258] <idle>-0 0d.h2 67132540us : vector_free_moved:
irq=16 vector=35 is_managed=0
[ 67.446480] <idle>-0 0d.h2 67284214us : vector_free_moved:
irq=29 vector=42 is_managed=0
[ 67.455768] kworker/-2495 1d..1 67297696us : vector_deactivate:
irq=29 is_managed=0 can_reserve=1 early=0
[ 67.466091] kworker/-2495 1d..2 67297697us : vector_clear: irq=29
vector=36 cpu=1 prev_vector=0 prev_cpu=0
[ 67.476505] kworker/-2495 1d..2 67297697us : vector_reserve:
irq=29 ret=0
[ 67.483907] kworker/-2495 1d..2 67297697us : vector_config: irq=29
vector=239 cpu=0 apicdest=0x00000001
[ 67.494040] kworker/-2495 1d..1 67297712us : vector_teardown:
irq=29 is_managed=0 has_reserved=1
[ 67.503514] ---------------------------------
[ 67.508163] Modules linked in: snd_hda_codec_realtek
x86_pkg_temp_thermal snd_hda_codec_generic snd_hda_codec_hdmi
intel_powerclamp coretemp snd_hda_intel crct10dif_pclmul snd_hda_codec
crc32_pclmul snd_hwdep snd_hda_core ghash_clmus
[ 67.536277] CPU: 4 PID: 29 Comm: migration/4 Not tainted
4.14.0-rc4-next-20171013-ezbench_3fd49c0edac1e6df0d62f7e0fe9276 #1
[ 67.547922] Hardware name: LENOVO 10AGS00601/SHARKBAY, BIOS FBKT34AUS
04/24/2013
[ 67.555575] task: ffff88040ce66800 task.stack: ffffc90000140000
[ 67.561832] RIP: 0010:apic_update_vector+0x94/0x150
[ 67.566949] RSP: 0018:ffffc90000143c38 EFLAGS: 00010087
[ 67.572432] RAX: 000000000000b840 RBX: 0000000000000021 RCX:
ffff88041ea00000
[ 67.579910] RDX: ffff88040cc9c200 RSI: 0000000000000021 RDI:
ffff88040419c0c0
[ 67.587296] RBP: ffffc90000143c78 R08: fffffffe00000000 R09:
00050001000fffff
[ 67.594781] R10: 0000000000000040 R11: ffff88040c800270 R12:
0000000000000000
[ 67.602313] R13: 0000000000000021 R14: ffff88040419c140 R15:
ffff88040c48ea28
[ 67.609793] FS: 0000000000000000(0000) GS:ffff88041eb00000(0000)
knlGS:0000000000000000
[ 67.618134] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 67.624061] CR2: 00007f3cc02c2420 CR3: 0000000406e2b003 CR4:
00000000001606e0
[ 67.631554] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[ 67.638982] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[ 67.646525] Call Trace:
[ 67.649109] assign_vector_locked+0x9c/0x150
[ 67.653592] apic_set_affinity+0x78/0xa0
[ 67.657777] ioapic_set_affinity+0x1a/0x60
[ 67.662093] irq_do_set_affinity+0x2a/0xb0
[ 67.666427] irq_migrate_all_off_this_cpu+0x16d/0x2f0
[ 67.671737] fixup_irqs+0x2f/0x130
[ 67.675271] cpu_disable_common+0x1c7/0x1e0
[ 67.679640] native_cpu_disable+0x20/0x30
[ 67.683844] take_cpu_down+0x3c/0xa0
[ 67.687616] multi_cpu_stop+0x8e/0xb0
[ 67.691454] ? cpu_stop_queue_work+0x90/0x90
[ 67.695966] cpu_stopper_thread+0x8a/0x100
[ 67.700244] smpboot_thread_fn+0x165/0x230
[ 67.704521] kthread+0x10c/0x140
[ 67.707866] ? sort_range+0x20/0x20
[ 67.711565] ? kthread_create_on_node+0x40/0x40
[ 67.716317] ret_from_fork+0x22/0x30
[ 67.720059] Code: 89 66 10 48 c7 c0 40 b8 00 00 4a 8b 0c e5 a0 53 d1
81 48 89 c2 48 8d 14 da 48 8b 14 0a 48 85 d2 74 0b 48 81 fa 00 f0 ff ff
77 02 <0f> 0b 48 8b 75 c8 48 8d 14 d9 48 89 34 02 48 83 c4 18 5b 41 5c
[ 67.739807] RIP: apic_update_vector+0x94/0x150 RSP: ffffc90000143c38
[ 67.746501] ---[ end trace f554595b6cdabd5c ]---
[ 67.751410] note: migration/4[29] exited with preempt_count 3
[ 67.757387] ------------[ cut here ]------------
[ 67.762129] kernel BUG at kernel/cpu.c:810!
[ 67.766514] invalid opcode: 0000 [#2] PREEMPT SMP
[ 67.771442] Dumping ftrace buffer:
[ 67.775034] (ftrace buffer empty)
[ 67.778829] Modules linked in: snd_hda_codec_realtek
x86_pkg_temp_thermal snd_hda_codec_generic snd_hda_codec_hdmi
intel_powerclamp coretemp snd_hda_intel crct10dif_pclmul snd_hda_codec
crc32_pclmul snd_hwdep snd_hda_core ghash_clmus
[ 67.807176] CPU: 4 PID: 0 Comm: swapper/4 Tainted: G D
4.14.0-rc4-next-20171013-ezbench_3fd49c0edac1e6df0d62f7e0fe9276 #1
[ 67.819890] Hardware name: LENOVO 10AGS00601/SHARKBAY, BIOS FBKT34AUS
04/24/2013
[ 67.827637] task: ffff88040ce0c100 task.stack: ffffc90000098000
[ 67.833831] RIP: 0010:cpuhp_report_idle_dead+0x59/0x60
[ 67.839263] RSP: 0018:ffffc9000009bed0 EFLAGS: 00010212
[ 67.844714] RAX: 0000000000000004 RBX: ffff88041eb0c9e0 RCX:
000000000000001f
[ 67.852166] RDX: 0000000fc6a7a2a9 RSI: ffffffff81ca141e RDI:
ffffffff81cae67d
[ 67.859617] RBP: ffffc9000009bed8 R08: 000000000001e6ca R09:
0000000000000010
[ 67.866961] R10: 0000000000000000 R11: 000000000001e680 R12:
ffffffff81f2b470
[ 67.874345] R13: ffff88040ce0c100 R14: 0000000000000000 R15:
0000000000000000
[ 67.881712] FS: 0000000000000000(0000) GS:ffff88041eb00000(0000)
knlGS:0000000000000000
[ 67.890283] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 67.896341] CR2: 00007f3cc02c2420 CR3: 0000000406e2b003 CR4:
00000000001606e0
[ 67.903767] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[ 67.911247] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[ 67.918723] Call Trace:
[ 67.921278] do_idle+0x15a/0x1c0
[ 67.924675] cpu_startup_entry+0x18/0x20
[ 67.928790] start_secondary+0x10d/0x130
[ 67.932879] secondary_startup_64+0xa5/0xb0
[ 67.937327] Code: 56 00 00 00 be 10 00 00 00 48 c7 c7 70 b4 f2 81 e8
ed 8c 37 00 48 89 da 31 c9 48 c7 c6 70 cb 07 81 89 c7 e8 ba 5a 07 00 5b
5d c3 <0f> 0b 0f 1f 44 00 00 55 89 f8 89 c7 48 89 e5 41 55 41 54 53 48
[ 67.957026] RIP: cpuhp_report_idle_dead+0x59/0x60 RSP: ffffc9000009bed0
[ 67.963942] ---[ end trace f554595b6cdabd5d ]---
[ 67.968825] Kernel panic - not syncing: Attempted to kill the idle task!
[ 69.100752] Shutting down cpus with NMI
[ 69.104792] Dumping ftrace buffer:
[ 69.108657] (ftrace buffer empty)
[ 69.112538] Kernel Offset: disabled
[ 69.116311] ---[ end Kernel panic - not syncing: Attempted to kill
the idle task!