Ubuntu
udev package

vol_id takes way too long to finish on unavailable SCSI devices

Bug #156184 reported by Tore Anderson
2
Affects Status Importance Assigned to Milestone
udev (Ubuntu)
Fix Released
Low
Unassigned

Bug Description

root@cuba:~# time /lib/udev/vol_id --export /dev/sdb

real 1m36.796s
user 0m0.000s
sys 0m0.000s

/dev/sdb represents a path to a passive controller on a Sun StorageTek 6140, and are to be handled by dm-multipath. All I/O to the paths to the passive controller will fail until the volume is relocated to it (and at that point the formerly active controller will fail all I/O in the same manner).

This is logged during the vol_id run:

Oct 23 12:30:17 cuba kernel: [11390.027649] end_request: I/O error, dev sdb, sector 157286272
Oct 23 12:30:17 cuba kernel: [11390.039112] Buffer I/O error on device sdb, logical block 19660784
Oct 23 12:30:20 cuba kernel: [11393.044316] end_request: I/O error, dev sdb, sector 157286392
Oct 23 12:30:20 cuba kernel: [11393.055779] Buffer I/O error on device sdb, logical block 19660799
Oct 23 12:30:23 cuba kernel: [11396.061094] end_request: I/O error, dev sdb, sector 157286392
Oct 23 12:30:23 cuba kernel: [11396.072553] Buffer I/O error on device sdb, logical block 19660799
Oct 23 12:30:26 cuba kernel: [11399.079500] end_request: I/O error, dev sdb, sector 157286392
Oct 23 12:30:26 cuba kernel: [11399.090957] Buffer I/O error on device sdb, logical block 19660799
Oct 23 12:30:29 cuba kernel: [11402.113530] end_request: I/O error, dev sdb, sector 157286392
Oct 23 12:30:29 cuba kernel: [11402.124993] Buffer I/O error on device sdb, logical block 19660799
Oct 23 12:30:32 cuba kernel: [11405.130144] end_request: I/O error, dev sdb, sector 157286392
Oct 23 12:30:32 cuba kernel: [11405.141602] Buffer I/O error on device sdb, logical block 19660799
Oct 23 12:30:35 cuba kernel: [11408.148862] end_request: I/O error, dev sdb, sector 157286336
Oct 23 12:30:35 cuba kernel: [11408.160345] Buffer I/O error on device sdb, logical block 19660792
Oct 23 12:30:38 cuba kernel: [11411.167363] end_request: I/O error, dev sdb, sector 157286384
Oct 23 12:30:38 cuba kernel: [11411.178824] Buffer I/O error on device sdb, logical block 19660798
Oct 23 12:30:41 cuba kernel: [11414.186536] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:41 cuba kernel: [11414.196612] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:44 cuba kernel: [11417.202231] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:44 cuba kernel: [11417.212306] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:47 cuba kernel: [11420.219020] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:47 cuba kernel: [11420.229103] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:50 cuba kernel: [11423.237633] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:50 cuba kernel: [11423.247706] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:53 cuba kernel: [11426.255198] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:53 cuba kernel: [11426.265270] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:56 cuba kernel: [11429.271366] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:56 cuba kernel: [11429.281440] Buffer I/O error on device sdb, logical block 0
Oct 23 12:30:59 cuba kernel: [11432.286377] end_request: I/O error, dev sdb, sector 0
Oct 23 12:30:59 cuba kernel: [11432.296453] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:02 cuba kernel: [11435.301055] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:02 cuba kernel: [11435.311128] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:05 cuba kernel: [11438.315190] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:05 cuba kernel: [11438.325260] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:08 cuba kernel: [11441.348733] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:08 cuba kernel: [11441.358805] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:11 cuba kernel: [11444.363694] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:11 cuba kernel: [11444.373771] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:14 cuba kernel: [11447.408236] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:14 cuba kernel: [11447.418309] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:17 cuba kernel: [11450.434998] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:17 cuba kernel: [11450.445073] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:20 cuba kernel: [11453.448893] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:20 cuba kernel: [11453.458965] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:23 cuba kernel: [11456.464670] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:23 cuba kernel: [11456.474741] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:26 cuba kernel: [11459.486188] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:29 cuba kernel: [11462.496979] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:29 cuba kernel: [11462.507052] printk: 1 messages suppressed.
Oct 23 12:31:29 cuba kernel: [11462.507055] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:33 cuba kernel: [11465.511830] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:33 cuba kernel: [11465.521906] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:36 cuba kernel: [11468.534604] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:39 cuba kernel: [11471.538092] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:39 cuba kernel: [11471.548187] printk: 1 messages suppressed.
Oct 23 12:31:39 cuba kernel: [11471.548189] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:42 cuba kernel: [11474.556949] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:45 cuba kernel: [11477.559427] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:45 cuba kernel: [11477.569498] printk: 1 messages suppressed.
Oct 23 12:31:45 cuba kernel: [11477.569499] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:48 cuba kernel: [11480.588067] end_request: I/O error, dev sdb, sector 0
Oct 23 12:31:48 cuba kernel: [11480.598138] Buffer I/O error on device sdb, logical block 0
Oct 23 12:31:51 cuba kernel: [11483.601854] end_request: I/O error, dev sdb, sector 0

