Subject: Re: next-20250327 - lockdep whine and USB issues at boot

From: "Valdis Klētnieks" <[email-masked]>
Date: Sat, 29 Mar 2025 02:02:10 -0400

On Sat, 29 Mar 2025 10:06:39 +0800, Ming Lei said:
> On Fri, Mar 28, 2025 at 02:10:53PM -0400, Valdis Klētnieks wrote:
> > Saw this during boot on a Dell Inspiron 5559 laptop.  
> > 
> > In addition, the external USB ports all gave up, rendering a USB mouse and a
> > USB external drive totally dead in the water.  May or may not be related, I didn't
> > dig too far into it.
>
> It shouldn't be related to the warning.

> For this lockdep warning, feel free to try patch in the following link:
>
> https://lore.kernel.org/linux-block/Z-dUCLvf06SfTOHy@fedora/

After applying that patch, USB *didn't* die during boot.  So apparently
*something* changed.  

Also, the patch merely caused a *different* lockdep warning.
Rather than  &q->q_usage_counter(io) and &q->elevator_lock, the
new one is &q->elevator_lock versus pcpu_alloc_mutex...

Looks like it's a bit more convoluted than first looked?

[   52.140990] [    T954] io scheduler bfq registered

[   52.355286] [    T848] ======================================================
[   52.436367] [    T848] WARNING: possible circular locking dependency detected
[   52.517414] [    T848] 6.14.0-next-20250327-dirty #111 Tainted: G          I     T  
[   52.598492] [    T848] ------------------------------------------------------
[   52.679571] [    T848] (udev-worker)/848 is trying to acquire lock:
[   52.760647] [    T848] ffffffff99bb4470 (pcpu_alloc_mutex){+.+.}-{4:4}, at: pcpu_alloc_noprof+0x524/0x840
[   53.162776] [    T848] 
                          but task is already holding lock:
[   53.244616] [    T848] ffff8c22c3392428 (&q->elevator_lock){+.+.}-{4:4}, at: elv_iosched_store+0xe1/0x260
[   53.646741] [    T848] 
                          which lock already depends on the new lock.

[   53.729459] [    T848] 
                          the existing dependency chain (in reverse order) is:
[   53.811348] [    T848] 
                          -> #3 (&q->elevator_lock){+.+.}-{4:4}:
[   54.214266] [    T848]        lock_acquire.part.0+0xbe/0x240
[   54.295342] [    T848]        __mutex_lock+0xcb/0xfc0
[   54.376409] [    T848]        elv_iosched_store+0xe1/0x260
[   54.457476] [    T848]        kernfs_fop_write_iter+0x160/0x240
[   54.538548] [    T848]        vfs_write+0x2ec/0x5c0
[   54.619619] [    T848]        ksys_write+0x7a/0xf0
[   54.700687] [    T848]        do_syscall_64+0x68/0x140
[   54.781751] [    T848]        entry_SYSCALL_64_after_hwframe+0x71/0x79
[   54.862814] [    T848] 
                          -> #2 (&q->q_usage_counter(io)#10){++++}-{0:0}:
[   55.345959] [    T848]        lock_acquire.part.0+0xbe/0x240
[   55.427018] [    T848]        blk_alloc_queue+0x30b/0x350
[   55.508082] [    T848]        blk_mq_alloc_queue+0x62/0xd0
[   55.589134] [    T848]        scsi_alloc_sdev+0x29c/0x3d0
[   55.670185] [    T848]        scsi_probe_and_add_lun+0x1d8/0x2b0
[   55.751232] [    T848]        __scsi_add_device+0x114/0x130
[   55.832276] [    T848]        ata_scsi_scan_host+0x7a/0x190
[   55.913321] [    T848]        async_run_entry_fn+0x24/0xc0
[   55.994358] [    T848]        process_one_work+0x21e/0x5a0
[   56.075404] [    T848]        worker_thread+0x1d5/0x3c0
[   56.156444] [    T848]        kthread+0x114/0x230
[   56.237474] [    T848]        ret_from_fork+0x2c/0x50
[   56.318492] [    T848]        ret_from_fork_asm+0x1a/0x30
[   56.399515] [    T848] 
                          -> #1 (fs_reclaim){+.+.}-{0:0}:
[   56.802275] [    T848]        lock_acquire.part.0+0xbe/0x240
[   56.883298] [    T848]        fs_reclaim_acquire+0xa8/0xe0
[   56.964317] [    T848]        __alloc_frozen_pages_noprof+0xd2/0x340
[   57.045338] [    T848]        __alloc_pages_noprof+0x9/0x20
[   57.126360] [    T848]        pcpu_alloc_pages.isra.0+0x97/0x180
[   57.207375] [    T848]        pcpu_populate_chunk+0x34/0x70
[   57.288388] [    T848]        pcpu_alloc_noprof+0x2d1/0x840
[   57.369366] [    T848]        iommu_dma_init_fq+0x91/0x260
[   57.450373] [    T848]        iommu_dma_init_domain+0x1de/0x210
[   57.531381] [    T848]        iommu_setup_dma_ops+0x47/0x80
[   57.612355] [    T848]        iommu_device_register+0x172/0x250
[   57.693348] [    T848]        intel_iommu_init+0x5ef/0xbb0
[   57.774344] [    T848]        pci_iommu_init+0x29/0x90
[   57.855333] [    T848]        do_one_initcall+0x83/0x3c0
[   57.936316] [    T848]        do_initcalls+0x130/0x1b0
[   58.017300] [    T848]        kernel_init_freeable+0x292/0x300
[   58.098281] [    T848]        kernel_init+0x15/0x130
[   58.179254] [    T848]        ret_from_fork+0x2c/0x50
[   58.260224] [    T848]        ret_from_fork_asm+0x1a/0x30
[   58.341195] [    T848] 
                          -> #0 (pcpu_alloc_mutex){+.+.}-{4:4}:
[   58.743832] [    T848]        check_prev_add+0xe1/0xcf0
[   58.824752] [    T848]        __lock_acquire+0x1031/0x13b0
[   58.905697] [    T848]        lock_acquire.part.0+0xbe/0x240
[   58.986633] [    T848]        __mutex_lock+0xcb/0xfc0
[   59.067565] [    T848]        pcpu_alloc_noprof+0x524/0x840
[   59.148463] [    T848]        sbitmap_init_node+0xf0/0x230
[   59.229392] [    T848]        sbitmap_queue_init_node+0x29/0x140
[   59.310317] [    T848]        blk_mq_init_tags+0x95/0x110
[   59.391240] [    T848]        blk_mq_alloc_map_and_rqs+0x3c/0x110
[   59.472131] [    T848]        blk_mq_init_sched+0x100/0x260
[   59.553017] [    T848]        elevator_switch+0xb1/0x190
[   59.633926] [    T848]        elv_iosched_store+0x1db/0x260
[   59.714841] [    T848]        kernfs_fop_write_iter+0x160/0x240
[   59.795728] [    T848]        vfs_write+0x2ec/0x5c0
[   59.876599] [    T848]        ksys_write+0x7a/0xf0
[   59.957500] [    T848]        do_syscall_64+0x68/0x140
[   60.038396] [    T848]        entry_SYSCALL_64_after_hwframe+0x71/0x79
[   60.119269] [    T848] 
                          other info that might help us debug this:

[   60.201395] [    T848] Chain exists of:
                            pcpu_alloc_mutex --> &q->q_usage_counter(io)#10 --> &q->elevator_lock

[   60.845339] [    T848]  Possible unsafe locking scenario:

[   60.926872] [    T848]        CPU0                    CPU1
[   61.007776] [    T848]        ----                    ----
[   61.088676] [    T848]   lock(&q->elevator_lock);
[   61.330053] [    T848]                                lock(&q->q_usage_counter(io)#10);
[   61.651731] [    T848]                                lock(&q->elevator_lock);
[   61.893151] [    T848]   lock(pcpu_alloc_mutex);
[   62.134602] [    T848] 
                           *** DEADLOCK ***

[   62.216729] [    T848] 6 locks held by (udev-worker)/848:
[   62.297630] [    T848]  #0: ffff8c22c8575440 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x7a/0xf0
[   62.860055] [    T848]  #1: ffff8c22c9fb4090 (&of->mutex#2){+.+.}-{4:4}, at: kernfs_fop_write_iter+0x119/0x240
[   63.422482] [    T848]  #2: ffff8c22c821fad0 (kn->active#89){.+.+}-{0:0}, at: kernfs_fop_write_iter+0x122/0x240
[   63.984915] [    T848]  #3: ffff8c22c3391e98 (&q->q_usage_counter(io)#10){++++}-{0:0}, at: blk_mq_freeze_queue_nomemsave+0x11/0x20
[   64.547390] [    T848]  #4: ffff8c22c3391ed8 (&q->q_usage_counter(queue)){++++}-{0:0}, at: blk_mq_freeze_queue_nomemsave+0x11/0x20
[   65.029578] [    T848]  #5: ffff8c22c3392428 (&q->elevator_lock){+.+.}-{4:4}, at: elv_iosched_store+0xe1/0x260
[   65.511794] [    T848] 
                          stack backtrace:
[   65.593348] [    T848] CPU: 1 UID: 0 PID: 848 Comm: (udev-worker) Tainted: G          I     T   6.14.0-next-20250327-dirty #111 PREEMPT(full)  7b54f670bb22238ec039f82f30e0fd3bcc8dbc83
[   65.673611] [    T848] Tainted: [I]=FIRMWARE_WORKAROUND, [T]=RANDSTRUCT
[   65.753868] [    T848] Hardware name: Dell Inc. Unidentified System/052K07, BIOS 1.9.0 09/07/2020
[   65.834126] [    T848] Call Trace:
[   65.914385] [    T848]  <TASK>
[   65.994655] [    T848]  dump_stack_lvl+0x65/0x90
[   66.074916] [    T848]  print_circular_bug.cold+0x38/0x46
[   66.155178] [    T848]  check_noncircular+0x169/0x190
[   66.235441] [    T848]  check_prev_add+0xe1/0xcf0
[   66.315699] [    T848]  ? add_chain_cache+0x115/0x4c0
[   66.395961] [    T848]  __lock_acquire+0x1031/0x13b0
[   66.476225] [    T848]  lock_acquire.part.0+0xbe/0x240
[   66.556484] [    T848]  ? pcpu_alloc_noprof+0x524/0x840
[   66.636745] [    T848]  ? lock_acquire+0xf8/0x140
[   66.717006] [    T848]  __mutex_lock+0xcb/0xfc0
[   66.797266] [    T848]  ? pcpu_alloc_noprof+0x524/0x840
[   66.877526] [    T848]  ? lockdep_hardirqs_on+0x84/0x130
[   66.957786] [    T848]  ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
[   67.038044] [    T848]  ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
[   67.118303] [    T848]  ? pcpu_alloc_noprof+0x524/0x840
[   67.198566] [    T848]  ? pcpu_alloc_noprof+0x524/0x840
[   67.278825] [    T848]  ? find_held_lock+0x2b/0x80
[   67.359084] [    T848]  pcpu_alloc_noprof+0x524/0x840
[   67.439344] [    T848]  ? local_clock_noinstr+0xf/0x100
[   67.519608] [    T848]  sbitmap_init_node+0xf0/0x230
[   67.599870] [    T848]  sbitmap_queue_init_node+0x29/0x140
[   67.680131] [    T848]  blk_mq_init_tags+0x95/0x110
[   67.760392] [    T848]  blk_mq_alloc_map_and_rqs+0x3c/0x110
[   67.840654] [    T848]  blk_mq_init_sched+0x100/0x260
[   67.920916] [    T848]  elevator_switch+0xb1/0x190
[   68.001176] [    T848]  ? elv_iosched_store+0x1d0/0x260
[   68.081437] [    T848]  elv_iosched_store+0x1db/0x260
[   68.161700] [    T848]  kernfs_fop_write_iter+0x160/0x240
[   68.241960] [    T848]  vfs_write+0x2ec/0x5c0
[   68.322224] [    T848]  ksys_write+0x7a/0xf0
[   68.402485] [    T848]  do_syscall_64+0x68/0x140
[   68.482745] [    T848]  entry_SYSCALL_64_after_hwframe+0x71/0x79
[   68.563004] [    T848] RIP: 0033:0x7f2a1747ca06
[   68.643263] [    T848] Code: 5d e8 41 8b 93 08 03 00 00 59 5e 48 83 f8 fc 75 19 83 e2 39 83 fa 08 75 11 e8 26 ff ff ff 66 0f 1f 44 00 00 48 8b 45 10 0f 05 <48> 8b 5d f8 c9 c3 0f 1f 40 00 f3 0f 1e fa 55 48 89 e5 48 83 ec 08
[   68.723521] [    T848] RSP: 002b:00007ffe48933eb0 EFLAGS: 00000202 ORIG_RAX: 0000000000000001
[   68.884037] [    T848] RAX: ffffffffffffffda RBX: 000056119a4eaff0 RCX: 00007f2a1747ca06
[   68.964295] [    T848] RDX: 0000000000000003 RSI: 00007ffe48934200 RDI: 0000000000000027
[   69.044553] [    T848] RBP: 00007ffe48933ed0 R08: 0000000000000000 R09: 0000000000000000
[   69.124811] [    T848] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000000003
[   69.205068] [    T848] R13: 0000000000000003 R14: 00007ffe48934200 R15: 00007ffe48934200
[   69.285332] [    T848]  </TASK>