Bug 717249

Summary: cpu consuming near 100% after inserting a usb flash drive
Product: [Fedora] Fedora Reporter: Andrew <travneff>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 15CC: aquini, davidz, gansalmon, itamar, jonathan, jwboyer, kay, kernel-maint, madhu.chinakonda, travneff
Target Milestone: ---Flags: travneff: needinfo-
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-08-17 12:06:20 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Andrew 2011-06-28 12:51:11 UTC
Description of problem:
I have a usb flash drive which is recognized as two devices: usual flash drive and CD-ROM drive (it stores some autorun data).
After inserting it CPU load became very high, for example:

Cpu(s): 54.5%us, 44.9%sy,  0.0%ni,  0.3%id,  0.0%wa,  0.0%hi,  0.3%si,  0.0%st
Mem:   3091920k total,  1245112k used,  1846808k free,   134116k buffers
Swap:  2097148k total,        0k used,  2097148k free,   466172k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  957 dbus      20   0 95920 2232 1248 S 14.5  0.1   0:14.12 dbus-daemon
 2235 root      20   0  124m 3616 2556 S 13.9  0.1   0:12.00 udisks-daemon


udisks shows there are a lot of "changed" notifies for this device (several per second):

$ udisks --monitor
Monitoring activity from the disks daemon. Press Ctrl+C to cancel.
changed:     /org/freedesktop/UDisks/devices/sr0
changed:     /org/freedesktop/UDisks/devices/sr0
changed:     /org/freedesktop/UDisks/devices/sr0
changed:     /org/freedesktop/UDisks/devices/sr0
changed:     /org/freedesktop/UDisks/devices/sr0
[many repeats]


Running "udisks --inhibit" or "udisks --inhibit-all-polling" doesn't help. Adding following variable to the string in /etc/udev/rules.d/70-persistent-cd.rules doesn't help too: ENV{UDISKS_DISABLE_POLLING}="1"


HAL is not launched. There are just one packet installed, which is needed as a dependency for gnome-vfs2, gimp, thunderbird and others:

$ rpm -qa | grep hal
hal-libs-0.5.14-6.fc15.x86_64


Reproducible: always.


Steps to Reproduce:
Just insert a flash drive to USB port (no mounting or other operations required).


Additional info:
These issues may be related, I think:
https://bugzilla.redhat.com/show_bug.cgi?id=684614
https://bugzilla.redhat.com/show_bug.cgi?id=637973
https://bugzilla.redhat.com/show_bug.cgi?id=600592


sr0 device info:

$ udisks --show-info /dev/sr0
Showing information for /org/freedesktop/UDisks/devices/sr0
  native-path:                 /sys/devices/pci0000:00/0000:00:02.1/usb1/1-2/1-2:1.0/host6/target6:0:0/6:0:0:1/block/sr0
  device:                      11:0
  device-file:                 /dev/sr0
    presentation:              /dev/sr0
    by-id:                     /dev/disk/by-id/usb-Generic_AutoRun_Disk_LWN98399-0:1
    by-path:                   /dev/disk/by-path/pci-0000:00:02.1-usb-0:2:1.0-scsi-0:0:0:1
  detected at:                 Tue Jun 28 11:46:28 2011
  system internal:             0
  removable:                   1
  has media:                   1 (detected at Tue Jun 28 11:46:28 2011)
    detects change:            1
    detection by polling:      0
    detection inhibitable:     1
    detection inhibited:       0
  is read only:                0
  is mounted:                  0
  mount paths:             
  mounted by uid:              0
  presentation hide:           0
  presentation nopolicy:       0
  presentation name:           
  presentation icon:           
  size:                        11540480
  block size:                  512
  job underway:                no
  usage:                       
  type:                        
  version:                     
  uuid:                        
  label:                       
  optical disc:
    blank:                     0
    appendable:                0
    closed:                    0
    num tracks:                0
    num audio tracks:          0
    num sessions:              0
  drive:
    vendor:                    Generic
    model:                     AutoRun Disk
    revision:                  8.00
    serial:                    LWN98399
    WWN:                       
    detachable:                1
    can spindown:              0
    rotational media:          Yes, unknown rate
    write-cache:               unknown
    ejectable:                 1
    adapter:                   Unknown
    ports:
    similar devices:
    media:                     optical_cd
      compat:                  optical_cd optical_mrw optical_mrw_w
    interface:                 usb
    if speed:                  480000000 bits/s
    ATA SMART:                 not available

