Re: soft lockup with pre-rc1

[Damien Le Moal]

On 10/7/22 02:33, Jeff Layton wrote:
> I pulled down Linus tree today and did some testing with some filesystem
> related patches. Running xfstests against ext4 in a VM, and I hit this:
> 
> [ 8947.343179] run fstests generic/224 at 2022-10-06 13:24:20
> [ 8948.435322] EXT4-fs (dm-1): mounted filesystem with ordered data mode. Quota mode: none.
> [ 8949.235839] EXT4-fs (dm-2): mounted filesystem with ordered data mode. Quota mode: none.
> [ 9017.622065] watchdog: BUG: soft lockup - CPU#2 stuck for 23s! [kworker/2:0:1145882]
> [ 9023.009230] Modules linked in: ext4(E) mbcache(E) jbd2(E) nft_fib_inet(E) nft_fib_ipv4(E) nft_fib_ipv6(E) nft_fib(E) nft_reject_inet(E) nf_reject_ipv4(E) nf_reject_ipv6(E) nft_reject(E) nft_ct(E) nft_chain_nat(E) nf_nat(E) nf_conntrack(E) nf_defrag_ipv6(E) nf_defrag_ipv4(E) rfkill(E) ip_set(E) nf_tables(E) nfnetlink(E) iTCO_wdt(E) intel_pmc_bxt(E) iTCO_vendor_support(E) joydev(E) intel_rapl_msr(E) i2c_i801(E) virtio_balloon(E) i2c_smbus(E) lpc_ich(E) intel_rapl_common(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) fuse(E) sunrpc(E) zram(E) xfs(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) ghash_clmulni_intel(E) virtio_gpu(E) virtio_dma_buf(E) drm_shmem_helper(E) serio_raw(E) virtio_net(E) drm_kms_helper(E) virtio_blk(E) net_failover(E) virtio_console(E) failover(E) drm(E) qemu_fw_cfg(E)
> [ 9023.081530] CPU: 2 PID: 1145882 Comm: kworker/2:0 Tainted: G            E      6.0.0+ #43
> [ 9023.085919] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-1.fc36 04/01/2014
> [ 9023.090747] Workqueue: events_freezable_power_ disk_events_workfn
> [ 9023.095155] RIP: 0010:__do_softirq+0xb5/0x401
> [ 9023.147050] Code: ff e8 6f db bc fe c7 44 24 1c 0a 00 00 00 48 c7 c7 c0 d2 87 ad e8 1b 9c be ff 65 66 c7 05 d1 0e a4 52 00 00 fb 0f 1f 44 00 00 <bb> ff ff ff ff 41 0f bc de 83 c3 01 0f 84 9a 00 00 00 48 c7 c5 c0
> [ 9023.158173] RSP: 0018:ffff888221909f80 EFLAGS: 00000296
> [ 9023.163217] RAX: 0000000000000002 RBX: ffff888107fb002c RCX: ffffffffac1cdc2d
> [ 9023.168569] RDX: dffffc0000000000 RSI: ffffffffad87d2c0 RDI: ffffffffada7f7e0
> [ 9023.173885] RBP: 0000000000000000 R08: 0000000000000000 R09: ffffffffafc01083
> [ 9023.179097] R10: fffffbfff5f80210 R11: 0000000000000000 R12: 0000000000000000
> [ 9023.184780] R13: 0000000000000000 R14: 0000000000000282 R15: ffff888107fb0000
> [ 9023.189955] FS:  0000000000000000(0000) GS:ffff888221900000(0000) knlGS:0000000000000000
> [ 9023.195329] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 9023.200380] CR2: 00007fba16a314e0 CR3: 0000000107882000 CR4: 00000000003506e0
> [ 9023.205569] Call Trace:
> [ 9023.209571]  <IRQ>
> [ 9023.213587]  __irq_exit_rcu+0x12a/0x190
> [ 9023.217664]  sysvec_apic_timer_interrupt+0x8a/0xb0
> [ 9023.221863]  </IRQ>
> [ 9023.225684]  <TASK>
> [ 9023.229384]  asm_sysvec_apic_timer_interrupt+0x16/0x20
> [ 9023.233485] RIP: 0010:_raw_spin_unlock_irqrestore+0x19/0x40
> [ 9023.237740] Code: c6 48 89 df e8 d8 54 fe fe 90 eb cc 0f 1f 44 00 00 0f 1f 44 00 00 e8 5a 4e fe fe 90 f7 c6 00 02 00 00 74 06 fb 0f 1f 44 00 00 <bf> 01 00 00 00 e8 ad 9a f8 fe 65 8b 05 16 a8 e2 52 85 c0 74 05 e9
> [ 9023.246961] RSP: 0018:ffff88810f9e7828 EFLAGS: 00000206
> [ 9023.251106] RAX: 0000000000000001 RBX: 0000000000000000 RCX: ffffffffacbdecee
> [ 9023.255535] RDX: dffffc0000000000 RSI: 0000000000000286 RDI: ffff888109e4d500
> [ 9023.259915] RBP: ffff88810a9d8000 R08: 0000000000000001 R09: ffff88810aa8894b
> [ 9023.264310] R10: ffffed1021551129 R11: fefefefefefefeff R12: 0000000000000286
> [ 9023.268834] R13: ffff88810a9d8010 R14: ffff8881013e0000 R15: ffff88810ab5a000
> [ 9023.273239]  ? ata_scsi_queuecmd+0x6e/0xb0
> [ 9023.277360]  ? _raw_spin_unlock_irqrestore+0xa/0x40
> [ 9023.281479]  ata_scsi_queuecmd+0x7a/0xb0
> [ 9023.285386]  scsi_queue_rq+0xb5c/0x13c0
> [ 9023.289449]  blk_mq_dispatch_rq_list+0x3e2/0xfc0
> [ 9023.293549]  ? blk_insert_cloned_request+0x330/0x330
> [ 9023.297646]  ? _raw_spin_lock+0x77/0xc0
> [ 9023.301593]  ? _raw_spin_lock_bh+0xc0/0xc0
> [ 9023.305485]  __blk_mq_sched_dispatch_requests+0x13b/0x1f0
> [ 9023.309609]  ? blk_mq_do_dispatch_ctx+0x340/0x340
> [ 9023.313581]  ? _raw_spin_lock_bh+0xc0/0xc0
> [ 9023.317304]  blk_mq_sched_dispatch_requests+0x82/0xb0
> [ 9023.320780]  __blk_mq_run_hw_queue+0x66/0xe0
> [ 9023.324965]  blk_mq_sched_insert_request+0x16f/0x1d0
> [ 9023.328294]  ? __alloc_pages_slowpath.constprop.0+0x1360/0x1360
> [ 9023.331757]  ? blk_mq_sched_bio_merge+0x180/0x180
> [ 9023.335040]  ? bio_add_pc_page+0x8a/0xb0
> [ 9023.339093]  blk_execute_rq+0x111/0x2c0
> [ 9023.343823]  ? blk_mq_get_sq_hctx+0x80/0x80
> [ 9023.348523]  __scsi_execute+0x13a/0x2b0
> [ 9023.353163]  sr_check_events+0x13e/0x420
> [ 9023.357071]  ? sr_packet+0x90/0x90
> [ 9023.359914]  ? __mod_timer+0x42a/0x5e0
> [ 9023.362727]  ? hibernation_snapshot+0x3e8/0x640
> [ 9023.365600]  ? console_emit_next_record.constprop.0+0x400/0x400
> [ 9023.368659]  cdrom_check_events+0x34/0x70
> [ 9023.371522]  disk_check_events+0x5d/0x180
> [ 9023.374430]  process_one_work+0x3d3/0x6a0
> [ 9023.377304]  worker_thread+0x8a/0x610
> [ 9023.380329]  ? process_one_work+0x6a0/0x6a0
> [ 9023.383202]  kthread+0x167/0x1a0
> [ 9023.385889]  ? kthread_complete_and_exit+0x20/0x20
> [ 9023.388668]  ret_from_fork+0x22/0x30
> [ 9023.391338]  </TASK>

Adding linux-block and linux-fsdevel, just in case.

Hmm... Weird. ATA changes for 6.1 are not merged yet, and none of them
touch ata_scsi_queue_cmd() or port locking anyway.

It looks like the ata lock is stuck, which may mean that some other
context is stuck in completion path ? Do you see any other task stuck in
ata code ?

> 
> Last commit in my tree is this:
> 
> 833477fce7a1 (origin/master) Merge tag 'sound-6.1-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
> 
> I also have some filesystem related patches on top of this. inode-
>> i_version patches mostly -- nothing that should effect things at this
> level.
> 
> config is attached.

-- 
Damien Le Moal
Western Digital Research