Compare this to a fdisk test to the same device:

root@cuba:~# time fdisk -l /dev/sdb

real 0m3.052s
user 0m0.000s
sys 0m0.000s

The logs contains only:

Oct 23 12:34:09 cuba kernel: [11621.914630] end_request: I/O error, dev sdb, sector 0
Oct 23 12:34:09 cuba kernel: [11621.924707] Buffer I/O error on device sdb, logical block 0

Now, a 90 second delay might be acceptable, but it's not unusual to have many paths to many volumes, and half of these will normally be inaccessible. I have a server here that takes AGES to boot because of this - it has got 28 such passive paths visible, and udev/vol_id has to time out on all of them. The math is easy.

Tore

Revision history for this message
Scott James Remnant (Canonical) (canonical-scott) wrote :

Kay: any thoughts?

Changed in udev:
importance: Undecided → Low
status: New → Confirmed
Revision history for this message
Kay Sievers (kaysievers) wrote :

Scott, can you build a test package with this patch for Tore?
http://git.kernel.org/?p=linux/hotplug/udev.git;a=commitdiff;h=2bb4dd9766479348a2829ceb8ef583a788bfd840

So Tore can test, if it makes the timing acceptable on his box.

Thanks!

Revision history for this message
Tore Anderson (toreanderson) wrote : Re: [Bug 156184] Re: vol_id takes way too long to finish on unavailable SCSI devices

* Kay Sievers

> Scott, can you build a test package with this patch for Tore?
>
> So Tore can test, if it makes the timing acceptable on his box.

Don't bother with that... It should be enough to just test vol_id:

root@cuba:~# time /tmp/vol_id-udev113orig --export /dev/sdk
/dev/sdk: unknown volume type

real 2m1.113s
user 0m0.000s
sys 0m0.000s
root@cuba:~# time /tmp/vol_id-udev113patched --export /dev/sdk
/dev/sdk: unknown volume type

real 0m6.047s
user 0m0.000s
sys 0m0.000s

It's MUCH better with the patch. However I think it is possible to make
it even twice as quick, since it generates two I/O errors still:

Dec 17 09:36:13 cuba kernel: [3942923.936191] end_request: I/O error, dev sdk, sector 0
Dec 17 09:36:13 cuba kernel: [3942923.946615] Buffer I/O error on device sdk, logical block 0
Dec 17 09:36:16 cuba kernel: [3942926.955903] end_request: I/O error, dev sdk, sector 0
Dec 17 09:36:16 cuba kernel: [3942926.966328] Buffer I/O error on device sdk, logical block 0

In comparsion "fdisk -l /dev/sdk" takes 3 seconds and only one such
error is logged per invocation.

I can also confirm that the patch does not appear to break anything for
reachable devices:

root@cuba:~# /tmp/vol_id-udev113orig --export /dev/sde
ID_FS_USAGE=filesystem
ID_FS_TYPE=ext3
ID_FS_VERSION=1.0
ID_FS_UUID=df6f538e-a8b4-4195-91e9-4989cb6bfb45
ID_FS_UUID_ENC=df6f538e-a8b4-4195-91e9-4989cb6bfb45
ID_FS_LABEL=honolulu/mysql
ID_FS_LABEL_ENC=honolulu\x2fmysql
ID_FS_LABEL_SAFE=honolulumysql
root@cuba:~# /tmp/vol_id-udev113patched --export /dev/sde
ID_FS_USAGE=filesystem
ID_FS_TYPE=ext3
ID_FS_VERSION=1.0
ID_FS_UUID=df6f538e-a8b4-4195-91e9-4989cb6bfb45
ID_FS_UUID_ENC=df6f538e-a8b4-4195-91e9-4989cb6bfb45
ID_FS_LABEL=honolulu/mysql
ID_FS_LABEL_ENC=honolulu\x2fmysql
ID_FS_LABEL_SAFE=honolulumysql

