Re: DEAD callback error for CPU, WARNING: CPU: 3 PID: 1134 at kernel/cpu.c:1163 _cpu_down+0x20a/0x3a0

From: Colin King (gmail)
Date: Mon Nov 08 2021 - 17:25:52 EST

On 08/11/2021 08:12, Peter Zijlstra wrote:
On Sun, Nov 07, 2021 at 11:59:17AM +0000, Colin King (gmail) wrote:
On a SMP system in a VM, a deadlock callback error can be reproduced with
5.15, tested from head at commit d4439a1189f93d0ac1eaf0197db8e6b3e197d5c7

Didn't see this issue on 5.13

How to reproduce:

git clone https://github.com/ColinIanKing/stress-ng
cd stress-ng
make -j $(nproc)
sudo ./stress-ng --cpu-online 0 -t 15 --pathological

Tested on a 8 thread virtual machine, 4MB of memory.

[ 2239.378724] smpboot: CPU 6 is now offline
[ 2239.379443] smpboot: Booting Node 0 Processor 6 APIC 0x6
[ 2239.380169] kvm-clock: cpu 6, msr 79201181, secondary cpu clock
[ 2239.401652] ------------[ cut here ]------------
[ 2239.401658] DEAD callback error for CPU6
[ 2239.401721] WARNING: CPU: 3 PID: 1134 at kernel/cpu.c:1163
_cpu_down+0x20a/0x3a0

Can you do the same with whatever magic is required to get the
pr_debug() output from cpuhp_down_callbacks() included?

reproducer is actually very easy:

# echo 0 > /sys/devices/system/cpu/cpu7/online


[ 75.258042] smpboot: CPU 7 is now offline
[ 75.258093] CPU DOWN failed (-22) CPU 7 state padata:dead (39)
[ 75.258193] smpboot: Booting Node 0 Processor 7 APIC 0x7
[ 75.258380] kvm-clock: cpu 7, msr 1042011c1, secondary cpu clock
[ 75.278828] ------------[ cut here ]------------
[ 75.278830] DEAD callback error for CPU7
[ 75.278856] WARNING: CPU: 1 PID: 1078 at kernel/cpu.c:1163 _cpu_down+0x20a/0x3a0
[ 75.278865] Modules linked in: dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua intel_rapl_msr intel_rapl_common snd_hda_codec_generic ledtrig_audio kvm_intel snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec kvm snd_hda_core rapl input_leds snd_hwdep joydev snd_pcm snd_timer snd serio_raw qemu_fw_cfg mac_hid soundcore sch_fq_codel msr virtio_rng ip_tables x_tables autofs4 btrfs blake2b_generic zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear qxl drm_ttm_helper ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops hid_generic crct10dif_pclmul crc32_pclmul ghash_clmulni_intel cec aesni_intel rc_core crypto_simd virtio_net net_failover usbhid i2c_i801 ahci psmouse cryptd hid i2c_smbus drm lpc_ich libahci virtio_blk failover
[ 75.278920] CPU: 1 PID: 1078 Comm: bash Not tainted 5.15.0+ #1
[ 75.278924] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014
[ 75.278925] RIP: 0010:_cpu_down+0x20a/0x3a0
[ 75.278927] Code: 8b 03 41 39 c6 7f 6f 39 45 c0 0f 8e 34 ff ff ff 3d 96 00 00 00 0f 84 be 00 00 00 44 89 ee 48 c7 c7 f3 38 7a a4 e8 26 a2 f9 ff <0f> 0b e9 13 ff ff ff e8 3a bd 52 ff e9 2a ff ff ff f0 48 0f b3 05
[ 75.278929] RSP: 0018:ffffb12600d03c98 EFLAGS: 00010282
[ 75.278930] RAX: 0000000000000000 RBX: ffff8e9d7bde0660 RCX: 0000000000000000
[ 75.278931] RDX: 0000000000000001 RSI: ffffffffa47b6099 RDI: 00000000ffffffff
[ 75.278932] RBP: ffffb12600d03cd8 R08: 0000000000000000 R09: ffffb12600d03a88
[ 75.278933] R10: ffffb12600d03a80 R11: ffffffffa5156908 R12: 0000000000000000
[ 75.278934] R13: 0000000000000007 R14: 0000000000000096 R15: 00000000ffffffea
[ 75.278935] FS: 00007f5b0014a740(0000) GS:ffff8e9d7bc40000(0000) knlGS:0000000000000000
[ 75.278937] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 75.278937] CR2: 000055f4a4e58818 CR3: 0000000115042005 CR4: 0000000000370ee0
[ 75.278940] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 75.278941] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 75.278942] Call Trace:
[ 75.278943] <TASK>
[ 75.278950] cpu_device_down+0x34/0x60
[ 75.278953] cpu_subsys_offline+0xe/0x10
[ 75.278956] device_offline+0xe6/0x110
[ 75.278957] online_store+0x53/0xc0
[ 75.278959] dev_attr_store+0x17/0x30
[ 75.278962] sysfs_kf_write+0x3e/0x50
[ 75.278964] kernfs_fop_write_iter+0x137/0x1c0
[ 75.278966] new_sync_write+0x117/0x1a0
[ 75.278970] vfs_write+0x211/0x2a0
[ 75.278978] ksys_write+0x67/0xe0
[ 75.278982] __x64_sys_write+0x19/0x20
[ 75.278984] do_syscall_64+0x5c/0xc0
[ 75.279000] ? irqentry_exit_to_user_mode+0x9/0x20
[ 75.279002] ? irqentry_exit+0x33/0x40
[ 75.279004] ? exc_page_fault+0x89/0x180
[ 75.279005] ? asm_exc_page_fault+0x8/0x30
[ 75.279008] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 75.279010] RIP: 0033:0x7f5b00264777
[ 75.279016] Code: 10 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 75.279018] RSP: 002b:00007ffed5e83b58 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 75.279020] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f5b00264777
[ 75.279021] RDX: 0000000000000002 RSI: 000055d8774e0b10 RDI: 0000000000000001
[ 75.279022] RBP: 000055d8774e0b10 R08: 0000000000000000 R09: 00007f5b00365cf0
[ 75.279023] R10: 00007f5b00365cc0 R11: 0000000000000246 R12: 0000000000000002
[ 75.279024] R13: 00007f5b00366760 R14: 00007f5b00367560 R15: 00007f5b00366960
[ 75.279029] </TASK>

Colin