Greetings, I was moving a large number of files between 2 USB HDDs in Gnome's Nautilus, and after a while (at about 90%) I noticed the operation was becoming very slow, with writeback speeds from /proc/meminfo of about 30-40 kb/sec. I found this in dmesg (more call traces are being generated right now as the operation is still in progress): [15792.910568] usb 3-1: reset SuperSpeed USB device number 7 using xhci_hcd [15792.929371] scsi host3: uas_eh_bus_reset_handler success [15823.915754] sd 3:0:0:0: [sdb] tag#27 uas_eh_abort_handler 0 uas-tag 28 inflight: CMD OUT [15823.915760] sd 3:0:0:0: [sdb] tag#27 CDB: opcode=0x2a 2a 00 43 df b1 00 00 02 e0 00 [15823.915929] scsi host3: uas_eh_bus_reset_handler start [15823.918343] sd 3:0:0:0: [sdb] tag#0 uas_zap_pending 0 uas-tag 1 inflight: CMD [15823.918346] sd 3:0:0:0: [sdb] tag#0 CDB: opcode=0x2a 2a 00 43 da 2d 00 00 04 00 00 [15823.918350] sd 3:0:0:0: [sdb] tag#1 uas_zap_pending 0 uas-tag 2 inflight: CMD [15823.918351] sd 3:0:0:0: [sdb] tag#1 CDB: opcode=0x2a 2a 00 43 d9 b1 00 00 02 e0 00 [15823.918354] sd 3:0:0:0: [sdb] tag#2 uas_zap_pending 0 uas-tag 3 inflight: CMD [15823.918356] sd 3:0:0:0: [sdb] tag#2 CDB: opcode=0x2a 2a 00 43 d9 ad 00 00 04 00 00 [15823.918358] sd 3:0:0:0: [sdb] tag#3 uas_zap_pending 0 uas-tag 4 inflight: CMD [15823.918360] sd 3:0:0:0: [sdb] tag#3 CDB: opcode=0x2a 2a 00 43 d9 31 00 00 02 e0 00 [15823.918362] sd 3:0:0:0: [sdb] tag#4 uas_zap_pending 0 uas-tag 5 inflight: CMD [15823.918364] sd 3:0:0:0: [sdb] tag#4 CDB: opcode=0x2a 2a 00 43 d9 2d 00 00 04 00 00 [15823.918366] sd 3:0:0:0: [sdb] tag#5 uas_zap_pending 0 uas-tag 6 inflight: CMD [15823.918368] sd 3:0:0:0: [sdb] tag#5 CDB: opcode=0x2a 2a 00 43 d8 b1 00 00 02 e0 00 [15823.918370] sd 3:0:0:0: [sdb] tag#6 uas_zap_pending 0 uas-tag 7 inflight: CMD [15823.918372] sd 3:0:0:0: [sdb] tag#6 CDB: opcode=0x2a 2a 00 43 d8 ad 00 00 04 00 00 [15823.918374] sd 3:0:0:0: [sdb] tag#7 uas_zap_pending 0 uas-tag 8 inflight: CMD [15823.918376] sd 3:0:0:0: [sdb] tag#7 CDB: opcode=0x2a 2a 00 43 da 31 00 00 02 e0 00 [15823.918378] sd 3:0:0:0: [sdb] tag#8 uas_zap_pending 0 uas-tag 9 inflight: CMD [15823.918380] sd 3:0:0:0: [sdb] tag#8 CDB: opcode=0x2a 2a 00 43 db 31 00 00 02 e0 00 [15823.918383] sd 3:0:0:0: [sdb] tag#9 uas_zap_pending 0 uas-tag 10 inflight: CMD [15823.918384] sd 3:0:0:0: [sdb] tag#9 CDB: opcode=0x2a 2a 00 43 db 2d 00 00 04 00 00 [15823.918387] sd 3:0:0:0: [sdb] tag#10 uas_zap_pending 0 uas-tag 11 inflight: CMD [15823.918389] sd 3:0:0:0: [sdb] tag#10 CDB: opcode=0x2a 2a 00 43 da b1 00 00 02 e0 00 [15823.918391] sd 3:0:0:0: [sdb] tag#11 uas_zap_pending 0 uas-tag 12 inflight: CMD [15823.918393] sd 3:0:0:0: [sdb] tag#11 CDB: opcode=0x2a 2a 00 43 da ad 00 00 04 00 00 [15823.918395] sd 3:0:0:0: [sdb] tag#12 uas_zap_pending 0 uas-tag 13 inflight: CMD [15823.918397] sd 3:0:0:0: [sdb] tag#12 CDB: opcode=0x2a 2a 00 43 dc ad 00 00 04 00 00 [15823.918399] sd 3:0:0:0: [sdb] tag#13 uas_zap_pending 0 uas-tag 14 inflight: CMD [15823.918401] sd 3:0:0:0: [sdb] tag#13 CDB: opcode=0x2a 2a 00 43 dc 31 00 00 02 e0 00 [15823.918404] sd 3:0:0:0: [sdb] tag#14 uas_zap_pending 0 uas-tag 15 inflight: CMD [15823.918405] sd 3:0:0:0: [sdb] tag#14 CDB: opcode=0x2a 2a 00 43 dc 2d 00 00 04 00 00 [15823.918408] sd 3:0:0:0: [sdb] tag#15 uas_zap_pending 0 uas-tag 16 inflight: CMD [15823.918410] sd 3:0:0:0: [sdb] tag#15 CDB: opcode=0x2a 2a 00 43 db b1 00 00 02 e0 00 [15823.918412] sd 3:0:0:0: [sdb] tag#16 uas_zap_pending 0 uas-tag 17 inflight: CMD [15823.918414] sd 3:0:0:0: [sdb] tag#16 CDB: opcode=0x2a 2a 00 43 db ad 00 00 04 00 00 [15823.918416] sd 3:0:0:0: [sdb] tag#17 uas_zap_pending 0 uas-tag 18 inflight: CMD [15823.918418] sd 3:0:0:0: [sdb] tag#17 CDB: opcode=0x2a 2a 00 43 dc b1 00 00 02 e0 00 [15823.918420] sd 3:0:0:0: [sdb] tag#18 uas_zap_pending 0 uas-tag 19 inflight: CMD [15823.918422] sd 3:0:0:0: [sdb] tag#18 CDB: opcode=0x2a 2a 00 43 df 31 00 00 02 e0 00 [15823.918424] sd 3:0:0:0: [sdb] tag#19 uas_zap_pending 0 uas-tag 20 inflight: CMD [15823.918426] sd 3:0:0:0: [sdb] tag#19 CDB: opcode=0x2a 2a 00 43 df 2d 00 00 04 00 00 [15823.918428] sd 3:0:0:0: [sdb] tag#20 uas_zap_pending 0 uas-tag 21 inflight: CMD [15823.918430] sd 3:0:0:0: [sdb] tag#20 CDB: opcode=0x2a 2a 00 43 de b1 00 00 02 e0 00 [15823.918432] sd 3:0:0:0: [sdb] tag#21 uas_zap_pending 0 uas-tag 22 inflight: CMD [15823.918434] sd 3:0:0:0: [sdb] tag#21 CDB: opcode=0x2a 2a 00 43 de ad 00 00 04 00 00 [15823.918436] sd 3:0:0:0: [sdb] tag#22 uas_zap_pending 0 uas-tag 23 inflight: CMD [15823.918438] sd 3:0:0:0: [sdb] tag#22 CDB: opcode=0x2a 2a 00 43 de 2d 00 00 00 08 00 [15823.918440] sd 3:0:0:0: [sdb] tag#23 uas_zap_pending 0 uas-tag 24 inflight: CMD [15823.918442] sd 3:0:0:0: [sdb] tag#23 CDB: opcode=0x2a 2a 00 43 dd b1 00 00 02 e0 00 [15823.918444] sd 3:0:0:0: [sdb] tag#24 uas_zap_pending 0 uas-tag 25 inflight: CMD [15823.918446] sd 3:0:0:0: [sdb] tag#24 CDB: opcode=0x2a 2a 00 43 dd ad 00 00 04 00 00 [15823.918448] sd 3:0:0:0: [sdb] tag#25 uas_zap_pending 0 uas-tag 26 inflight: CMD [15823.918450] sd 3:0:0:0: [sdb] tag#25 CDB: opcode=0x2a 2a 00 43 dd 2d 00 00 00 08 00 [15823.918452] sd 3:0:0:0: [sdb] tag#26 uas_zap_pending 0 uas-tag 27 inflight: CMD [15823.918454] sd 3:0:0:0: [sdb] tag#26 CDB: opcode=0x2a 2a 00 43 df ad 00 00 04 00 00 [15824.032772] usb 3-1: reset SuperSpeed USB device number 7 using xhci_hcd [15824.051935] scsi host3: uas_eh_bus_reset_handler success [16313.923750] sd 3:0:0:0: [sdb] tag#9 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD [16313.923754] sd 3:0:0:0: [sdb] tag#9 CDB: opcode=0x85 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00 [16319.727453] usb 3-1: stat urb: no pending cmd for uas-tag 10 [16327.491170] scsi host3: uas_eh_bus_reset_handler start [16327.603538] usb 3-1: reset SuperSpeed USB device number 7 using xhci_hcd [16327.622564] scsi host3: uas_eh_bus_reset_handler success [16327.622640] sd 3:0:0:0: [sdb] tag#9 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x06 [16327.622645] sd 3:0:0:0: [sdb] tag#9 CDB: opcode=0x85 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00 [16876.459418] [drm:intel_set_cpu_fifo_underrun_reporting [i915]] *ERROR* uncleared fifo underrun on pipe A [16876.459456] [drm:intel_cpu_fifo_underrun_irq_handler [i915]] *ERROR* CPU pipe A FIFO underrun [16906.754556] sd 3:0:0:0: [sdb] tag#2 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD [16906.754562] sd 3:0:0:0: [sdb] tag#2 CDB: opcode=0x85 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00 [16912.858634] usb 3-1: stat urb: no pending cmd for uas-tag 3 [16917.927923] scsi host3: uas_eh_bus_reset_handler start [16918.041136] usb 3-1: reset SuperSpeed USB device number 7 using xhci_hcd [16918.060164] scsi host3: uas_eh_bus_reset_handler success [16918.060240] sd 3:0:0:0: [sdb] tag#2 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x06 [16918.060245] sd 3:0:0:0: [sdb] tag#2 CDB: opcode=0x85 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00 [17079.321362] INFO: task kworker/u16:70:22677 blocked for more than 120 seconds. [17079.321368] Tainted: G U 4.12.8-2-ARCH #1 [17079.321370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [17079.321374] kworker/u16:70 D 0 22677 2 0x00000000 [17079.321394] Workqueue: writeback wb_workfn (flush-8:16) [17079.321401] Call Trace: [17079.321414] __schedule+0x236/0x870 [17079.321422] schedule+0x3d/0x90 [17079.321428] io_schedule+0x16/0x40 [17079.321435] get_request+0x264/0x790 [17079.321443] ? ioc_lookup_icq+0x50/0x70 [17079.321451] ? wake_bit_function+0x60/0x60 [17079.321458] blk_queue_bio+0x11f/0x420 [17079.321464] generic_make_request+0x11e/0x2f0 [17079.321471] submit_bio+0x73/0x150 [17079.321476] ? submit_bio+0x73/0x150 [17079.321484] submit_bh_wbc+0x13c/0x160 [17079.321491] __block_write_full_page+0x170/0x390 [17079.321495] ? I_BDEV+0x20/0x20 [17079.321500] ? touch_buffer+0x70/0x70 [17079.321505] block_write_full_page+0xe8/0x130 [17079.321511] blkdev_writepage+0x18/0x20 [17079.321517] __writepage+0x13/0x30 [17079.321523] write_cache_pages+0x1f3/0x4e0 [17079.321529] ? wb_position_ratio+0x1e0/0x1e0 [17079.321536] generic_writepages+0x5c/0x90 [17079.321542] blkdev_writepages+0xe/0x10 [17079.321547] ? blkdev_writepages+0xe/0x10 [17079.321550] do_writepages+0x48/0xd0 [17079.321556] ? ktime_get+0x40/0xa0 [17079.321563] __writeback_single_inode+0x45/0x390 [17079.321567] ? __writeback_single_inode+0x45/0x390 [17079.321573] writeback_sb_inodes+0x201/0x510 [17079.321580] __writeback_inodes_wb+0x67/0xb0 [17079.321585] wb_writeback+0x29b/0x340 [17079.321591] wb_workfn+0x1ac/0x3c0 [17079.321595] ? wb_workfn+0x1ac/0x3c0 [17079.321601] process_one_work+0x1de/0x430 [17079.321604] worker_thread+0x47/0x3f0 [17079.321610] kthread+0x125/0x140 [17079.321613] ? process_one_work+0x430/0x430 [17079.321618] ? kthread_create_on_node+0x70/0x70 [17079.321624] ret_from_fork+0x25/0x30 [17079.321633] INFO: task kworker/u16:2:27517 blocked for more than 120 seconds. [17079.321636] Tainted: G U 4.12.8-2-ARCH #1 [17079.321637] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [17079.321639] kworker/u16:2 D 0 27517 2 0x00000000 [17079.321649] Workqueue: events_freezable_power_ disk_events_workfn [17079.321652] Call Trace: [17079.321657] __schedule+0x236/0x870 [17079.321661] schedule+0x3d/0x90 [17079.321664] io_schedule+0x16/0x40 [17079.321667] get_request+0x264/0x790 [17079.321672] ? wake_bit_function+0x60/0x60 [17079.321677] blk_get_request+0x80/0xe0 [17079.321689] scsi_execute+0x40/0x270 [scsi_mod] [17079.321698] scsi_test_unit_ready+0x60/0xe0 [scsi_mod] [17079.321706] sd_check_events+0x119/0x170 [sd_mod] [17079.321712] disk_check_events+0x62/0x140 [17079.321719] disk_events_workfn+0x16/0x20 [17079.321722] process_one_work+0x1de/0x430 [17079.321725] worker_thread+0x47/0x3f0 [17079.321731] kthread+0x125/0x140 [17079.321734] ? process_one_work+0x430/0x430 [17079.321738] ? kthread_create_on_node+0x70/0x70 [17079.321743] ret_from_fork+0x25/0x30 [17325.072099] INFO: task kworker/u16:70:22677 blocked for more than 120 seconds. [17325.072104] Tainted: G U 4.12.8-2-ARCH #1 [17325.072106] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [17325.072108] kworker/u16:70 D 0 22677 2 0x00000000 [17325.072127] Workqueue: writeback wb_workfn (flush-8:16) [17325.072132] Call Trace: [17325.072144] __schedule+0x236/0x870 [17325.072149] schedule+0x3d/0x90 [17325.072155] io_schedule+0x16/0x40 [17325.072161] get_request+0x264/0x790 [17325.072169] ? ioc_lookup_icq+0x50/0x70 [17325.072177] ? wake_bit_function+0x60/0x60 [17325.072182] blk_queue_bio+0x11f/0x420 [17325.072187] generic_make_request+0x11e/0x2f0 [17325.072192] submit_bio+0x73/0x150 [17325.072196] ? submit_bio+0x73/0x150 [17325.072203] submit_bh_wbc+0x13c/0x160 [17325.072209] __block_write_full_page+0x170/0x390 [17325.072214] ? I_BDEV+0x20/0x20 [17325.072219] ? touch_buffer+0x70/0x70 [17325.072224] block_write_full_page+0xe8/0x130 [17325.072230] blkdev_writepage+0x18/0x20 [17325.072237] __writepage+0x13/0x30 [17325.072243] write_cache_pages+0x1f3/0x4e0 [17325.072249] ? wb_position_ratio+0x1e0/0x1e0 [17325.072257] generic_writepages+0x5c/0x90 [17325.072263] blkdev_writepages+0xe/0x10 [17325.072268] ? blkdev_writepages+0xe/0x10 [17325.072272] do_writepages+0x48/0xd0 [17325.072278] ? _raw_spin_unlock_irqrestore+0x15/0x30 [17325.072288] ? uas_queuecommand+0xb7/0x2b0 [uas] [17325.072294] __writeback_single_inode+0x45/0x390 [17325.072299] ? __writeback_single_inode+0x45/0x390 [17325.072305] writeback_sb_inodes+0x201/0x510 [17325.072312] __writeback_inodes_wb+0x67/0xb0 [17325.072318] wb_writeback+0x29b/0x340 [17325.072324] wb_workfn+0xb3/0x3c0 [17325.072329] ? wb_workfn+0xb3/0x3c0 [17325.072335] process_one_work+0x1de/0x430 [17325.072339] worker_thread+0x47/0x3f0 [17325.072345] kthread+0x125/0x140 [17325.072349] ? process_one_work+0x430/0x430 [17325.072353] ? kthread_create_on_node+0x70/0x70 [17325.072360] ret_from_fork+0x25/0x30 (previously reported at https://bugzilla.kernel.org/show_bug.cgi?id=196825) Thanks, raoul -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
