7

I'm writing an initramfs-script and want to detect usb-sticks as fast as possible.

When I insert an usb 2.0 stick, the detection of idVendor, idProduct and USB class happens within 100 ms. But the scsi subsystem does not "attach" until about 1 s has passed and it takes another 500 ms before the partition is fully recognized.

I assume that the driver needs to read the partition table in order to detect partitions. Why does it take so long? I don't expect the urb send/recev time to be that long or the access time of the flash to take so much time.

I've tried 5 sticks from different vendors and the result is about the same.

[ 5731.097540] usb 2-1.2: new high-speed USB device number 7 using ehci-pci
[ 5731.195360] usb 2-1.2: New USB device found, idVendor=0951, idProduct=1643
[ 5731.195368] usb 2-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 5731.195372] usb 2-1.2: Product: DataTraveler G3
[ 5731.195376] usb 2-1.2: Manufacturer: Kingston
[ 5731.195379] usb 2-1.2: SerialNumber: 001CC0EC32BCBBB04712022C
[ 5731.196942] usb-storage 2-1.2:1.0: USB Mass Storage device detected
[ 5731.197193] scsi host9: usb-storage 2-1.2:1.0
[ 5732.268389] scsi 9:0:0:0: Direct-Access     Kingston DataTraveler G3  PMAP PQ: 0 ANSI: 0 CCS
[ 5732.268995] sd 9:0:0:0: Attached scsi generic sg2 type 0
[ 5732.883939] sd 9:0:0:0: [sdb] 7595520 512-byte logical blocks: (3.88 GB/3.62 GiB)
[ 5732.884565] sd 9:0:0:0: [sdb] Write Protect is off
[ 5732.884568] sd 9:0:0:0: [sdb] Mode Sense: 23 00 00 00
[ 5732.885178] sd 9:0:0:0: [sdb] No Caching mode page found
[ 5732.885181] sd 9:0:0:0: [sdb] Assuming drive cache: write through
[ 5732.903834]  sdb: sdb1
[ 5732.906812] sd 9:0:0:0: [sdb] Attached SCSI removable disk

Edit So I've found the delay_use module parameter that by default is set to 1 second, which explains the delay I'm seeing. But I'm wondering if someone can provide context as to why that parameter is needed? A comment suggested that for older usb sticks, delay_use might need to be set to as much as 5 seconds. What is it inside the usb stick that takes so much time; firmware initialization; reads from the flash? I find it hard to belive that we need delays as long as 1 second or more when the latency for accessing flash is in the order of tens of microseconds.

I realize that this might be slightly off-topic for this channel, if so, I'll go to electronics.stackexchange.com

5

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.

9

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.

  • 2
    Not only that, but you can change the timeout (by writing to /sys/module/usb_storage/parameters/delay_use). For older usb disks, a settle delay of up to 5 seconds may be needed, but for modern solid-state storage, it's probably not needed at all. Unfortunately, the kernel can't know that until it's too late to be useful! – Toby Speight Feb 24 '16 at 17:05
  • @TobySpeight If you provide that as a separate answer with some more context on why the settle dealy might need to be in order of seconds, then I'll happily accept your answer. See the edit I did to the question asking for more context. – Daniel Näslund Feb 25 '16 at 7:27
  • @dannas were you going to accept the answer as you said? You're leaving us all in suspense :). – msouth Feb 2 '17 at 4:21

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.