| Message ID | 20201028203124.375344-4-mathias.nyman@linux.intel.com |
|---|---|
| State | New |
| Headers | show |
| Series | xhci fixes for usb-linus | expand |
Greetings,
Testing $subject in shiny new 5.10-rt induced a lockdep grumble, so I
plugged it into master and booted lappy with threadirqs. When I then
fired up my android-x86 vm toy, that kernel grumbled as well.
[ 81.184240] tun: Universal TUN/TAP device driver, 1.6
[ 81.187185] virbr0: port 1(virbr0-nic) entered blocking state
[ 81.187230] virbr0: port 1(virbr0-nic) entered disabled state
[ 81.187529] device virbr0-nic entered promiscuous mode
[ 81.867218] virbr0: port 1(virbr0-nic) entered blocking state
[ 81.867326] virbr0: port 1(virbr0-nic) entered listening state
[ 82.038707] virbr0: port 1(virbr0-nic) entered disabled state
[ 93.259770] virbr0: port 2(vnet0) entered blocking state
[ 93.259818] virbr0: port 2(vnet0) entered disabled state
[ 93.260118] device vnet0 entered promiscuous mode
[ 93.260888] virbr0: port 2(vnet0) entered blocking state
[ 93.260935] virbr0: port 2(vnet0) entered listening state
[ 93.601718] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[ 95.278373] virbr0: port 2(vnet0) entered learning state
[ 97.293928] virbr0: port 2(vnet0) entered forwarding state
[ 97.293984] virbr0: topology change detected, propagating
[ 107.611645] =====================================================
[ 107.611650] WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected
[ 107.611656] 5.10.0.g23859ae-master #17 Tainted: G S I E
[ 107.611660] -----------------------------------------------------
[ 107.611666] worker/4060 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
[ 107.611671] ffff90bba6d2c680 (lock#2){+.+.}-{2:2}, at: radix_tree_maybe_preload+0x8/0xb0
[ 107.611684]
and this task is already holding:
[ 107.611689] ffff90ba501a8430 (&xhci->lock){..-.}-{2:2}, at: xhci_urb_enqueue+0x20a/0x6f0 [xhci_hcd]
[ 107.611706] which would create a new lock dependency:
[ 107.611710] (&xhci->lock){..-.}-{2:2} -> (lock#2){+.+.}-{2:2}
[ 107.611719]
but this new dependency connects a SOFTIRQ-irq-safe lock:
[ 107.611725] (&xhci->lock){..-.}-{2:2}
[ 107.611727]
... which became SOFTIRQ-irq-safe at:
[ 107.611741] lock_acquire+0x1a7/0x3b0
[ 107.611748] _raw_spin_lock_irqsave+0x3d/0x50
[ 107.611760] xhci_hub_status_data+0xc2/0x390 [xhci_hcd]
[ 107.611776] usb_hcd_poll_rh_status+0x41/0x180 [usbcore]
[ 107.611783] call_timer_fn+0x9d/0x2b0
[ 107.611788] run_timer_softirq+0x48d/0x570
[ 107.611793] __do_softirq+0xeb/0x4a4
[ 107.611799] run_ksoftirqd+0x32/0x60
[ 107.611805] smpboot_thread_fn+0x1d8/0x280
[ 107.611810] kthread+0x14c/0x170
[ 107.611816] ret_from_fork+0x1f/0x30
[ 107.611819]
to a SOFTIRQ-irq-unsafe lock:
[ 107.611825] (lock#2){+.+.}-{2:2}
[ 107.611828]
... which became SOFTIRQ-irq-unsafe at:
[ 107.611837] ...
[ 107.611839] lock_acquire+0x1a7/0x3b0
[ 107.611846] __radix_tree_preload+0x5c/0x2a0
[ 107.611851] idr_preload+0xf/0xb0
[ 107.611857] __kernfs_new_node+0x66/0x270
[ 107.611862] kernfs_create_root+0xab/0x140
[ 107.611868] sysfs_init+0x14/0x53
[ 107.611873] mnt_init+0xc9/0x1f1
[ 107.611878] vfs_caches_init+0xca/0xd4
[ 107.611884] start_kernel+0x734/0x78a
[ 107.611889] secondary_startup_64_no_verify+0xb8/0xbb
[ 107.611893]
other info that might help us debug this:
[ 107.611901] Possible interrupt unsafe locking scenario:
[ 107.611908] CPU0 CPU1
[ 107.611912] ---- ----
[ 107.611916] lock(lock#2);
[ 107.611921] local_irq_disable();
[ 107.611926] lock(&xhci->lock);
[ 107.611932] lock(lock#2);
[ 107.611938] <Interrupt>
[ 107.611942] lock(&xhci->lock);
[ 107.611947]
*** DEADLOCK ***
[ 107.611954] 4 locks held by worker/4060:
[ 107.611958] #0: ffffffffb056a9e0 (rcu_read_lock){....}-{1:2}, at: hctx_lock+0x17/0xe0
[ 107.611969] #1: ffff90ba45d58048 (shost->host_lock){....}-{2:2}, at: uas_queuecommand+0x28/0x260 [uas]
[ 107.611981] #2: ffff90ba45d59848 (&devinfo->lock){..-.}-{2:2}, at: uas_queuecommand+0xd9/0x260 [uas]
[ 107.611992] #3: ffff90ba501a8430 (&xhci->lock){..-.}-{2:2}, at: xhci_urb_enqueue+0x20a/0x6f0 [xhci_hcd]
[ 107.612008]
the dependencies between SOFTIRQ-irq-safe lock and the holding lock:
[ 107.612035] -> (&xhci->lock){..-.}-{2:2} {
[ 107.612043] IN-SOFTIRQ-W at:
[ 107.612048] lock_acquire+0x1a7/0x3b0
[ 107.612054] _raw_spin_lock_irqsave+0x3d/0x50
[ 107.612066] xhci_hub_status_data+0xc2/0x390 [xhci_hcd]
[ 107.612079] usb_hcd_poll_rh_status+0x41/0x180 [usbcore]
[ 107.612085] call_timer_fn+0x9d/0x2b0
[ 107.612091] run_timer_softirq+0x48d/0x570
[ 107.612096] __do_softirq+0xeb/0x4a4
[ 107.612102] run_ksoftirqd+0x32/0x60
[ 107.612108] smpboot_thread_fn+0x1d8/0x280
[ 107.612113] kthread+0x14c/0x170
[ 107.612119] ret_from_fork+0x1f/0x30
[ 107.612123] INITIAL USE at:
[ 107.612129] lock_acquire+0x1a7/0x3b0
[ 107.612134] _raw_spin_lock_irqsave+0x3d/0x50
[ 107.612146] xhci_hub_control+0xa5/0x2440 [xhci_hcd]
[ 107.612158] usb_hcd_submit_urb+0x743/0xb00 [usbcore]
[ 107.612171] usb_start_wait_urb+0x55/0x140 [usbcore]
[ 107.612184] usb_control_msg+0xc3/0x110 [usbcore]
[ 107.612195] hub_configure+0x103/0xc00 [usbcore]
[ 107.612207] hub_probe+0x29c/0x350 [usbcore]
[ 107.612220] usb_probe_interface+0x105/0x300 [usbcore]
[ 107.612227] really_probe+0xf7/0x4d0
[ 107.612232] driver_probe_device+0x5d/0x140
[ 107.612238] bus_for_each_drv+0x5e/0x90
[ 107.612244] __device_attach+0xbe/0x140
[ 107.612249] bus_probe_device+0x9c/0xb0
[ 107.612255] device_add+0x3fa/0x820
[ 107.612267] usb_set_configuration+0x469/0x960 [usbcore]
[ 107.612280] usb_generic_driver_probe+0x28/0x70 [usbcore]
[ 107.612293] usb_probe_device+0x3b/0xc0 [usbcore]
[ 107.612298] really_probe+0xf7/0x4d0
[ 107.612304] driver_probe_device+0x5d/0x140
[ 107.612309] bus_for_each_drv+0x5e/0x90
[ 107.612315] __device_attach+0xbe/0x140
[ 107.612320] bus_probe_device+0x9c/0xb0
[ 107.612325] device_add+0x3fa/0x820
[ 107.612337] usb_new_device+0x21d/0x4a0 [usbcore]
[ 107.612349] usb_add_hcd+0x60b/0x7f0 [usbcore]
[ 107.612361] usb_hcd_pci_probe+0x237/0x480 [usbcore]
[ 107.612367] xhci_pci_probe+0x6d/0x1df [xhci_pci]
[ 107.612374] local_pci_probe+0x42/0x90
[ 107.612380] pci_device_probe+0xe7/0x1a0
[ 107.612385] really_probe+0xf7/0x4d0
[ 107.612391] driver_probe_device+0x5d/0x140
[ 107.612397] device_driver_attach+0x4f/0x60
[ 107.612402] __driver_attach+0xa4/0x140
[ 107.612408] bus_for_each_dev+0x67/0x90
[ 107.612414] bus_add_driver+0x18c/0x230
[ 107.612419] driver_register+0x5b/0xf0
[ 107.612425] do_one_initcall+0x54/0x2f0
[ 107.612430] do_init_module+0x5b/0x21b
[ 107.612436] load_module+0x1e40/0x2370
[ 107.612442] __do_sys_finit_module+0x98/0xe0
[ 107.612448] do_syscall_64+0x33/0x40
[ 107.612453] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 107.612458] }
[ 107.612467] ... key at: [<ffffffffc06044e0>] __key.49448+0x0/0xfffffffffffe5b20 [xhci_hcd]
[ 107.612473] ... acquired at:
[ 107.612478] lock_acquire+0x1a7/0x3b0
[ 107.612483] radix_tree_maybe_preload+0x49/0xb0
[ 107.612493] xhci_update_stream_segment_mapping+0x63/0x160 [xhci_hcd]
[ 107.612503] xhci_ring_expansion+0x19d/0x320 [xhci_hcd]
[ 107.612514] prepare_ring+0x8b/0x1f0 [xhci_hcd]
[ 107.612523] prepare_transfer+0x64/0x140 [xhci_hcd]
[ 107.612534] xhci_queue_bulk_tx+0xe7/0xb70 [xhci_hcd]
[ 107.612544] xhci_urb_enqueue+0x615/0x6f0 [xhci_hcd]
[ 107.612556] usb_hcd_submit_urb+0xa7/0xb00 [usbcore]
[ 107.612561] uas_submit_urbs+0x35b/0x500 [uas]
[ 107.612566] uas_queuecommand+0x1db/0x260 [uas]
[ 107.612579] scsi_queue_rq+0x5ca/0xbe0 [scsi_mod]
[ 107.612585] blk_mq_dispatch_rq_list+0x285/0x6d0
[ 107.612590] __blk_mq_do_dispatch_sched+0x210/0x260
[ 107.612596] __blk_mq_sched_dispatch_requests+0x133/0x170
[ 107.612602] blk_mq_sched_dispatch_requests+0x30/0x60
[ 107.612607] __blk_mq_run_hw_queue+0x6f/0xd0
[ 107.612612] __blk_mq_delay_run_hw_queue+0xda/0x1f0
[ 107.612617] blk_mq_run_hw_queue+0x6a/0xd0
[ 107.612623] blk_mq_sched_insert_requests+0xdd/0x2a0
[ 107.612628] blk_mq_flush_plug_list+0x12d/0x240
[ 107.612633] blk_flush_plug_list+0xb4/0xd0
[ 107.612638] blk_mq_submit_bio+0x365/0x770
[ 107.612643] submit_bio_noacct+0x41e/0x4b0
[ 107.612648] submit_bio+0x33/0x160
[ 107.612677] ext4_mpage_readpages+0x1ad/0x980 [ext4]
[ 107.612683] read_pages+0x7d/0x230
[ 107.612688] page_cache_ra_unbounded+0x138/0x1f0
[ 107.612695] generic_file_buffered_read+0x144/0xa10
[ 107.612701] do_iter_readv_writev+0x17c/0x1b0
[ 107.612706] do_iter_read+0xca/0x1c0
[ 107.612711] vfs_readv+0x6f/0xa0
[ 107.612716] do_preadv+0x9c/0xe0
[ 107.612720] do_syscall_64+0x33/0x40
[ 107.612726] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 107.612734]
the dependencies between the lock to be acquired
[ 107.612734] and SOFTIRQ-irq-unsafe lock:
[ 107.612761] -> (lock#2){+.+.}-{2:2} {
[ 107.612769] HARDIRQ-ON-W at:
[ 107.612775] lock_acquire+0x1a7/0x3b0
[ 107.612780] __radix_tree_preload+0x5c/0x2a0
[ 107.612786] idr_preload+0xf/0xb0
[ 107.612792] __kernfs_new_node+0x66/0x270
[ 107.612798] kernfs_create_root+0xab/0x140
[ 107.612804] sysfs_init+0x14/0x53
[ 107.612809] mnt_init+0xc9/0x1f1
[ 107.612814] vfs_caches_init+0xca/0xd4
[ 107.612820] start_kernel+0x734/0x78a
[ 107.612826] secondary_startup_64_no_verify+0xb8/0xbb
[ 107.612831] SOFTIRQ-ON-W at:
[ 107.612836] lock_acquire+0x1a7/0x3b0
[ 107.612841] __radix_tree_preload+0x5c/0x2a0
[ 107.612847] idr_preload+0xf/0xb0
[ 107.612853] __kernfs_new_node+0x66/0x270
[ 107.612858] kernfs_create_root+0xab/0x140
[ 107.612864] sysfs_init+0x14/0x53
[ 107.612869] mnt_init+0xc9/0x1f1
[ 107.612875] vfs_caches_init+0xca/0xd4
[ 107.612880] start_kernel+0x734/0x78a
[ 107.612885] secondary_startup_64_no_verify+0xb8/0xbb
[ 107.612891] INITIAL USE at:
[ 107.612896] lock_acquire+0x1a7/0x3b0
[ 107.612901] __radix_tree_preload+0x5c/0x2a0
[ 107.612906] idr_preload+0xf/0xb0
[ 107.612912] __kernfs_new_node+0x66/0x270
[ 107.612918] kernfs_create_root+0xab/0x140
[ 107.612923] sysfs_init+0x14/0x53
[ 107.612928] mnt_init+0xc9/0x1f1
[ 107.612933] vfs_caches_init+0xca/0xd4
[ 107.612939] start_kernel+0x734/0x78a
[ 107.612944] secondary_startup_64_no_verify+0xb8/0xbb
[ 107.612949] }
[ 107.612953] ... key at: [<ffff90bba6c2c680>] 0xffff90bba6c2c680
[ 107.612958] ... acquired at:
[ 107.612963] lock_acquire+0x1a7/0x3b0
[ 107.612968] radix_tree_maybe_preload+0x49/0xb0
[ 107.612978] xhci_update_stream_segment_mapping+0x63/0x160 [xhci_hcd]
[ 107.612989] xhci_ring_expansion+0x19d/0x320 [xhci_hcd]
[ 107.612999] prepare_ring+0x8b/0x1f0 [xhci_hcd]
[ 107.613008] prepare_transfer+0x64/0x140 [xhci_hcd]
[ 107.613019] xhci_queue_bulk_tx+0xe7/0xb70 [xhci_hcd]
[ 107.613029] xhci_urb_enqueue+0x615/0x6f0 [xhci_hcd]
[ 107.613041] usb_hcd_submit_urb+0xa7/0xb00 [usbcore]
[ 107.613047] uas_submit_urbs+0x35b/0x500 [uas]
[ 107.613052] uas_queuecommand+0x1db/0x260 [uas]
[ 107.613063] scsi_queue_rq+0x5ca/0xbe0 [scsi_mod]
[ 107.613068] blk_mq_dispatch_rq_list+0x285/0x6d0
[ 107.613073] __blk_mq_do_dispatch_sched+0x210/0x260
[ 107.613079] __blk_mq_sched_dispatch_requests+0x133/0x170
[ 107.613085] blk_mq_sched_dispatch_requests+0x30/0x60
[ 107.613090] __blk_mq_run_hw_queue+0x6f/0xd0
[ 107.613095] __blk_mq_delay_run_hw_queue+0xda/0x1f0
[ 107.613100] blk_mq_run_hw_queue+0x6a/0xd0
[ 107.613106] blk_mq_sched_insert_requests+0xdd/0x2a0
[ 107.613111] blk_mq_flush_plug_list+0x12d/0x240
[ 107.613116] blk_flush_plug_list+0xb4/0xd0
[ 107.613121] blk_mq_submit_bio+0x365/0x770
[ 107.613126] submit_bio_noacct+0x41e/0x4b0
[ 107.613131] submit_bio+0x33/0x160
[ 107.613153] ext4_mpage_readpages+0x1ad/0x980 [ext4]
[ 107.613158] read_pages+0x7d/0x230
[ 107.613163] page_cache_ra_unbounded+0x138/0x1f0
[ 107.613169] generic_file_buffered_read+0x144/0xa10
[ 107.613175] do_iter_readv_writev+0x17c/0x1b0
[ 107.613180] do_iter_read+0xca/0x1c0
[ 107.613185] vfs_readv+0x6f/0xa0
[ 107.613189] do_preadv+0x9c/0xe0
[ 107.613194] do_syscall_64+0x33/0x40
[ 107.613199] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 107.613207]
stack backtrace:
[ 107.613214] CPU: 2 PID: 4060 Comm: worker Tainted: G S I E 5.10.0.g23859ae-master #17
[ 107.613220] Hardware name: HP HP Spectre x360 Convertible/804F, BIOS F.47 11/22/2017
[ 107.613226] Call Trace:
[ 107.613233] dump_stack+0x77/0x97
[ 107.613239] check_irq_usage+0x7a8/0x7b0
[ 107.613246] ? check_path.constprop.54+0x22/0x40
[ 107.613255] ? __lock_acquire+0x14af/0x1a70
[ 107.613260] __lock_acquire+0x14af/0x1a70
[ 107.613268] lock_acquire+0x1a7/0x3b0
[ 107.613273] ? radix_tree_maybe_preload+0x8/0xb0
[ 107.613283] ? xhci_segment_alloc+0xd8/0x100 [xhci_hcd]
[ 107.613290] radix_tree_maybe_preload+0x49/0xb0
[ 107.613295] ? radix_tree_maybe_preload+0x8/0xb0
[ 107.613305] xhci_update_stream_segment_mapping+0x63/0x160 [xhci_hcd]
[ 107.613316] xhci_ring_expansion+0x19d/0x320 [xhci_hcd]
[ 107.613328] prepare_ring+0x8b/0x1f0 [xhci_hcd]
[ 107.613338] prepare_transfer+0x64/0x140 [xhci_hcd]
[ 107.613350] xhci_queue_bulk_tx+0xe7/0xb70 [xhci_hcd]
[ 107.613363] xhci_urb_enqueue+0x615/0x6f0 [xhci_hcd]
[ 107.613377] usb_hcd_submit_urb+0xa7/0xb00 [usbcore]
[ 107.613383] ? find_held_lock+0x2d/0x90
[ 107.613389] ? uas_submit_urbs+0x34a/0x500 [uas]
[ 107.613396] uas_submit_urbs+0x35b/0x500 [uas]
[ 107.613403] uas_queuecommand+0x1db/0x260 [uas]
[ 107.613415] scsi_queue_rq+0x5ca/0xbe0 [scsi_mod]
[ 107.613421] blk_mq_dispatch_rq_list+0x285/0x6d0
[ 107.613430] __blk_mq_do_dispatch_sched+0x210/0x260
[ 107.613437] __blk_mq_sched_dispatch_requests+0x133/0x170
[ 107.613444] blk_mq_sched_dispatch_requests+0x30/0x60
[ 107.613449] __blk_mq_run_hw_queue+0x6f/0xd0
[ 107.613455] __blk_mq_delay_run_hw_queue+0xda/0x1f0
[ 107.613461] blk_mq_run_hw_queue+0x6a/0xd0
[ 107.613467] blk_mq_sched_insert_requests+0xdd/0x2a0
[ 107.613473] blk_mq_flush_plug_list+0x12d/0x240
[ 107.613480] blk_flush_plug_list+0xb4/0xd0
[ 107.613486] blk_mq_submit_bio+0x365/0x770
[ 107.613493] submit_bio_noacct+0x41e/0x4b0
[ 107.613500] ? submit_bio+0x33/0x160
[ 107.613505] ? xa_load+0xb6/0x130
[ 107.613509] submit_bio+0x33/0x160
[ 107.613514] ? bio_add_page+0x29/0x70
[ 107.613536] ext4_mpage_readpages+0x1ad/0x980 [ext4]
[ 107.613544] ? find_held_lock+0x2d/0x90
[ 107.613550] read_pages+0x7d/0x230
[ 107.613556] ? lru_cache_add+0x113/0x1b0
[ 107.613562] ? page_cache_ra_unbounded+0x138/0x1f0
[ 107.613567] page_cache_ra_unbounded+0x138/0x1f0
[ 107.613575] generic_file_buffered_read+0x144/0xa10
[ 107.613583] do_iter_readv_writev+0x17c/0x1b0
[ 107.613589] do_iter_read+0xca/0x1c0
[ 107.613595] vfs_readv+0x6f/0xa0
[ 107.613602] ? __fget_files+0xea/0x1f0
[ 107.613608] ? __fget_files+0x102/0x1f0
[ 107.613614] ? do_preadv+0x9c/0xe0
[ 107.613618] do_preadv+0x9c/0xe0
[ 107.613624] do_syscall_64+0x33/0x40
[ 107.613629] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 107.613637] RIP: 0033:0x7fd344b8cc83
[ 107.613647] Code: 49 89 ca b8 27 01 00 00 0f 05 48 3d 01 f0 ff ff 73 34 c3 48 83 ec 08 e8 fb 64 01 00 48 89 04 24 49 89 ca b8 27 01 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 41 65 01 00 48 89 d0 48 83 c4 08 48 3d 01
[ 107.613657] RSP: 002b:00007fd33d39a850 EFLAGS: 00000293 ORIG_RAX: 0000000000000127
[ 107.613664] RAX: ffffffffffffffda RBX: 00007fd20e0a46f0 RCX: 00007fd344b8cc83
[ 107.613670] RDX: 0000000000000002 RSI: 00007fd3242644b0 RDI: 000000000000000b
[ 107.613675] RBP: 0000563a9eb21140 R08: 0000000000000000 R09: 00000000ffffffff
[ 107.613681] R10: 00000000da0c9000 R11: 0000000000000293 R12: 0000563a9cdc36b0
[ 107.613686] R13: 0000563a9eb211a8 R14: 00007fd324269590 R15: 00007ffeab138280
Hi On 29.10.2020 8.03, Mike Galbraith wrote: > Greetings, > > Testing $subject in shiny new 5.10-rt induced a lockdep grumble, so I > plugged it into master and booted lappy with threadirqs. When I then > fired up my android-x86 vm toy, that kernel grumbled as well. > > > [ 107.611645] ===================================================== > [ 107.611650] WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected > [ 107.611656] 5.10.0.g23859ae-master #17 Tainted: G S I E > [ 107.611660] ----------------------------------------------------- > [ 107.611666] worker/4060 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: > [ 107.611671] ffff90bba6d2c680 (lock#2){+.+.}-{2:2}, at: radix_tree_maybe_preload+0x8/0xb0 > [ 107.611684] > and this task is already holding: > [ 107.611689] ffff90ba501a8430 (&xhci->lock){..-.}-{2:2}, at: xhci_urb_enqueue+0x20a/0x6f0 [xhci_hcd] > [ 107.611706] which would create a new lock dependency: > [ 107.611710] (&xhci->lock){..-.}-{2:2} -> (lock#2){+.+.}-{2:2} > [ 107.611719] This looks like a separate locking issue related to stream ring buffer expansion and radix tree usage. This has probably been there for a while. Can you check if this can be reproduced with 5.9 kernel? I don't have a quick fix for this. I need to look into it more. Anyway, this shouldn't prevent PATCH 3/3 from fixing the streams debugfs issue introduced in 5.10-rc1 -Mathias
On 2020-10-29 11:41:41 [+0200], Mathias Nyman wrote: > This looks like a separate locking issue related to stream ring buffer expansion and radix tree usage. > This has probably been there for a while. Can you check if this can be reproduced with 5.9 kernel? > > I don't have a quick fix for this. I need to look into it more. > Anyway, this shouldn't prevent PATCH 3/3 from fixing the streams debugfs issue introduced in 5.10-rc1 let me look into this. > -Mathias Sebastian
On Thu, 2020-10-29 at 10:42 +0100, Sebastian Andrzej Siewior wrote: > On 2020-10-29 11:41:41 [+0200], Mathias Nyman wrote: > > This looks like a separate locking issue related to stream ring buffer expansion and radix tree usage. > > This has probably been there for a while. Can you check if this can be reproduced with 5.9 kernel? > > > > I don't have a quick fix for this. I need to look into it more. > > Anyway, this shouldn't prevent PATCH 3/3 from fixing the streams debugfs issue introduced in 5.10-rc1 > > let me look into this. Below, the aforementioned 5.10-rt splat in case that helps. [ 155.051661] ====================================================== [ 155.051661] WARNING: possible circular locking dependency detected [ 155.051662] 5.10.0.g23859ae-rt1-rt #11 Tainted: G S I E [ 155.051663] ------------------------------------------------------ [ 155.051663] worker/4086 is trying to acquire lock: [ 155.051664] ffff8b6666daa090 ((lock).lock){+.+.}-{2:2}, at: radix_tree_maybe_preload+0x42/0x110 [ 155.051672] but task is already holding lock: [ 155.051673] ffff8b6520c945b8 (&xhci->lock){+.+.}-{0:0}, at: xhci_urb_enqueue+0x217/0x740 [xhci_hcd] [ 155.051683] which lock already depends on the new lock. [ 155.051683] the existing dependency chain (in reverse order) is: [ 155.051683] -> #2 (&xhci->lock){+.+.}-{0:0}: [ 155.051685] rt_spin_lock+0x2b/0xc0 [ 155.051687] xhci_irq+0x3f/0x540 [xhci_hcd] [ 155.051695] irq_forced_thread_fn+0x30/0x80 [ 155.051697] irq_thread+0xf7/0x1a0 [ 155.051698] kthread+0x16c/0x190 [ 155.051700] ret_from_fork+0x1f/0x30 [ 155.051702] -> #1 ((softirq_ctrl.lock).lock){+.+.}-{2:2}: [ 155.051703] rt_spin_lock+0x2b/0xc0 [ 155.051704] __local_bh_disable_ip+0x127/0x2c0 [ 155.051706] __do_sys_bpf+0x1959/0x1f50 [ 155.051708] do_syscall_64+0x33/0x40 [ 155.051710] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 155.051711] -> #0 ((lock).lock){+.+.}-{2:2}: [ 155.051712] __lock_acquire+0x149d/0x1a70 [ 155.051714] lock_acquire+0x1a7/0x410 [ 155.051716] rt_spin_lock+0x2b/0xc0 [ 155.051716] radix_tree_maybe_preload+0x42/0x110 [ 155.051718] xhci_update_stream_segment_mapping+0x63/0x190 [xhci_hcd] [ 155.051723] xhci_ring_expansion+0x19d/0x390 [xhci_hcd] [ 155.051728] prepare_ring+0x8b/0x1f0 [xhci_hcd] [ 155.051734] prepare_transfer+0x64/0x140 [xhci_hcd] [ 155.051739] xhci_queue_bulk_tx+0xe7/0xc50 [xhci_hcd] [ 155.051745] xhci_urb_enqueue+0x627/0x740 [xhci_hcd] [ 155.051750] usb_hcd_submit_urb+0xa7/0xac0 [usbcore] [ 155.051760] uas_submit_urbs+0x35b/0x500 [uas] [ 155.051762] uas_queuecommand+0x1d3/0x240 [uas] [ 155.051763] scsi_queue_rq+0x5e5/0xce0 [scsi_mod] [ 155.051772] blk_mq_dispatch_rq_list+0x291/0x6e0 [ 155.051774] __blk_mq_do_dispatch_sched+0x219/0x260 [ 155.051775] __blk_mq_sched_dispatch_requests+0x154/0x190 [ 155.051776] blk_mq_sched_dispatch_requests+0x33/0x60 [ 155.051777] __blk_mq_run_hw_queue+0x86/0xf0 [ 155.051779] __blk_mq_delay_run_hw_queue+0x135/0x180 [ 155.051781] blk_mq_run_hw_queue+0x70/0xe0 [ 155.051782] blk_mq_sched_insert_requests+0xdd/0x2a0 [ 155.051783] blk_mq_flush_plug_list+0x12d/0x2b0 [ 155.051784] blk_flush_plug_list+0xb4/0xd0 [ 155.051785] blk_mq_submit_bio+0x365/0x930 [ 155.051786] submit_bio_noacct+0x41e/0x4b0 [ 155.051786] submit_bio+0x33/0x160 [ 155.051787] ext4_mpage_readpages+0x1ad/0x930 [ext4] [ 155.051811] read_pages+0x7d/0x230 [ 155.051813] page_cache_ra_unbounded+0x13b/0x1f0 [ 155.051814] generic_file_buffered_read+0x144/0xa10 [ 155.051815] do_iter_readv_writev+0x182/0x1b0 [ 155.051817] do_iter_read+0xca/0x1c0 [ 155.051818] vfs_readv+0x6f/0xa0 [ 155.051819] do_preadv+0x9c/0xe0 [ 155.051820] do_syscall_64+0x33/0x40 [ 155.051822] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 155.051823] other info that might help us debug this: [ 155.051824] Chain exists of: (lock).lock --> (softirq_ctrl.lock).lock --> &xhci->lock [ 155.051825] Possible unsafe locking scenario: [ 155.051826] CPU0 CPU1 [ 155.051826] ---- ---- [ 155.051826] lock(&xhci->lock); [ 155.051827] lock((softirq_ctrl.lock).lock); [ 155.051828] lock(&xhci->lock); [ 155.051828] lock((lock).lock); [ 155.051829] *** DEADLOCK *** [ 155.051829] 7 locks held by worker/4086: [ 155.051830] #0: ffffffffbd59c8e0 (rcu_read_lock){....}-{1:2}, at: hctx_lock+0x17/0xe0 [ 155.051833] #1: ffff8b65201340c0 (shost->host_lock){+.+.}-{0:0}, at: uas_queuecommand+0x2b/0x240 [uas] [ 155.051837] #2: ffffffffbd59c8e0 (rcu_read_lock){....}-{1:2}, at: rt_spin_lock+0x5/0xc0 [ 155.051839] #3: ffff8b6520136010 (&devinfo->lock){+.+.}-{0:0}, at: uas_queuecommand+0xd7/0x240 [uas] [ 155.051841] #4: ffffffffbd59c8e0 (rcu_read_lock){....}-{1:2}, at: rt_spin_lock+0x5/0xc0 [ 155.051843] #5: ffff8b6520c945b8 (&xhci->lock){+.+.}-{0:0}, at: xhci_urb_enqueue+0x217/0x740 [xhci_hcd] [ 155.051850] #6: ffffffffbd59c8e0 (rcu_read_lock){....}-{1:2}, at: rt_spin_lock+0x5/0xc0 [ 155.051853] stack backtrace: [ 155.051853] CPU: 3 PID: 4086 Comm: worker Tainted: G S I E 5.10.0.g23859ae-rt1-rt #11 [ 155.051855] Hardware name: HP HP Spectre x360 Convertible/804F, BIOS F.47 11/22/2017 [ 155.051856] Call Trace: [ 155.051858] dump_stack+0x77/0x97 [ 155.051861] check_noncircular+0xe7/0x100 [ 155.051865] ? __lock_acquire+0x149d/0x1a70 [ 155.051867] __lock_acquire+0x149d/0x1a70 [ 155.051870] lock_acquire+0x1a7/0x410 [ 155.051872] ? radix_tree_maybe_preload+0x42/0x110 [ 155.051875] ? xhci_segment_alloc+0xd8/0x100 [xhci_hcd] [ 155.051880] rt_spin_lock+0x2b/0xc0 [ 155.051882] ? radix_tree_maybe_preload+0x42/0x110 [ 155.051883] radix_tree_maybe_preload+0x42/0x110 [ 155.051885] xhci_update_stream_segment_mapping+0x63/0x190 [xhci_hcd] [ 155.051891] xhci_ring_expansion+0x19d/0x390 [xhci_hcd] [ 155.051897] prepare_ring+0x8b/0x1f0 [xhci_hcd] [ 155.051903] prepare_transfer+0x64/0x140 [xhci_hcd] [ 155.051909] xhci_queue_bulk_tx+0xe7/0xc50 [xhci_hcd] [ 155.051919] xhci_urb_enqueue+0x627/0x740 [xhci_hcd] [ 155.051924] ? dma_map_sg_attrs+0x30/0x50 [ 155.051926] ? usb_hcd_map_urb_for_dma+0xc2/0x460 [usbcore] [ 155.051935] usb_hcd_submit_urb+0xa7/0xac0 [usbcore] [ 155.051942] ? mark_held_locks+0x49/0x70 [ 155.051944] ? _raw_spin_unlock_irqrestore+0x70/0x80 [ 155.051945] ? lockdep_hardirqs_on+0x85/0x110 [ 155.051947] ? _raw_spin_unlock_irqrestore+0x34/0x80 [ 155.051948] ? rt_mutex_futex_unlock+0x56/0x80 [ 155.051950] uas_submit_urbs+0x35b/0x500 [uas] [ 155.051952] ? sdev_evt_alloc+0x60/0x60 [scsi_mod] [ 155.051959] uas_queuecommand+0x1d3/0x240 [uas] [ 155.051962] scsi_queue_rq+0x5e5/0xce0 [scsi_mod] [ 155.051969] blk_mq_dispatch_rq_list+0x291/0x6e0 [ 155.051970] ? rt_mutex_futex_unlock+0x56/0x80 [ 155.051973] __blk_mq_do_dispatch_sched+0x219/0x260 [ 155.051976] __blk_mq_sched_dispatch_requests+0x154/0x190 [ 155.051978] blk_mq_sched_dispatch_requests+0x33/0x60 [ 155.051979] __blk_mq_run_hw_queue+0x86/0xf0 [ 155.051981] __blk_mq_delay_run_hw_queue+0x135/0x180 [ 155.051983] blk_mq_run_hw_queue+0x70/0xe0 [ 155.051985] blk_mq_sched_insert_requests+0xdd/0x2a0 [ 155.051987] blk_mq_flush_plug_list+0x12d/0x2b0 [ 155.051990] blk_flush_plug_list+0xb4/0xd0 [ 155.051992] blk_mq_submit_bio+0x365/0x930 [ 155.051994] submit_bio_noacct+0x41e/0x4b0 [ 155.051996] ? submit_bio+0x33/0x160 [ 155.051997] ? xa_load+0xb6/0x130 [ 155.051999] submit_bio+0x33/0x160 [ 155.052000] ? bio_add_page+0x29/0x70 [ 155.052002] ext4_mpage_readpages+0x1ad/0x930 [ext4] [ 155.052021] ? _raw_spin_unlock_irqrestore+0x70/0x80 [ 155.052022] ? lockdep_hardirqs_on+0x85/0x110 [ 155.052024] read_pages+0x7d/0x230 [ 155.052026] ? rcu_read_lock_sched_held+0x32/0x60 [ 155.052029] ? page_cache_ra_unbounded+0x13b/0x1f0 [ 155.052030] page_cache_ra_unbounded+0x13b/0x1f0 [ 155.052032] generic_file_buffered_read+0x144/0xa10 [ 155.052036] do_iter_readv_writev+0x182/0x1b0 [ 155.052038] do_iter_read+0xca/0x1c0 [ 155.052040] vfs_readv+0x6f/0xa0 [ 155.052043] ? __fget_files+0xf6/0x1f0 [ 155.052045] ? __fget_files+0x10e/0x1f0 [ 155.052047] ? do_preadv+0x9c/0xe0 [ 155.052048] do_preadv+0x9c/0xe0 [ 155.052049] do_syscall_64+0x33/0x40 [ 155.052051] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 155.052053] RIP: 0033:0x7f70da5adc83 [ 155.052055] Code: 49 89 ca b8 27 01 00 00 0f 05 48 3d 01 f0 ff ff 73 34 c3 48 83 ec 08 e8 fb 64 01 00 48 89 04 24 49 89 ca b8 27 01 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 41 65 01 00 48 89 d0 48 83 c4 08 48 3d 01 [ 155.052056] RSP: 002b:00007f70d2dbb850 EFLAGS: 00000293 ORIG_RAX: 0000000000000127 [ 155.052058] RAX: ffffffffffffffda RBX: 00007f6fa6ded6f0 RCX: 00007f70da5adc83 [ 155.052058] RDX: 0000000000000002 RSI: 00007f70b80f45d0 RDI: 000000000000000b [ 155.052059] RBP: 000055752e62e140 R08: 0000000000000000 R09: 00000000ffffffff [ 155.052059] R10: 000000015fd7e000 R11: 0000000000000293 R12: 000055752bfc36b0 [ 155.052060] R13: 000055752e62e1a8 R14: 00007f70b81a4540 R15: 00007ffe9e730b10
On 2020-10-29 11:23:25 [+0100], Mike Galbraith wrote: > Below, the aforementioned 5.10-rt splat in case that helps. > > [ 155.051826] CPU0 CPU1 > [ 155.051826] ---- ---- > [ 155.051826] lock(&xhci->lock); > [ 155.051827] lock((softirq_ctrl.lock).lock); > [ 155.051828] lock(&xhci->lock); > [ 155.051828] lock((lock).lock); > [ 155.051829] no, that is yet again different. Based on these lines the reason is most likely the same as in net/TCP you reported a few releases ago (RT specific). I need to consult core & locking overlords to figure out how we deal with this in future since is seems this cases pop up in packs. If you have more lockdep reports with softirq_ctrl.lock involved, please throw them at me. Sebastian
On Thu, 2020-10-29 at 11:41 +0200, Mathias Nyman wrote:
> Can you check if this can be reproduced with 5.9 kernel?
Nope, 5.9.2 didn't reproduce.
-Mike
On 29.10.2020 13.11, Mike Galbraith wrote: > On Thu, 2020-10-29 at 11:41 +0200, Mathias Nyman wrote: >> Can you check if this can be reproduced with 5.9 kernel? > > Nope, 5.9.2 didn't reproduce. > Very odd. It might be hard to reproduce as it requires xhci ring expansion to trigger it, meaning at some point there is so much data queued to a device the current ring buffer can't fit it. Other possibility is that there were some radix tree changes in 5.10-rc1, haven't looked into those. -Mathias
On 2020-10-29 13:22:20 [+0200], Mathias Nyman wrote: > On 29.10.2020 13.11, Mike Galbraith wrote: > > On Thu, 2020-10-29 at 11:41 +0200, Mathias Nyman wrote: > >> Can you check if this can be reproduced with 5.9 kernel? > > > > Nope, 5.9.2 didn't reproduce. > > > > Very odd. > It might be hard to reproduce as it requires xhci ring expansion to trigger it, > meaning at some point there is so much data queued to a device the current ring buffer > can't fit it. > > Other possibility is that there were some radix tree changes in 5.10-rc1, haven't looked into those. This came with commit 673d74683627b ("usb: xhci: add debugfs support for ep with stream") which is appeared in v5.10-rc1. This hunk below works around it: diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c index 482fe8c5e3b47..699777fb523b6 100644 --- a/drivers/usb/host/xhci.c +++ b/drivers/usb/host/xhci.c @@ -3533,11 +3533,13 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, struct usb_device *udev, xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", udev->slot_id, ep_index); vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); } xhci_free_command(xhci, config_cmd); spin_unlock_irqrestore(&xhci->lock, flags); + for (i = 0; i < num_eps; i++) + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); + /* Subtract 1 for stream 0, which drivers can't use */ return num_streams - 1; This makes the warning go away here, I'm not 100% sure that this okay. One thing I noticed: free_streams() does not remove the debugfs file so: | $ cd /sys/bus/usb/drivers/uas | $ echo 2-1:1.0 > bind | $ echo 2-1:1.0 > unbind and the kernel log shows: |sd 7:0:0:0: [sdb] Synchronizing SCSI cache |sd 7:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK |debugfs: File 'stream_id' in directory 'ep07' already present! |debugfs: File 'stream_context_array' in directory 'ep07' already present! |debugfs: File 'stream_id' in directory 'ep07' already present! |debugfs: File 'stream_context_array' in directory 'ep07' already present! |scsi host7: uas |scsi 7:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 |sd 7:0:0:0: Attached scsi generic sg2 type 0 |sd 7:0:0:0: [sdb] 262144 512-byte logical blocks: (134 MB/128 MiB) |sd 7:0:0:0: [sdb] Write Protect is off |sd 7:0:0:0: [sdb] Mode Sense: 63 00 00 08 |sd 7:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA |sd 7:0:0:0: [sdb] Attached SCSI disk > -Mathias Sebastian
> -----Original Message----- > From: Sebastian Andrzej Siewior <bigeasy@linutronix.de> > Sent: Thursday, October 29, 2020 7:38 PM > To: Mathias Nyman <mathias.nyman@linux.intel.com> > Cc: Mike Galbraith <efault@gmx.de>; gregkh@linuxfoundation.org; > linux-usb@vger.kernel.org; Hans de Goede <hdegoede@redhat.com>; Jun Li > <jun.li@nxp.com> > Subject: Re: [PATCH 3/3] xhci: Don't create stream debugfs files with spinlock > held. > > On 2020-10-29 13:22:20 [+0200], Mathias Nyman wrote: > > On 29.10.2020 13.11, Mike Galbraith wrote: > > > On Thu, 2020-10-29 at 11:41 +0200, Mathias Nyman wrote: > > >> Can you check if this can be reproduced with 5.9 kernel? > > > > > > Nope, 5.9.2 didn't reproduce. > > > > > > > Very odd. > > It might be hard to reproduce as it requires xhci ring expansion to > > trigger it, meaning at some point there is so much data queued to a > > device the current ring buffer can't fit it. > > > > Other possibility is that there were some radix tree changes in 5.10-rc1, > haven't looked into those. > > This came with commit > 673d74683627b ("usb: xhci: add debugfs support for ep with stream") > > which is appeared in v5.10-rc1. This hunk below works around it: > > diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c index > 482fe8c5e3b47..699777fb523b6 100644 > --- a/drivers/usb/host/xhci.c > +++ b/drivers/usb/host/xhci.c > @@ -3533,11 +3533,13 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, > struct usb_device *udev, > xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", > udev->slot_id, ep_index); > vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; > - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > } > xhci_free_command(xhci, config_cmd); > spin_unlock_irqrestore(&xhci->lock, flags); > > + for (i = 0; i < num_eps; i++) > + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > + > /* Subtract 1 for stream 0, which drivers can't use */ > return num_streams - 1; > > This makes the warning go away here, I'm not 100% sure that this okay. > One thing I noticed: free_streams() does not remove the debugfs file so: > | $ cd /sys/bus/usb/drivers/uas > | $ echo 2-1:1.0 > bind > | $ echo 2-1:1.0 > unbind > > and the kernel log shows: > |sd 7:0:0:0: [sdb] Synchronizing SCSI cache sd 7:0:0:0: [sdb] > |Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR > |driverbyte=DRIVER_OK > |debugfs: File 'stream_id' in directory 'ep07' already present! > |debugfs: File 'stream_context_array' in directory 'ep07' already present! > |debugfs: File 'stream_id' in directory 'ep07' already present! > |debugfs: File 'stream_context_array' in directory 'ep07' already present! > |scsi host7: uas > |scsi 7:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: > 5 > |sd 7:0:0:0: Attached scsi generic sg2 type 0 sd 7:0:0:0: [sdb] 262144 > |512-byte logical blocks: (134 MB/128 MiB) sd 7:0:0:0: [sdb] Write > |Protect is off sd 7:0:0:0: [sdb] Mode Sense: 63 00 00 08 sd 7:0:0:0: > |[sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or > |FUA sd 7:0:0:0: [sdb] Attached SCSI disk This is because your change is using wrong *ep_index* when create stream files, if you use the below patch from Mathias, you will not have this problem. diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c index 482fe8c5e3b4..d4a8d0efbbc4 100644 --- a/drivers/usb/host/xhci.c +++ b/drivers/usb/host/xhci.c @@ -3533,11 +3533,14 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, struct usb_device *udev, xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", udev->slot_id, ep_index); vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); } xhci_free_command(xhci, config_cmd); spin_unlock_irqrestore(&xhci->lock, flags); + for (i = 0; i < num_eps; i++) { + ep_index = xhci_get_endpoint_index(&eps[i]->desc); + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); + } /* Subtract 1 for stream 0, which drivers can't use */ return num_streams - 1; Li Jun > > > -Mathias > > Sebastian
On 29.10.2020 13.38, Sebastian Andrzej Siewior wrote: > On 2020-10-29 13:22:20 [+0200], Mathias Nyman wrote: >> On 29.10.2020 13.11, Mike Galbraith wrote: >>> On Thu, 2020-10-29 at 11:41 +0200, Mathias Nyman wrote: >>>> Can you check if this can be reproduced with 5.9 kernel? >>> >>> Nope, 5.9.2 didn't reproduce. >>> >> >> Very odd. >> It might be hard to reproduce as it requires xhci ring expansion to trigger it, >> meaning at some point there is so much data queued to a device the current ring buffer >> can't fit it. >> >> Other possibility is that there were some radix tree changes in 5.10-rc1, haven't looked into those. > > This came with commit > 673d74683627b ("usb: xhci: add debugfs support for ep with stream") > > which is appeared in v5.10-rc1. This hunk below works around it: > > diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c > index 482fe8c5e3b47..699777fb523b6 100644 > --- a/drivers/usb/host/xhci.c > +++ b/drivers/usb/host/xhci.c > @@ -3533,11 +3533,13 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, struct usb_device *udev, > xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", > udev->slot_id, ep_index); > vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; > - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > } > xhci_free_command(xhci, config_cmd); > spin_unlock_irqrestore(&xhci->lock, flags); > > + for (i = 0; i < num_eps; i++) > + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > + > /* Subtract 1 for stream 0, which drivers can't use */ > return num_streams - 1; > Sebastian, I think you might be missing the first mail in this thread. https://lore.kernel.org/linux-usb/20201028203124.375344-4-mathias.nyman@linux.intel.com/ Let me do a quick recap to avoid confusion here. So far we have 2 issues. 1. Lockdep issue #1, stream debugfs entry created with local interrupts disabled and xhci->lock held Cause: 673d74683627b ("usb: xhci: add debugfs support for ep with stream") in v5.10-rc1 Fix: [PATCH 3/3] xhci: Don't create stream debugfs files with spinlock held. (i.e. the mail we are replying to) Comment: easily reproduced, enable lockdep and uas, mount debugfs and connect a UAS device. discovered by both Hans and Mike . 2. Lockdep issue #2, adding entries to radix tree during (stream) ring expansion with interrupts disabled and xhci->lock held. Cause: unknown, probably a patch since we started using radix trees for finding streams Fix: unknown. Comment: Discovered by Mike when testing fix for issue#1. I suspect it can be reproduced on 5.9 but is probably really hard as it involves ring expansion. -Mathias
On 2020-10-29 15:08:06 [+0200], Mathias Nyman wrote: > Sebastian, I think you might be missing the first mail in this thread. thank you for clearing that up. > https://lore.kernel.org/linux-usb/20201028203124.375344-4-mathias.nyman@linux.intel.com/ > > Let me do a quick recap to avoid confusion here. So far we have 2 issues. > > 1. Lockdep issue #1, stream debugfs entry created with local interrupts disabled and xhci->lock held > Cause: 673d74683627b ("usb: xhci: add debugfs support for ep with stream") in v5.10-rc1 > Fix: [PATCH 3/3] xhci: Don't create stream debugfs files with spinlock held. (i.e. the mail we are replying to) > Comment: easily reproduced, enable lockdep and uas, mount debugfs and connect a UAS device. > discovered by both Hans and Mike > . > 2. Lockdep issue #2, adding entries to radix tree during (stream) ring expansion with interrupts disabled and xhci->lock held. > Cause: unknown, probably a patch since we started using radix trees for finding streams > Fix: unknown. > Comment: Discovered by Mike when testing fix for issue#1. I suspect it can be reproduced on 5.9 but is > probably really hard as it involves ring expansion. > > -Mathias Sebastian
From: Mathias Nyman > Sent: 29 October 2020 13:08 ... > 2. Lockdep issue #2, adding entries to radix tree during (stream) ring expansion with interrupts > disabled and xhci->lock held. > Cause: unknown, probably a patch since we started using radix trees for finding streams > Fix: unknown. > Comment: Discovered by Mike when testing fix for issue#1. > I suspect it can be reproduced on 5.9 but is > probably really hard as it involves ring expansion. ISTR thinking that code was allocating 'memory pages' in a place where (IIRC) vmalloc() wouldn't be allowed. I'd sort of assumed the allocation function was allowed. David - Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK Registration No: 1397386 (Wales)
On 2020-10-29 15:08:06 [+0200], Mathias Nyman wrote: > 2. Lockdep issue #2, adding entries to radix tree during (stream) ring expansion with interrupts disabled and xhci->lock held. > Cause: unknown, probably a patch since we started using radix trees for finding streams > Fix: unknown. > Comment: Discovered by Mike when testing fix for issue#1. I suspect it can be reproduced on 5.9 but is > probably really hard as it involves ring expansion. So lockdep complains with this: CPU0 CPU1 ---- ---- lock(lock#2); local_irq_disable(); lock(&xhci->lock); lock(lock#2); <Interrupt> lock(&xhci->lock); (https://lore.kernel.org/linux-usb/1cbb8b7defb1db1d4747995c11ebebb3dd9a66ec.camel@gmx.de/) lockdep does not like that preload is used with disabled interrupts (in non-interrupt context) and acquires lock#2 (the local_lock) which could lead to a dead-lock as described above. The flaw in the logic above is that lock#2 on CPU0 != CPU1. We could make lockdep happy and remove what it observes on CPU1 by doing this: diff --git a/drivers/usb/host/xhci-mem.c b/drivers/usb/host/xhci-mem.c index 138ba4528dd3a..2cb8874c1c51f 100644 --- a/drivers/usb/host/xhci-mem.c +++ b/drivers/usb/host/xhci-mem.c @@ -197,12 +197,15 @@ static int xhci_insert_segment_mapping(struct radix_tree_root *trb_address_map, if (radix_tree_lookup(trb_address_map, key)) return 0; - ret = radix_tree_maybe_preload(mem_flags); - if (ret) - return ret; - ret = radix_tree_insert(trb_address_map, - key, ring); - radix_tree_preload_end(); + if (gfpflags_allow_blocking(mem_flags)) { + ret = radix_tree_maybe_preload(mem_flags); + if (ret) + return ret; + } + ret = radix_tree_insert(trb_address_map, key, ring); + + if (gfpflags_allow_blocking(mem_flags)) + radix_tree_preload_end(); return ret; } There is no pre-load in GFP_ATOMIC case but it still acquires the local_lock. We might be able to drop radix_tree_maybe_preload(). I saw GFP_KERNEL only during enumeration from xhci_alloc_streams(). Later, while transfers were pending it came always from the scsi stack with disabled interrupts and xhci->lock acquired. > -Mathias Sebastian
> -----Original Message----- > From: Mathias Nyman <mathias.nyman@linux.intel.com> > Sent: Thursday, October 29, 2020 4:31 AM > To: gregkh@linuxfoundation.org > Cc: linux-usb@vger.kernel.org; Mathias Nyman > <mathias.nyman@linux.intel.com>; Hans de Goede <hdegoede@redhat.com>; Mike > Galbraith <efault@gmx.de>; Jun Li <jun.li@nxp.com> > Subject: [PATCH 3/3] xhci: Don't create stream debugfs files with spinlock > held. > > Creating debugfs files while loding the spin_lock_irqsave(xhci->lock) > creates a lock dependecy that could possibly deadlock. > > Lockdep warns: > > ===================================================== > WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected > 5.10.0-rc1pdx86+ #8 Not tainted > ----------------------------------------------------- > systemd-udevd/386 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: > ffffffffb1a94038 (pin_fs_lock){+.+.}-{2:2}, at: simple_pin_fs+0x22/0xa0 > > and this task is already holding: > ffff9e7b87fbc430 (&xhci->lock){-.-.}-{2:2}, at: > xhci_alloc_streams+0x5f9/0x810 which would create a new lock dependency: > (&xhci->lock){-.-.}-{2:2} -> (pin_fs_lock){+.+.}-{2:2} > > Create the files a bit later after lock is released. > > Reported-by: Hans de Goede <hdegoede@redhat.com> > Reported-by: Mike Galbraith <efault@gmx.de> > Tested-by: Hans de Goede <hdegoede@redhat.com> > CC: Li Jun <jun.li@nxp.com> > Fixes: 673d74683627 ("usb: xhci: add debugfs support for ep with stream") > Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com> Reviewed-and-tested-by: Li Jun <jun.li@nxp.com> > --- > drivers/usb/host/xhci.c | 5 ++++- > 1 file changed, 4 insertions(+), 1 deletion(-) > > diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c index > 482fe8c5e3b4..d4a8d0efbbc4 100644 > --- a/drivers/usb/host/xhci.c > +++ b/drivers/usb/host/xhci.c > @@ -3533,11 +3533,14 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, > struct usb_device *udev, > xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", > udev->slot_id, ep_index); > vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; > - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > } > xhci_free_command(xhci, config_cmd); > spin_unlock_irqrestore(&xhci->lock, flags); > > + for (i = 0; i < num_eps; i++) { > + ep_index = xhci_get_endpoint_index(&eps[i]->desc); > + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); > + } > /* Subtract 1 for stream 0, which drivers can't use */ > return num_streams - 1; > > -- > 2.25.1
===================================================== WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected 5.10.0-rc1pdx86+ #8 Not tainted ----------------------------------------------------- systemd-udevd/386 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: ffffffffb1a94038 (pin_fs_lock){+.+.}-{2:2}, at: simple_pin_fs+0x22/0xa0 and this task is already holding: ffff9e7b87fbc430 (&xhci->lock){-.-.}-{2:2}, at: xhci_alloc_streams+0x5f9/0x810 which would create a new lock dependency: (&xhci->lock){-.-.}-{2:2} -> (pin_fs_lock){+.+.}-{2:2} Create the files a bit later after lock is released. Reported-by: Hans de Goede <hdegoede@redhat.com> Reported-by: Mike Galbraith <efault@gmx.de> Tested-by: Hans de Goede <hdegoede@redhat.com> CC: Li Jun <jun.li@nxp.com> Fixes: 673d74683627 ("usb: xhci: add debugfs support for ep with stream") Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com> --- drivers/usb/host/xhci.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c index 482fe8c5e3b4..d4a8d0efbbc4 100644 --- a/drivers/usb/host/xhci.c +++ b/drivers/usb/host/xhci.c @@ -3533,11 +3533,14 @@ static int xhci_alloc_streams(struct usb_hcd *hcd, struct usb_device *udev, xhci_dbg(xhci, "Slot %u ep ctx %u now has streams.\n", udev->slot_id, ep_index); vdev->eps[ep_index].ep_state |= EP_HAS_STREAMS; - xhci_debugfs_create_stream_files(xhci, vdev, ep_index); } xhci_free_command(xhci, config_cmd); spin_unlock_irqrestore(&xhci->lock, flags); + for (i = 0; i < num_eps; i++) { + ep_index = xhci_get_endpoint_index(&eps[i]->desc); + xhci_debugfs_create_stream_files(xhci, vdev, ep_index); + } /* Subtract 1 for stream 0, which drivers can't use */ return num_streams - 1;