Bug#782390: udev: time between USB-stick connection and device notification takes up to a minute

[Bernhard Übelacker]

Hello Michael,
I am sorry, but my old address got shut down.


On Wed, 21 Dec 2016 19:30:10 +0100 Michael Biebl  wrote:
> just wanted to ask, if you still run into this issue with a newer kernel
> (from testing). If so, I think it would probably best to re-assign this.
> 
> Regards,
> Michael

Unfortunately this hardware was not my own.
Probably on upgrading to Stretch on his system ...

But I am fine with closing the bug too, because this stick is of rather
small capacity and no other user noticed the same behaviour.

Kind regards,
Bernhard

Bug#782390: udev: time between USB-stick connection and device notification takes up to a minute

[Michael Biebl]

Hi Bernd

On Wed, 27 May 2015 22:11:38 +0200
=?UTF-8?B?QmVybmhhcmQgw5xiZWxhY2tlcg==?=  wrote:
> Hello Marco, hello Michael,
> sorry for the delay.
> This is just to add some points to the bug.
> 
> 
> On Sat, 11 Apr 2015 16:04:50 +0200 m...@linux.it (Marco d'Itri) wrote:
> > Unless something is creating an events loop then this is an hardware 
> > issue or a kernel bug.
> > Considering that this only happens with a specific USB stick I will 
> > assume that it is broken.
> 
> To me it looks like the creators of this stick intentionally made a
> waiting time of 5 seconds between being recognized as USB stick and
> actually "inserting" the "media" into it, like a card reader.
> In this 5 seconds the kernel always tries to open the "media" and triggers
> new block-change events (possibly by being triggered by blkid runs triggered
> by udev triggered by the first block-change event).
> This accumulates to ~700 messages in this 5 seconds, which now taking nearly a
> minute for udev to process.
> If such a behaviour is allowed I cannot say.
> 
> 
> With attached printk-KOBJ_CHANGE.diff I isolated the two origins of
> these block-change events on the kernel side:
>   Mai 27 21:02:12.125582 rechner kernel: disk_check_events: 
> kobject_uevent_env KOBJ_CHANGE nr_events=1 envp[0]=DISK_MEDIA_CHANGE=1 size=0
> (405 times)
>   Mai 27 21:02:12.130620 rechner kernel: invalidate_partitions: 
> kobject_uevent KOBJ_CHANGE (0/0)
> (323 times)
> 
> 
> These are the origins of the function calls, as far as I could follow them:
>   blkdev_get
>   __blkdev_get (block_dev.c)
>   invalidate_partitions (partition-generic.c)
> 
>   check_disk_change (block_dev.c)
>   disk_clear_events (genhd.c)
>   disk_check_events (genhd.c)
> 
>   add_disk (genhd.c)
>   disk_alloc_events via INIT_DELAYED_WORK (genhd.c)
>   disk_events_workfn (genhd.c)
>   disk_check_events (genhd.c)
> 
> 
> I tried to find a way to avoid some of these events and possibly
> have found something for the invalidate_partitions path at least:
>   Does it make sense to send the block-change event in invalidate_partitions
>   when the disk had a size of 0 before and after checking its size?
>   (Or call invalidate_partitions in this case at all?)
> 
> 
> The second point is following question:
>   Does it make sense to insert an identically block-change event for this 
> device
>   when we know that there are already some in the queue?
>   (See attached drop-block-change-events-already-in-queue.patch)

just wanted to ask, if you still run into this issue with a newer kernel
(from testing). If so, I think it would probably best to re-assign this.

Regards,
Michael

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#782390: udev: time between USB-stick connection and device notification takes up to a minute

[Bernhard Übelacker]

Hello Marco, hello Michael,
sorry for the delay.
This is just to add some points to the bug.


On Sat, 11 Apr 2015 16:04:50 +0200 m...@linux.it (Marco d'Itri) wrote:
 Unless something is creating an events loop then this is an hardware 
 issue or a kernel bug.
 Considering that this only happens with a specific USB stick I will 
 assume that it is broken.

To me it looks like the creators of this stick intentionally made a
waiting time of 5 seconds between being recognized as USB stick and
actually inserting the media into it, like a card reader.
In this 5 seconds the kernel always tries to open the media and triggers
new block-change events (possibly by being triggered by blkid runs triggered
by udev triggered by the first block-change event).
This accumulates to ~700 messages in this 5 seconds, which now taking nearly a
minute for udev to process.
If such a behaviour is allowed I cannot say.


With attached printk-KOBJ_CHANGE.diff I isolated the two origins of
these block-change events on the kernel side:
  Mai 27 21:02:12.125582 rechner kernel: disk_check_events: kobject_uevent_env 
KOBJ_CHANGE nr_events=1 envp[0]=DISK_MEDIA_CHANGE=1 size=0
(405 times)
  Mai 27 21:02:12.130620 rechner kernel: invalidate_partitions: kobject_uevent 
KOBJ_CHANGE (0/0)
(323 times)


These are the origins of the function calls, as far as I could follow them:
  blkdev_get
  __blkdev_get (block_dev.c)
  invalidate_partitions (partition-generic.c)

  check_disk_change (block_dev.c)
  disk_clear_events (genhd.c)
  disk_check_events (genhd.c)

  add_disk (genhd.c)
  disk_alloc_events via INIT_DELAYED_WORK (genhd.c)
  disk_events_workfn (genhd.c)
  disk_check_events (genhd.c)


I tried to find a way to avoid some of these events and possibly
have found something for the invalidate_partitions path at least:
  Does it make sense to send the block-change event in invalidate_partitions
  when the disk had a size of 0 before and after checking its size?
  (Or call invalidate_partitions in this case at all?)


The second point is following question:
  Does it make sense to insert an identically block-change event for this device
  when we know that there are already some in the queue?
  (See attached drop-block-change-events-already-in-queue.patch)


Kind regards,
Bernhard
diff -Nurp ../orig/linux-3.16.7-ckt9/block/genhd.c linux-3.16.7-ckt9/block/genhd.c
--- ../orig/linux-3.16.7-ckt9/block/genhd.c	2015-03-30 12:09:09.0 +0200
+++ linux-3.16.7-ckt9/block/genhd.c	2015-05-27 16:39:55.643254200 +0200
@@ -1652,8 +1652,11 @@ static void disk_check_events(struct dis
 		if (events  disk-events  (1  i))
 			envp[nr_events++] = disk_uevents[i];
 
-	if (nr_events)
+	if (nr_events) {
+		printk(disk_check_events: kobject_uevent_env KOBJ_CHANGE nr_events=%d envp[0]=%s size=%lld\n,
+			nr_events, envp[0], (loff_t)get_capacity(disk)  9);
 		kobject_uevent_env(disk_to_dev(disk)-kobj, KOBJ_CHANGE, envp);
+	}
 }
 
 /*
diff -Nurp ../orig/linux-3.16.7-ckt9/block/partition-generic.c linux-3.16.7-ckt9/block/partition-generic.c
--- ../orig/linux-3.16.7-ckt9/block/partition-generic.c	2015-03-30 12:09:09.0 +0200
+++ linux-3.16.7-ckt9/block/partition-generic.c	2015-05-27 16:40:52.989463697 +0200
@@ -532,10 +532,13 @@ rescan:
 int invalidate_partitions(struct gendisk *disk, struct block_device *bdev)
 {
 	int res;
+	loff_t size_before, size_after;
 
 	if (!bdev-bd_invalidated)
 		return 0;
 
+	size_before = (loff_t)get_capacity(disk)  9;
+
 	res = drop_partitions(disk, bdev);
 	if (res)
 		return res;
@@ -543,6 +546,10 @@ int invalidate_partitions(struct gendisk
 	set_capacity(disk, 0);
 	check_disk_size_change(disk, bdev);
 	bdev-bd_invalidated = 0;
+
+	size_after = (loff_t)get_capacity(disk)  9;
+
+	printk(invalidate_partitions: kobject_uevent KOBJ_CHANGE (%lld/%lld)\n, size_before, size_after);
 	/* tell userspace that the media / partition table may have changed */
 	kobject_uevent(disk_to_dev(disk)-kobj, KOBJ_CHANGE);
 
Mai 27 21:02:10.889774 rechner kernel: usb 1-2: new high-speed USB device 
number 4 using ehci-pci
Mai 27 21:02:11.021904 rechner kernel: usb 1-2: New USB device found, 
idVendor=08ec, idProduct=0016
Mai 27 21:02:11.022190 rechner kernel: usb 1-2: New USB device strings: Mfr=1, 
Product=2, SerialNumber=3
Mai 27 21:02:11.022415 rechner kernel: usb 1-2: Product: FlashPen
Mai 27 21:02:11.022624 rechner kernel: usb 1-2: Manufacturer: Hama
Mai 27 21:02:11.022852 rechner kernel: usb 1-2: SerialNumber: 0F719B50E0101924
Mai 27 21:02:11.029600 rechner mtp-probe[1582]: checking bus 1, device 4: 
/sys/devices/pci:00/:00:02.1/usb1/1-2
Mai 27 21:02:11.030838 rechner mtp-probe[1582]: bus: 1, device: 4 was not an 
MTP device
Mai 27 21:02:11.098067 rechner kernel: usb-storage 1-2:1.0: USB Mass Storage 
device detected
Mai 27 21:02:11.110079 rechner kernel: scsi7 : usb-storage 1-2:1.0
Mai 27 21:02:11.110211 rechner kernel: usbcore: registered new interface driver 
usb-storage
Mai 

Bug#782390: udev: time between USB-stick connection and device notification takes up to a minute

[Marco d'Itri]

On Apr 11, Bernhard Übelacker bernha...@vr-web.de wrote:

 I am unsure if this is strictly a problem with systemd-udev, which should
 be prepared for such a event storm, or if it should be assigned to the
 kernel, where I assume these events are originating from.
Unless something is creating an events loop then this is an hardware 
issue or a kernel bug.
Considering that this only happens with a specific USB stick I will 
assume that it is broken.

-- 
ciao,
Marco


pgpO63Y4ofmwJ.pgp
Description: PGP signature

Bug#782390: udev: time between USB-stick connection and device notification takes up to a minute

[Michael Biebl]

Am 11.04.2015 um 15:17 schrieb Bernhard Übelacker:
 Package: udev
 Version: 215-14
 Severity: normal
 
 Dear Maintainer,
 when I insert a specific USB-stick I see following symptoms:
 - cpu usage rises (/lib/systemd/systemd-udevd, /usr/lib/udisks2/udisksd,
 /usr/bin/plasma-desktop)
 - it takes up to a minute until the device notifier popups.
 
 Took then a closer look by calling (udevadm monitor | ts  journalctl -f) 
 systemd-udevd-008-hama.txt
 when doing following actions (see attached file systemd-udevd-006.txt):
 
 - 14:50:00 physically attached USB-stick
 - 14:50:01 kernel: sd 12:0:0:0: [sdd] Attached SCSI removable disk
 - 14:50:02 KERNEL[99837.550175] change
 /devices/pci:00/:00:02.1/usb1/1-1/1-1:1.0/host15/target15:0:0/15:0:0:0/block/sde
 (block)
 -  this KERNEL.*change.*block message is received another 741 times
 - 14:50:05 rechner kernel: sd 15:0:0:0: [sde] 2004991 512-byte logical blocks:
 (1.02 GB/978 MiB)
 - 14:50:05 KERNEL[99840.590862] add
 /devices/pci:00/:00:02.1/usb1/1-1/1-1:1.0/host15/target15:0:0/15:0:0:0/block/sde/sde1
 (block)
 - 14:50:59 UDEV  [99894.356135] add
 /devices/pci:00/:00:02.1/usb1/1-1/1-1:1.0/host15/target15:0:0/15:0:0:0/block/sde/sde1
 (block)
 - 14:50:59 now the device notifier was opened
 
 It seems that for this USB-stick the kernel sends too early/too many
 of these change block events.
 Unfortunately receiving this events is much cheaper than processing
 them, so in these 3 seconds there are 9 times more received than processed.
 
 As all events are put into a queue the final add block event is only
 processed when all change block before were finished. In this case
 this took from 14:50:02 to 14:50:59.
 
 I am unsure if this is strictly a problem with systemd-udev, which should
 be prepared for such a event storm, or if it should be assigned to the
 kernel, where I assume these events are originating from.
 
 Kind regards,
 Bernhard
 
 
 
 root@rechner:~# uname -a
 Linux rechner 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt7-1 (2015-03-01) x86_64
 GNU/Linux


Processing 1000 udev add events can be costly, because udev will likely
spawn lots of (external) helpers, like blkid.
Depending on how fast your system is, that can take a while.

Smells like a kernel (or hardware bug), if it generates almost 1000 add
events for the same device.

Ben, what do you think?



-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature