[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Bug#671859: marked as done (udev: Udev hangs on boot for 120 seconds, times out then eats CPU failing to rename files)

Your message dated Sun, 07 Feb 2016 22:43:09 +0000
with message-id <E1aSY2v-0006JQ-Io@deadeye>
and subject line Closing bugs assigned to linux-2.6 package
has caused the Debian Bug report #671859,
regarding udev: Udev hangs on boot for 120 seconds, times out then eats CPU failing to rename files
to be marked as done.

This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.

(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact owner@bugs.debian.org
immediately.)


-- 
671859: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=671859
Debian Bug Tracking System
Contact owner@bugs.debian.org with problems
--- Begin Message --- 
Package: udev
Version: 175-3.1
Severity: important

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

Dear Maintainer,

This bug issue first came to light after upgrading the kernel from 3.0.1 to
3.3.4, both home-build versions from the kernel.org source. Switching back to
3.0.1 stops this behaviour, but since the problems all appear to point to
udev doing something odd, I thought this was the correct place to report the
bug. Please do correct me if you disagree.

After changing to kernel 3.3.4, the system became unresponsive on booting,
at the point where udev was being started. 120 seconds later, the system then
continued booting, but the CPU usage of all three cores of my machine are at
about 70% each, split approximately 2:1 system:user. The first few lines from
top illustrate this:

>>>
Tasks: 185 total,   2 running, 183 sleeping,   0 stopped,   0 zombie
%Cpu0  : 31.4 us, 44.1 sy,  0.0 ni, 24.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  : 26.2 us, 50.5 sy,  0.0 ni, 20.4 id,  0.0 wa,  0.0 hi,  2.9 si,  0.0 st
%Cpu2  : 23.3 us, 37.9 sy,  0.0 ni, 36.9 id,  0.0 wa,  0.0 hi,  1.9 si,  0.0 st
Kb Mem:   2052848 total,  1282356 used,   770492 free,    34752 buffers
Kb Swap:  2097148 total,        0 used,  2097148 free,   594576 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                                                
 1367 root      20   0 21404 1288  620 S  14.9  0.1   4:46.76 udevd                                                                  
 1368 root      20   0 21404 1280  616 S  14.6  0.1   4:45.65 udevd                                                                  
 1369 root      20   0 21404 1276  612 R  14.6  0.1   4:47.38 udevd                                                                  
 1370 root      20   0 21404 1260  596 S  14.6  0.1   4:47.26 udevd                                                                  
 1352 root      20   0 21672 1652  808 S   7.0  0.1   2:16.53 udevd                                                                  
 5707 root      20   0 47764 2056 1716 S   2.7  0.1   0:49.78 odccm                                                                  
 6029 dh        20   0  238m  14m  10m S   1.3  0.7   0:24.55 gkrellm                                                                
<<<

A large number of udev processes appear to be running as well:

>>>
$ ps faux|grep udev
root      1352  6.9  0.0  21672  1652 ?        Ss   15:33   2:22 udevd --daemon
root      1367 14.5  0.0  21404  1288 ?        S    15:33   4:59  \_ udevd --daemon
root      1368 14.4  0.0  21404  1280 ?        S    15:33   4:57  \_ udevd --daemon
root       370  0.0  0.0  29144  1520 ?        R    16:08   0:00  |   \_ /lib/udev/udisks-part-id /dev/ubd
root      1369 14.5  0.0  21404  1276 ?        S    15:33   4:59  \_ udevd --daemon
root       371  0.0  0.0  29140  1532 ?        D    16:08   0:00  |   \_ /lib/udev/udisks-part-id /dev/ubb
root      1370 14.5  0.0  21404  1260 ?        S    15:33   4:59  \_ udevd --daemon
root      1372  0.0  0.0  21404  1220 ?        S    15:33   0:00  \_ udevd --daemon
root      1374  0.0  0.0  21404  1180 ?        S    15:33   0:00  \_ udevd --daemon
root      1375  0.0  0.0  21404  1204 ?        S    15:33   0:00  \_ udevd --daemon
root      1377  0.0  0.0  21404  1204 ?        S    15:33   0:00  \_ udevd --daemon
root      1378  0.0  0.0  21404  1184 ?        S    15:33   0:00  \_ udevd --daemon
root      1379  0.0  0.0  21404  1144 ?        S    15:33   0:00  \_ udevd --daemon
root      1380  0.0  0.0  21404  1184 ?        S    15:33   0:00  \_ udevd --daemon
root      1381  0.0  0.0  21404  1192 ?        S    15:33   0:00  \_ udevd --daemon
root      1382  0.0  0.0  21404  1208 ?        S    15:33   0:00  \_ udevd --daemon
root      1383  0.0  0.0  21404  1092 ?        S    15:33   0:00  \_ udevd --daemon
root      1384  0.0  0.0  21404  1136 ?        S    15:33   0:00  \_ udevd --daemon
root      1385  0.0  0.0  21404  1192 ?        S    15:33   0:00  \_ udevd --daemon
root      1386  0.0  0.0  21404  1120 ?        S    15:33   0:00  \_ udevd --daemon
root      1387  0.0  0.0  21404  1120 ?        S    15:33   0:00  \_ udevd --daemon
root      1388  0.0  0.0  21404  1128 ?        S    15:33   0:00  \_ udevd --daemon
root      1389  0.0  0.0  21404  1156 ?        S    15:33   0:00  \_ udevd --daemon
root      1390  0.0  0.0  21404  1140 ?        S    15:33   0:00  \_ udevd --daemon
root      1391  0.0  0.0  21404  1152 ?        S    15:33   0:00  \_ udevd --daemon
root      1392  0.0  0.0  21404  1128 ?        S    15:33   0:00  \_ udevd --daemon
root      1393  0.0  0.0  21404  1132 ?        S    15:33   0:00  \_ udevd --daemon
root      1394  0.0  0.0  21404  1124 ?        S    15:33   0:00  \_ udevd --daemon
root      1395  0.0  0.0  21404  1128 ?        S    15:33   0:00  \_ udevd --daemon
root      1396  0.0  0.0  21404  1116 ?        S    15:33   0:00  \_ udevd --daemon
root      1397  0.0  0.0  21404  1116 ?        S    15:33   0:00  \_ udevd --daemon
root      1398  0.0  0.0  21404  1100 ?        S    15:33   0:00  \_ udevd --daemon
root      1399  0.0  0.0  21404  1100 ?        S    15:33   0:00  \_ udevd --daemon
root      1400  0.0  0.0  21404  1076 ?        S    15:33   0:00  \_ udevd --daemon
root      1401  0.0  0.0  21404  1072 ?        S    15:33   0:00  \_ udevd --daemon
root      1402  0.0  0.0  21404  1076 ?        S    15:33   0:00  \_ udevd --daemon
root      1403  0.0  0.0  21404  1076 ?        S    15:33   0:00  \_ udevd --daemon
root      1463  0.0  0.0  21668  1240 ?        S    15:33   0:00  \_ udevd --daemon
root      1464  0.0  0.0  21668  1148 ?        S    15:33   0:00  \_ udevd --daemon
root      1465  0.0  0.0  21404  1052 ?        S    15:33   0:00  \_ udevd --daemon
root      1466  0.0  0.0  21668  1240 ?        S    15:33   0:00  \_ udevd --daemon
<<<

There are also a large number of entries being sent to syslog of the following form:

>>>
May  7 15:48:10 scrat udevd[1369]: symlink '../../ubc' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:48:25 scrat udevd[1368]: symlink '../../ubc' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:49:26 scrat udevd[1369]: symlink '../../uba' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:49:41 scrat udevd[1367]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:49:59 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:50:23 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:50:59 scrat udevd[1367]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:51:28 scrat udevd[1367]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:51:40 scrat udevd[1369]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:51:58 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:52:59 scrat udevd[1368]: symlink '../../ubb' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:53:13 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:54:00 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:54:52 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:54:52 scrat udevd[1368]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:55:30 scrat udevd[1368]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:55:36 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:55:38 scrat udevd[1367]: symlink '../../ubc' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:56:21 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:56:48 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:56:48 scrat udevd[1370]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:58:15 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:58:25 scrat udevd[1369]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:58:31 scrat udevd[1367]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 15:58:57 scrat udevd[1369]: symlink '../../ubb' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 15:59:07 scrat udevd[1369]: symlink '../../ubc' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 16:00:01 scrat udevd[1369]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 16:00:18 scrat udevd[1368]: symlink '../../ubb' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 16:00:40 scrat udevd[1368]: symlink '../../uba' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 16:01:06 scrat udevd[1368]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 16:01:41 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 16:01:53 scrat udevd[1370]: symlink '../../ubd' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
May  7 16:02:23 scrat udevd[1369]: rename '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0' failed: No such file or directory 
May  7 16:02:23 scrat udevd[1368]: symlink '../../ubb' '/dev/disk/by-path/pci-0000:00:04.1-usb-0:3:1.0.udev-tmp' failed: File exists 
<<<

The filenames pointed to there seem to indicate that it's trying to set up a
USB multi-card reader, which presents itself as a USB mass storage device
with multiple LUNs. The device details are here:

>>>
$ lsusb -d 058f:6362 -v

Bus 002 Device 003: ID 058f:6362 Alcor Micro Corp. Flash Card Reader/Writer
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x058f Alcor Micro Corp.
  idProduct          0x6362 Flash Card Reader/Writer
  bcdDevice            1.26
  iManufacturer           1 
  iProduct                2 
  iSerial                 3 
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           32
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              100mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Device Status:     0xb810
  (Bus Powered)
<<<

If I now execute "sudo /etc/init.d/udev restart", the CPU usage drops back
down to zero and I get a much more sane looking number of udev processes
showing up:

>>>
$ ps faux|grep udev
root      8144  0.1  0.0  21376  1364 ?        Ss   16:15   0:00 udevd --daemon
root      8165  0.0  0.0  21372  1152 ?        S    16:15   0:00  \_ udevd --daemon
root      8210  0.0  0.0  29140  1524 ?        D    16:15   0:00  |   \_ /lib/udev/udisks-part-id /dev/ubb
root      8173  0.0  0.0  21372  1144 ?        S    16:15   0:00  \_ udevd --daemon
root      8196  0.0  0.0  29140  1524 ?        D    16:15   0:00  |   \_ /lib/udev/udisks-part-id /dev/uba
root      8181  0.0  0.0  21372  1152 ?        S    16:15   0:00  \_ udevd --daemon
root      8202  0.0  0.0  29140  1524 ?        D    16:15   0:00      \_ /lib/udev/udisks-part-id /dev/ubc
<<<

In summary, three things seem to work around the bug, though none of them are
anywhere close to ideal:

 * Boot without the USB card reader present. This is particularly impractical
   as it is an internal device.
 * Boot kernel 3.0.1
 * Put up with the initial timeout, then re-start udev once booted

I'd be happy to perform any further tests if it would be useful in getting to
the bottom of this problem.

All the best,
- -DH.


- -- System Information:
Debian Release: wheezy/sid
  APT prefers unstable
  APT policy: (550, 'unstable'), (550, 'testing'), (450, 'stable'), (445, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 3.3.4 (SMP w/3 CPU cores)
Locale: LANG=en_GB, LC_CTYPE=en_GB (charmap=ISO-8859-1)
Shell: /bin/sh linked to /bin/bash

Versions of packages udev depends on:
ii  debconf [debconf-2.0]  1.5.42
ii  libc6                  2.13-32
ii  libselinux1            2.1.9-4
ii  libudev0               175-3.1
ii  lsb-base               4.1+Debian2
ii  util-linux             2.20.1-4

Versions of packages udev recommends:
ii  pciutils  1:3.1.9-2
ii  usbutils  1:005-3

udev suggests no packages.

- -- debconf information:
  udev/title/upgrade:
  udev/new_kernel_needed: false
  udev/sysfs_deprecated_incompatibility:
  udev/reboot_needed:

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.12 (GNU/Linux)

iQIcBAEBCgAGBQJPp+j1AAoJEBIA1yCB7VsRrxIP/0PNZuH5SF6SJ4zq/OxWbPrt
IQgN0wKEQCNZ49w5pCDZ3ac/D1uCCsrHqWdp7CSSKp65MbkiFdpLVRSy4B5Huf2o
6y48vK9ORgl13htfW5ibz3Ird26oeQ4ajQHNApXPyZKe+q2q7oJYV+jFh1KlYQmJ
+OXUNhL9Sk0XaOQeZotwUSQjVRs/Ya0U4uYtKPOjXl/rgvZvUcN5pRXXag5v5/p/
mhXfPlAQe6acSuXdBj7uJ6cV68EYMMuRXAGqCU/3xekIA1GKJmYa3dQWG1nRqQzF
GM4WvkCznzIbr2H8gmiOkhPOxgFp2R61Gx4zIlaCz9nI6eavDDvr4JaQAhiK5vZw
bcsCWA/r/D19RmVfnG4ylGQiUKn8nq+DYy8lwQvQ5hIgkGTBERo6/rYnkosKCwYj
a21W5fIlw2YVssUevsbs5jxp5yGCgpx1dTKCCqWbaGNcz9jcnNQwvmutQYR3lHhs
EpljTK4ItC6JCk0IlBW/kAMC9UryiZnhGUhUUDVNo71FOBN6YG4zw5rQ3IjzLYLL
+CxZF9qiUFpvcnKVqz3lAkSIQ2gCAqBgtHAx4k9qW+I/2BoyLTm2lM7HSWFr/84P
g94YdMXm0iBDQ8cjLAbK09YQGkYENS9XAntKjLZRR2fV8Szp49FCHaGLUe2QaxLr
5NrzJ5bMeSkR6O9V1xMp
=HsG+
-----END PGP SIGNATURE-----

--- End Message ---
--- Begin Message --- 
Version: 3.4.1-1~experimental.1+rm

Debian 6.0 Long Term Support has now ended, and the 'linux-2.6' source
package will no longer be updated.  This bug is being closed on the
assumption that it does not affect the kernel versions in newer Debian
releases.

If you can still reproduce this bug in a newer release, please reopen
the bug report and reassign it to 'src:linux' and the affected version
of the package.  You can find the package version for the running
kernel by running:

    uname -v

or the versions of all installed kernel packages by running:

    dpkg -l 'linux-image-[34]*' | grep ^.i

and looking at the third column.

I apologise that we weren't able to provide a specific resolution for
this bug.

Ben.

-- 
Ben Hutchings - Debian developer, member of Linux kernel and LTS teams

--- End Message ---
Reply to: