0781:5406 udisks-daemon uses a ton of CPU after inserting a SanDisk U3 Cruzer Micro usb stick

[Brian Murray]

Binary package hint: udisks

Immediately after inserting this device I end up seeing this in top:

 1521 bdmurray 20 0 153m 4848 3248 R 48 0.3 3:22.45 gvfs-gdu-volume
 1523 root 20 0 133m 4756 3200 S 38 0.3 2:42.85 udisks-daemon
 1599 bdmurray 20 0 225m 10m 7884 S 22 0.6 1:33.28 gdu-notificatio
 1742 bdmurray 20 0 361m 16m 11m R 22 0.9 1:31.53 update-notifier
  463 root 18 -2 21664 1132 392 S 18 0.1 1:16.45 udevd

I wonder if it is related to the fake cd-rom on the stick:

[ 3925.041043] scsi 6:0:0:1: CD-ROM SanDisk U3 Cruzer Micro 6.51 PQ: 0 ANSI: 0

ProblemType: Bug
DistroRelease: Ubuntu 11.04
Package: udisks 1.0.2-3+ubuntu1
ProcVersionSignature: Ubuntu 2.6.38-5.32-generic 2.6.38-rc6
Uname: Linux 2.6.38-5-generic x86_64
Architecture: amd64
Date: Mon Feb 28 13:47:38 2011
EcryptfsInUse: Yes
HotplugNewDevices: /dev/sdb /dev/sdb1
HotplugNewMounts: /dev/sdb1 /media/6F51-B12A vfat rw,nosuid,nodev,relatime,uid=1000,gid=1000,fmask=0022,dmask=0077,codepage=cp437,iocharset=iso8859-1,shortname=mixed,showexec,utf8,flush,errors=remount-ro 0 0
InstallationMedia: Ubuntu 10.10 "Maverick Meerkat" - Release amd64 (20101007)
MachineType: LENOVO 0831CTO
ProcEnviron:
 LANGUAGE=en_US:en
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-2.6.38-5-generic root=UUID=58a88244-4d22-41f7-bd3a-aaa049c553a6 ro crashkernel=384M-2G:64M,2G-:128M quiet splash vt.handoff=7
SourcePackage: udisks
Symptom: storage
UpgradeStatus: Upgraded to natty on 2011-02-24 (3 days ago)
dmi.bios.date: 09/15/2010
dmi.bios.vendor: LENOVO
dmi.bios.version: 6QET53WW (1.23 )
dmi.board.name: 0831CTO
dmi.board.vendor: LENOVO
dmi.board.version: Not Available
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvr6QET53WW(1.23):bd09/15/2010:svnLENOVO:pn0831CTO:pvrThinkPadX201Tablet:rvnLENOVO:rn0831CTO:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 0831CTO
dmi.product.version: ThinkPad X201 Tablet
dmi.sys.vendor: LENOVO

[Leszek Lesner (leszek-lesner)]

I am seeing the exact same on my debian system with the 2.6.38-2-686 kernel.
Aswell as in Fedora 15 Beta that uses also a 2.6.38 kernel.

So my guess its a kernel bug.
Ah and btw. the reason for the high cpu rate in udisks and maybe udev is caused by a redetection of the stick every few seconds. So a /sbin/udevadm monitor (executed in a terminal of course) will give you a list of constantly detected new or changed devices like this :

KERNEL[1303421275.345520] change /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host7/target7:0:0/7:0:0:1/block/sr1 (block)
KERNEL[1303421275.360795] change /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host7/target7:0:0/7:0:0:1/block/sr1 (block)
UDEV [1303421275.363611] change /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host7/target7:0:0/7:0:0:1/block/sr1 (block)
KERNEL[1303421275.377142] change /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host7/target7:0:0/7:0:0:1/block/sr1 (block)
...

Restarting udev after unplugging the stick again should stop the high cpu usage.
So executing /etc/init.d/udev restart and the cpu usage is normal again.

[S. Christian Collins (s-chriscollins)]

After removing the U3 fake-CD partition (using the tool on my Sandisk Cruzer), my system no longer bogs down with the flash drive plugged in. This is a workaround for me, but not for anyone who wants to maintain the U3 functionality of his or her drive.

[David Barton (davebarton)]

This also happens with a Freecom Toughdrive USB hard disk. udisks --monitor reports that /dev/sr1 is constantly changing. Again, the fake CDROM drive appears to be the culprit. After using a Freecom tool to remove the fake drive, all the problems disappear.

[Dave Gilbert (ubuntu-treblig)]

For me this actually manages to trigger an oops after a zillion

VFS: busy inodes on changed media or resized disk sr1

This is on 2.6.38-10-generic #44-Ubuntu SMP and also on a different machine (with the same USB stick) on a 3.0rc3 kernel I built with a similar backtrace.

[17175.349990] BUG: unable to handle kernel NULL pointer dereference at 0000000000000002
[17175.350050] IP: [<ffffffff81a255c2>] init_groups+0x2/0xa0
[17175.350092] PGD 17e1d1067 PUD 1ea6a8067 PMD 0
[17175.350130] Oops: 0002 [#1] SMP
[17175.350157] last sysfs file: /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/bInterfaceSubClass
[17175.350214] CPU 6
[17175.350227] Modules linked in: nls_utf8 isofs sha256_generic cryptd aes_x86_64 aes_generic ip6table_filter ip6_tables binfmt_misc dm_crypt ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_CHECKSUM iptable_mangle xt_tcpudp iptable_filter ip_tables x_tables bridge stp kvm_intel kvm snd_hda_codec_hdmi snd_hda_codec_via snd_hda_intel snd_hda_codec snd_hwdep snd_seq_midi snd_pcm snd_rawmidi ppdev snd_seq_midi_event snd_seq snd_timer snd_seq_device lp snd soundcore snd_page_alloc parport_pc parport radeon ttm usbhid firewire_ohci usb_storage uas hid r8169 firewire_core drm_kms_helper pata_via crc_itu_t drm i2c_algo_bit configfs
[17175.350740]
[17175.350752] Pid: 1779, comm: umount Tainted: G W 2.6.38-10-generic #44-Ubuntu To Be Filled By O.E.M. To Be Filled By O.E.M./P55M Pro
[17175.350838] RIP: 0010:[<ffffffff81a255c2>] [<ffffffff81a255c2>] init_groups+0x2/0xa0
[17175.350891] RSP: 0018:ffff88014d0b3b30 EFLAGS: 00010002
[17175.350924] RAX: 0000000000000002 RBX: ffff88017e0686d0 RCX: 0000000000000010
[17175.350968] RDX: ffffffff81a255c0 RSI: 0000000000000000 RDI: ffff88017e0686d0
[17175.351011] RBP: ffff88014d0b3b38 R08: 0000000000000000 R09: ffff88021a5878a0
[17175.351053] R10: ffff88021a5878a0 R11: 0000000000000005 R12: 0000000000000000
[17175.351096] R13: 0000000000000001 R14: ffff88014d0b3d01 R15: ffff88021a5878a0
[17175.351141] FS: 00007eff431d5760(0000) GS:ffff8800c7580000(0000) knlGS:0000000000000000
[17175.351191] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[17175.351224] CR2: 0000000000000002 CR3: 000000014d94e000 CR4: 00000000000006e0
[17175.351267] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[17175.351311] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[17175.351355] Process umount (pid: 1779, threadinfo ffff88014d0b2000, task ffff8801436b8000)
[17175.351405] Stack:
[17175.351418] ffffffff812bd1ed ffff88014d0b3b98 ffffffff812c2e18 ffff88014d0b3b78
[17175.351471] 0000000000000082 0000000000000000 ffff880100000010 0000000000000000
[17175.351520] ffff88017e0686d0 0000000000000000 0000000000000010 ffff88014d0b3db8
[17175.351573] Call Trace:
[17175.351594] [<ffffffff812bd1ed>] ? elv_may_queue+0x1d/0x20
[17175.351628] [<ffffffff812c2e18>] get_request+0x48/0x3f0
[17175.351664] [<ffffffff812c3479>] get_request_wait+0x29/0x1a0
[17175.351702] [<ffffffff8110c6b0>] ? find_get_pages_tag+0x40/0x120
[17175.351744] [<ffffffff8105f464>] ? try_to_wake_up+0x244/0x3e0
[17175.351778] [<ffffffff812c365...

[Kees Cook (kees)]

I encountered this only after reformatting the stick with ext4 (it behaved fine prior to that). I would agree, it does seem to be some kind of kernel (or udev) bug.

[Dave Gilbert (ubuntu-treblig)]

This seems related to:

https://lkml.org/lkml/2011/7/1/318

oops on unpugging USB cdrom, and since this thumbdrive has a partition that pretends to be a cdrom I think it's the same problem.

[Brian Murray (brian-murray)]

I broke out my USB stick today and discovered that with kernel version 3.0.0-10 this is no longer an issue.

[Id2ndR (id2ndr)]

I have encountered the same trouble with 08ec:0015 M-Systems Flash Disk Pioneers Kingston DataTraveler ELITE
udisk --monitor output lots of "changed: /org/freedesktop/UDisks/devices/sdb" before "added: /org/freedesktop/UDisks/devices/sdb1".
I tried to change sdb1 partition type from 6 (fat16) to b (fat32) because I'm not sure of the filesystem but that doesn't change anything about udisks-daemon CPU usage and delay before be able to mount the partition.

I'm using Ubuntu 12.04

[Dave Gilbert (ubuntu-treblig)]

id2ndr: Can you attach the output of the
   dmesg command
and
   lsusb command

 after having plugged the flash disk in.
My guess is this is actually a different problem than the sandisk one but similar symptoms.

[Id2ndR (id2ndr)]

Here there are (just the useful part).

lsusb -vvv:

Bus 001 Device 008: ID 08ec:0015 M-Systems Flash Disk Pioneers Kingston DataTraveler ELITE
Device Descriptor:
  bLength 18
  bDescriptorType 1
  bcdUSB 2.00
  bDeviceClass 0 (Defined at Interface level)
  bDeviceSubClass 0
  bDeviceProtocol 0
  bMaxPacketSize0 64
  idVendor 0x08ec M-Systems Flash Disk Pioneers
  idProduct 0x0015 Kingston DataTraveler ELITE
  bcdDevice 2.00
  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 140mA
    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 0x81 EP 1 IN
        bmAttributes 2
          Transfer Type Bulk
          Synch Type None
          Usage Type Data
        wMaxPacketSize 0x0200 1x 512 bytes
        bInterval 0

dmesg:
[ 2113.393288] usb 1-4: new high-speed USB device number 8 using ehci_hcd
[ 2113.524941] usb 1-4: New USB device found, idVendor=08ec, idProduct=0015
[ 2113.524950] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2113.524956] usb 1-4: Product: DT Elite HS 2.0
[ 2113.524961] usb 1-4: Manufacturer: Kingston
[ 2113.524966] usb 1-4: SerialNumber: 08202A40D093A9CC
[ 2113.525590] scsi12 : usb-storage 1-4:1.0
[ 2114.524855] scsi 12:0:0:0: Direct-Access Kingston DT Elite HS 2.0 5.02 PQ: 0 ANSI: 0 CCS
[ 2114.526520] sd 12:0:0:0: Attached scsi generic sg4 type 0
[ 2114.534321] sd 12:0:0:0: [sdc] Attached SCSI removable disk
[ 2117.691684] sd 12:0:0:0: [sdc] 1019391 512-byte logical blocks: (521 MB/497 MiB)
[ 2117.693678] sd 12:0:0:0: [sdc] No Caching mode page present
[ 2117.693683] sd 12:0:0:0: [sdc] Assuming drive cache: write through
[ 2117.696318] sd 12:0:0:0: [sdc] No Caching mode page present
[ 2117.696322] sd 12:0:0:0: [sdc] Assuming drive cache: write through
[ 2117.698010] sdc: sdc1

[Dave Gilbert (ubuntu-treblig)]

id2ndr:
  To me that looks like a separate problem from this one; all the people on this one had keys that showed up as combination CDROM/disk pairs and it was the kernel getting upset at the cdrom which from the limited debug from yours doesn't seem to be the case. I suggest reporting a separate bug on it, feel free to add a note here giving that bug number.