Regards
--
Tore Anderson

Revision history for this message
Kay Sievers (kaysievers) wrote :

Ah, ok. Let's add the check to probe_all() too. This should fix it:
  http://git.kernel.org/?p=linux/hotplug/udev.git;a=commitdiff;h=73ff769c90307e9ef2947c7ba013626fb65c1478

Thanks!

Revision history for this message
Tore Anderson (toreanderson) wrote :

* Kay Sievers

> Ah, ok. Let's add the check to probe_all() too. This should fix it:

Indeed it does. A vol_id run on a unreadable device now takes three
seconds, just like fdisk. And it still works as expected on normal
devices. This fix will make life much easier for people like me with
midrange storage devices, thank you very much! :-)

Regards
--
Tore Anderson

Revision history for this message
Scott James Remnant (Canonical) (canonical-scott) wrote :

Are you like to release a 118 soon with this fix, or should I apply it to our 117 packages?

Revision history for this message
Kay Sievers (kaysievers) wrote :

Made a 118 release.

Scott James Remnant (Canonical) (canonical-scott)
Changed in udev:
status: Confirmed → Fix Committed
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package udev - 117-5

---------------
udev (117-5) hardy; urgency=low

  * Merge the "volumeid" package back into "udev", there is no particular
    gain to it being a separate binary package and it prevents the upgrade
    from dapper from migrating the fstab to UUID. LP: #209347.

  * debian/patches/00-git-bad-net-rules.patch:
    - Upstream patch from 118 to avoid creating persistent net rules
      which will match any device.
  * debian/patches/01-git-squashfs-lzma.patch:
    - Upstream patch from 118 to detect LZMA-compressed squashfs.
  * debian/patches/02-git-squashfs-endian.patch:
    - Upstream patch from 118 to detect endianness of LZMA squashfs.
  * debian/patches/03-git-vol_id-timeout-once.patch:
    - Upstream patch from 118 to only timeout once for unreadable devices.
      LP: #156184.
  * debian/patches/04-git-multiple-floppy-devices.patch:
    - Upstream patch from 118 to fix create_floppy_devices for more than
      one floppy device. Possibly LP: #132546.
  * debian/patches/05-git-vol_id-probe_all-readable.patch:
    - Upstream patch from 118 to check whether a device is readable before
      probing. Also LP: #156184.
  * debian/patches/00upstream-RUN-for-remove.patch:
    - Rename to 06-git-run-for-remove.patch so its in series with other
      git patches (this is from 119)
  * debian/patches/07-git-unlock-write_net_rules.patch:
    - Upstream patch from 119 to unlock rules after invalid match, correcting
      a bug introduced by 00-git-bad-net-rules.patch
  * debian/patches/08-git-vol_id-uuid-buffer.patch:
    - Upstream patch from 119 to correct UUID raw buffer usage.
  * debian/patches/09-git-update-ext.patch:
    - Upstream patch from 119 to update ext filesystem detection.
  * debian/patches/10-git-match-basename.patch:
    - Upstream patch from 119 to add match on the basename of an interface
      so we can deal with PS3 multiple interfaces with the same MAC.
  * debian/patches/11-git-persistent-change.patch:
    - Upstream patch from 119 to run persistent device rules on change
      events.
  * debian/patches/12-git-serialise-same-devno.patch:
    - Upstream patch from git to serialise multiple events with the same
      device number, fixes a race with serial ttys amongst other things.

  * 20-names.rules:
    - Add missing quotes for infiniband rules. LP: #192552.
    - Change "rdma_ucm" to "rdma_cm" (same bug).
  * 40-permissions.rules, 40-basic-permissions.rules:
    - Split out the most basic permissions into a separate file that can be
      used in the installer and initramfs. LP: #204108.
    - Add rules to place known USB serial devices that need libusb access
      in the dialout group. LP: #198757.
  * 65-persistent-storage.rules, 65-persistent-storage-tape.rules,
    65-persistent-input.rules, 66-persistent-storage-edd.rules:
    - Use upstream rule names for all rules. Also LP: #186686.
    - Add persistent-storage-edd.rules to installer and initramfs.
  * 80-programs.rules:
    - Pass $root/%k to create-floppy-devices, not $tempnode. LP: #132546.

 -- Scott James Remnant <email address hidden> Wed, 02 Apr 2008 18:59:56 +0100

Changed in udev:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.