Comment 1 David Zeuthen 2011-07-06 19:08:03 UTC
What is the kernel and udev versions?

Pretty sure this is caused by how we are detecting media changes (GET_EVENT instead of TUR) - see http://www.spinics.net/lists/hotplug/msg04965.html and surrounding messages for fixes. Reassigning to kernel and adding Kay to the Cc.

Comment 2 Andrew 2011-07-07 08:19:32 UTC
Kernel and udev are installed from current fedora stable repos:

$ uname -a
Linux localhost 2.6.38.8-32.fc15.x86_64 #1 SMP Mon Jun 13 19:49:05 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux

  udev:
libgudev1-167-4.fc15.x86_64
udev-167-4.fc15.x86_64
libudev-167-4.fc15.x86_64


I've tried following workaround and it helps, thank you

# echo 'KERNEL=="sr0", ACTION=="change", WAIT_FOR="nothing"' >> /etc/udev/rules.d/my.rules

Comment 3 Kay Sievers 2011-07-07 11:20:39 UTC
It is a Sandisk Cruzer device? The firmware is terribly broken
and reports endless media changes. Any access to the device will
cause a media change, not only for the fake cdrom, also for the
udeb-storage device. Udev runs in an endless loop, with an ever
growing event queue.

(In reply to comment #2)
> I've tried following workaround and it helps, thank you
> 
> # echo 'KERNEL=="sr0", ACTION=="change", WAIT_FOR="nothing"' >>
> /etc/udev/rules.d/my.rules

That doesn't help anything really. It's the equivalent of adding:
"sleep 10" to the cdrom event handler. It just makes the endless
loop slower, but udev is still dead-locked.

A patch to work around the issue in the kernel is on the way:
  http://www.spinics.net/lists/linux-scsi/msg53075.html

Comment 4 Andrew 2011-07-07 11:44:40 UTC
> It is a Sandisk Cruzer device?

No, it is Transcend JetFlash 16GB, but the behaviour is like you describe.
I understand that udev rule is not a solution.

Comment 5 Kay Sievers 2011-07-30 14:17:55 UTC
Patches, which are expected to detect the issue and work around it,
are merged upstream now:
  http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=79b9677d885d1a792bc103f2febb06f91f92de43

Comment 6 Dave Jones 2011-08-16 13:13:59 UTC
This patch is present in the 2.6.40.3-0 update that I just pushed to updates-testing.

Comment 7 Andrew 2011-08-17 11:42:07 UTC
Yes, this update stopped the infinite loop.
Now `udevadm monitor` shows the following:

UDEV  [1313515134.688731] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
KERNEL[1313515134.692017] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.722588] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
KERNEL[1313515134.725735] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.758158] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
KERNEL[1313515134.760891] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.791630] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
KERNEL[1313515134.794862] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.827038] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
KERNEL[1313515134.829643] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.844804] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:0/block/sdb/sdb2 (block)
UDEV  [1313515134.861678] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
[   74.849585] sr 6:0:0:1: GET_EVENT and TUR disagree continuously, suppress GET_EVENT events
KERNEL[1313515134.865795] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.893514] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:0/block/sdb/sdb1 (block)
UDEV  [1313515134.894994] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)
UDEV  [1313515134.908605] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3/2-1.3:1.0/host6/target6:0:0/6:0:0:1/block/sr0 (block)

[output stopped]

This issue can be closed, I think.

Comment 8 Josh Boyer 2011-08-17 12:06:20 UTC
Thanks for testing!