udevd takes 100% of cpu

[picgla]

Binary package hint: udev

udevd is causing the machine to run very high cpu utilization rates; fan runs constantly. meerkat on the same machine caused no such problems.

ProblemType: Bug
DistroRelease: Ubuntu 11.04
Package: udev 167-0ubuntu3
ProcVersionSignature: Ubuntu 2.6.38-9.43-generic 2.6.38.4
Uname: Linux 2.6.38-9-generic i686
Architecture: i386
Date: Mon May 9 19:43:58 2011
InstallationMedia: Ubuntu 11.04 "Natty Narwhal" - Release i386 (20110427.1)
MachineType: Dell Inc. OptiPlex GX280
ProcEnviron:
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/usr/local/bin/zsh
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-2.6.38-9-generic root=UUID=da503c0c-0d80-4161-ad70-d5f050ed7527 ro
SourcePackage: udev
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 03/03/2006
dmi.bios.vendor: Dell Inc.
dmi.bios.version: A08
dmi.board.name: 0H8164
dmi.board.vendor: Dell Inc.
dmi.chassis.type: 15
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvrA08:bd03/03/2006:svnDellInc.:pnOptiPlexGX280:pvr:rvnDellInc.:rn0H8164:rvr:cvnDellInc.:ct15:cvr:
dmi.product.name: OptiPlex GX280
dmi.sys.vendor: Dell Inc.

[Sam Liddicott (sam-liddicott)]

Here is what strace shows:

recv(8, 0xbfced218, 8, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=-4298, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\322\0\0\0\360\3\35\267{\313\305\356"..., 40}, {"UDEV_LOG=3\0ACTION=change\0DEVPATH"..., 210}], msg_controllen=0, msg_flags=0}, 0) = 250
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 5, -1) = 1 ([{fd=8, revents=POLLIN}])
recv(8, "\341\17\0\0\0\0\0\0", 8, MSG_DONTWAIT) = 8
_llseek(3, 0, [11513544], SEEK_CUR) = 0
write(3, "\351\260\0\0\0\0\0\0\0\0", 10) = 10
recv(8, 0xbfced218, 8, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=-4298, groups=00000000}, msg_iov(2)=[{"libudev\0\376\355\312\376(\0\0\0(\0\0\0\322\0\0\0\360\3\35\267{\313\305\356"..., 40}, {"UDEV_LOG=3\0ACTION=change\0DEVPATH"..., 210}], msg_controllen=0, msg_flags=0}, 0) = 250
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 5, -1) = 1 ([{fd=8, revents=POLLIN}])
recv(8, "\341\17\0\0\0\0\0\0", 8, MSG_DONTWAIT) = 8
_llseek(3, 0, [11513554], SEEK_CUR) = 0
write(3, "\352\260\0\0\0\0\0\0\0\0", 10) = 10

[Sam Liddicott (sam-liddicott)]

A trigger of this is inserting my Sandisk Cruzer USB memory stick with fake integrated CD-ROM.

This it dmesg when I insert the USB memory stick:
May 12 14:46:20 sojo kernel: [95455.488104] usb 1-3: new high speed USB device using ehci_hcd and address 12
May 12 14:46:20 sojo kernel: [95455.622507] scsi9 : usb-storage 1-3:1.0
May 12 14:46:21 sojo kernel: [95456.623418] scsi 9:0:0:0: Direct-Access SanDisk Cruzer 7.01 PQ: 0 ANSI: 0 CCS
May 12 14:46:21 sojo kernel: [95456.623973] scsi 9:0:0:1: CD-ROM SanDisk Cruzer 7.01 PQ: 0 ANSI: 0
May 12 14:46:21 sojo kernel: [95456.629231] sd 9:0:0:0: Attached scsi generic sg4 type 0
May 12 14:46:21 sojo kernel: [95456.635576] sd 9:0:0:0: [sdd] Attached SCSI removable disk
May 12 14:46:21 sojo kernel: [95456.645776] sr1: scsi3-mmc drive: 48x/48x tray
May 12 14:46:21 sojo kernel: [95456.645996] sr 9:0:0:1: Attached scsi CD-ROM sr1
May 12 14:46:21 sojo kernel: [95456.646558] sr 9:0:0:1: Attached scsi generic sg5 type 5
May 12 14:46:22 sojo kernel: [95457.352760] sd 9:0:0:0: [sdd] 31306239 512-byte logical blocks: (16.0 GB/14.9 GiB)
May 12 14:46:22 sojo kernel: [95457.354199] sd 9:0:0:0: [sdd] Asking for cache data failed
May 12 14:46:22 sojo kernel: [95457.354203] sd 9:0:0:0: [sdd] Assuming drive cache: write through
May 12 14:46:22 sojo kernel: [95457.358186] sd 9:0:0:0: [sdd] Asking for cache data failed
May 12 14:46:22 sojo kernel: [95457.358190] sd 9:0:0:0: [sdd] Assuming drive cache: write through
May 12 14:46:22 sojo kernel: [95457.358870] sdd: sdd1
May 12 14:46:23 sojo kernel: [95458.609921] ISO 9660 Extensions: Microsoft Joliet Level 3
May 12 14:46:24 sojo kernel: [95458.686421] ISOFS: changing to secondary root
May 12 14:46:24 sojo kernel: [95458.693931] VFS: busy inodes on changed media or resized disk sr1

Until I remove my SUB stick I get this in syslog repeatedly:
May 12 14:51:47 sojo kernel: [95782.079217] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.095640] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.112794] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.146326] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.162621] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.179708] VFS: busy inodes on changed media or resized disk sr1
May 12 14:51:47 sojo kernel: [95782.250378] VFS: busy inodes on changed media or resized disk sr1

But the CPU usage does not go away when I remove it, but udisks-daemon and dbys-daemon also take a lot of CPU.

[Sam Liddicott (sam-liddicott)]

A while after I removed my usb stick, udisks-daemon and dbus-daemon quietened down. Maybe they were handling the backlog of inode changed messages?

[Dmitry Savvateev (savvdm)]

I have the same problem with USB stick with integrated CD (Transcend). I often keep it inserted all the time, so I have to disable udev with 'udevadm control --stop-exec-queue'. This is not a solution, of course, but so far I could not figure out how to block media change events from sr1.

[Sam Liddicott (sam-liddicott)]

thank-you for this solution.

I've been plugging my memory stick into my NAS and using NFS to mount
it, which is clearly stupid.

Your solution is much better.

[Dmitry Savvateev (savvdm)]

I have found a way to reduce CPU load without entirely stopping the udev queue.

Create /etc/udev/rules.d/my.rules file, and put the following line into it:
KERNEL=="sr1", ACTION=="change", WAIT_FOR="nothing"

This will introduce a 10 seconds delay when processing 'change' events from /dev/sr1. As a result, CPU load returns to normal. I did not notice any negative side effects so far. Other udev events seem to get processed normally.

This is still a work-around, not a solution. The solution would be to find out exactly what's wrong with the existing udev rules, and fix the problem there.

[Dmitry Savvateev (savvdm)]

Here's the answer from Kay Sievers (udev mailing list):

It's a broken device, that tells with every check that the media has
 changed. This patch needs to be tested:
  http://marc.info/?l=linux-hotplug&m=130843331916959&w=2

[Alex (icidrop)]

Where is the patch, and how to apply it? I couldn't find it in the link. Please direct me.

[Dmitry Savvateev (savvdm)]

There is a source code patch in the message - it should be applied to the original sources, and re-compiled.