Why does it take so long to detect an usb stick?
Turns out that there's a 1 second timeout int drivers/usb/storage/usb.c. I enabled more debug-logging by typing the following two commands:
echo 8 > /proc/sys/kernel/printk
echo "module usb_storage +p" > /sys/kernel/debug/dynamic_debug/control
echo 0xFFFFFF > /proc/sys/dev/scsi/logging_level
The scsi subsystem has a weird (compared to the rest of the linux logging fascilities) way of specifying log levels; they're bits shifted one step for each level, see drivers/scsi/scsi_logging.h
See the line starting scan
below. The kernel waits 1 second before doing the scan.
[21960.837879 < 23.040778>] usb 2-1.2: USB disconnect, device number 18
[21960.838263 < 0.000384>] sd 20:0:0:0: [sg2] sg_remove_device
[21960.838888 < 0.000625>] sd 20:0:0:0: [sg2] sg_device_destroy
[21966.157918 < 5.319030>] usb 2-1.2: new high-speed USB device number 19 using ehci-pci
[21966.251625 < 0.093707>] usb 2-1.2: New USB device found, idVendor=0781, idProduct=5530
[21966.251634 < 0.000009>] usb 2-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[21966.251638 < 0.000004>] usb 2-1.2: Product: Firebird USB Flash Drive
[21966.251641 < 0.000003>] usb 2-1.2: Manufacturer: SanDisk
[21966.251644 < 0.000003>] usb 2-1.2: SerialNumber: 4C532000001215110130
[21966.252184 < 0.000540>] usb-storage 2-1.2:1.0: USB Mass Storage device detected
[21966.252307 < 0.000123>] scsi host21: usb-storage 2-1.2:1.0
[21966.252439 < 0.000132>] usb-storage 2-1.2:1.0: waiting for device to settle before scanning
[21967.250018 < 0.997579>] usb-storage 2-1.2:1.0: starting scan
[21967.250242 < 0.000224>] usb-storage 2-1.2:1.0: scan complete
[21967.250295 < 0.000053>] scsi host21: scsi_scan_host_selected: <4294967295:4294967295:18446744073709551615>
[21967.250354 < 0.000059>] scsi 21:0:0:0: scsi scan: INQUIRY pass 1 length 36
[21967.251717 < 0.001363>] scsi 21:0:0:0: scsi scan: INQUIRY successful with code 0x0
[21967.251738 < 0.000021>] scsi 21:0:0:0: Direct-Access SanDisk Cruzer 1.26 PQ: 0 ANSI: 5
[21967.251745 < 0.000007>] scsi target21:0:0: scsi scan: Sequential scan
[21967.251776 < 0.000031>] scsi 21:0:0:1: scsi scan: INQUIRY pass 1 length 36
[21967.251907 < 0.000131>] scsi 21:0:0:1: scsi scan: INQUIRY failed with code 0x40000
[21967.252282 < 0.000375>] sd 21:0:0:0: sg_alloc: dev=2
[21967.252366 < 0.000084>] sd 21:0:0:0: Attached scsi generic sg2 type 0
[21967.253703 < 0.001337>] sd 21:0:0:0: [sdb] 7821312 512-byte logical blocks: (4.00 GB/3.72 GiB)
[21967.255324 < 0.001621>] sd 21:0:0:0: [sdb] Write Protect is off
[21967.255334 < 0.000010>] sd 21:0:0:0: [sdb] Mode Sense: 43 00 00 00
[21967.258145 < 0.002811>] sd 21:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[21967.272208 < 0.014063>] sdb: sdb1
[21967.276433 < 0.004225>] sd 21:0:0:0: [sdb] Attached SCSI removable disk
Linus Torvalds changed the default delay from 5 to 1 seconds in Lower USB storage settling delay to something more reasonable. He does not provide any context on the technical reasons for why the delay was set so high, but hints that it may have just masqueraded some kernel bugs.
You can change the timeout by writing to /sys/module/usb_storage/parameters/delay_use
.
For older usb disks, a settle delay of 5 seconds or even more may be needed (and 5 was the default until it was reduced to 1 second in 2010), presumably because the controller is starved of power while the disk motors are initializing. Or possibly because the internal SCSI firmware takes time to boot up before it's responsive (can you tell I'm just speculating here?).
For modern solid-state storage, it's probably not needed at all, and many people set it to 0. Unfortunately, it's a global parameter that applies to all devices, so if you have any slow devices at all, you have to endure the delay for every mass-storage USB device you use. It would be nice if it could be set per-device by udev, but that's not the case.