Bug#663931: Same problem

[Jim Paris]

I'm having the same problem here.  udev seems to have problems after
libvirtd starts (even after libvirtd exits).  This in turn causes
problems with virt-manager.

  # /etc/init.d/udev stop
  Stopping the hotplug events dispatcher: udevd.
  # /etc/init.d/udev start
  Starting the hotplug events dispatcher: udevd.
  Synthesizing the initial hotplug events...done.
  Waiting for /dev to be fully populated...done.
  # time udevadm settle

  real    0m0.262s
  user    0m0.000s
  sys     0m0.004s
  # libvirtd -v
  2012-04-21 20:50:01.643+0000: 16223: info : libvirt version: 0.9.11
  ^C
  # time udevadm settle

  real	 2m0.159s
  user    0m0.004s
  sys     0m0.016s
  #

Note that just starting, then stopping libvirtd, causes udevadm settle
to suddenly take 2 minutes.  Even with libvirtd no longer running, and
udevadm settle will now always take 2 minutes until it is restarted.

In "udevadm monitor", starting libvirtd results in:

  KERNEL[511713.149926] add      /devices/virtual/net/lo/queues/rx-0 (queues)
  KERNEL[511713.149960] add      /devices/virtual/net/lo/queues/tx-0 (queues)
  UDEV  [511713.151394] add      /devices/virtual/net/lo/queues/tx-0 (queues)
  UDEV  [511713.151427] add      /devices/virtual/net/lo/queues/rx-0 (queues)
  KERNEL[511713.224143] remove   /devices/virtual/net/lo/queues/rx-0 (queues)
  KERNEL[511713.224167] remove   /devices/virtual/net/lo/queues/tx-0 (queues)
  UDEV  [511713.224610] remove   /devices/virtual/net/lo/queues/rx-0 (queues)
  UDEV  [511713.225180] remove   /devices/virtual/net/lo/queues/tx-0 (queues)

In syslog output after "udevadm control --log-priority debug",
starting libvirtd results in:

  Apr 21 16:56:51 p udevd[17521]: udevd message (SYNC) received 
  Apr 21 16:56:53 p udevd[17521]: seq 7530 queued, 'add' 'queues' 
  Apr 21 16:56:53 p udevd[17521]: seq 7530 forked new worker [18181] 
  Apr 21 16:56:53 p udevd[17521]: seq 7531 queued, 'add' 'queues' 
  Apr 21 16:56:53 p udevd[18181]: seq 7530 running 
  Apr 21 16:56:53 p udevd[17521]: seq 7531 forked new worker [18183] 
  Apr 21 16:56:53 p udevd[18183]: seq 7531 running 
  Apr 21 16:56:53 p udevd[18183]: passed -1 bytes to netlink monitor 0x1ff6730 
  Apr 21 16:56:53 p udevd[18181]: passed -1 bytes to netlink monitor 0x2006750 
  Apr 21 16:56:53 p udevd[17521]: seq 7530 done with 0 
  Apr 21 16:56:53 p udevd[18183]: seq 7531 processed with 0 
  Apr 21 16:56:53 p udevd[17521]: seq 7531 done with 0 
  Apr 21 16:56:53 p udevd[18181]: seq 7530 processed with 0 
  Apr 21 16:56:54 p udevd[17521]: seq 7532 queued, 'remove' 'queues' 
  Apr 21 16:56:54 p udevd[17521]: passed 168 bytes to netlink monitor 0x1ff5370 
  Apr 21 16:56:54 p udevd[17521]: seq 7533 queued, 'remove' 'queues' 
  Apr 21 16:56:54 p udevd[17521]: passed 168 bytes to netlink monitor 0x1ff5370 
  Apr 21 16:56:54 p udevd[18181]: seq 7532 running 
  Apr 21 16:56:54 p udevd[18183]: seq 7533 running 
  Apr 21 16:56:54 p udevd[18183]: no db file to read /dev/.udev/data/+queues:tx-0: No such file or directory 
  Apr 21 16:56:54 p udevd[18181]: no db file to read /dev/.udev/data/+queues:rx-0: No such file or directory 
  Apr 21 16:56:54 p udevd[18181]: passed -1 bytes to netlink monitor 0x2006750 
  Apr 21 16:56:54 p udevd[18181]: seq 7532 processed with 0 
  Apr 21 16:56:54 p udevd[17521]: seq 7532 done with 0 
  Apr 21 16:56:54 p udevd[18183]: passed -1 bytes to netlink monitor 0x1ff6730 
  Apr 21 16:56:54 p udevd[18183]: seq 7533 processed with 0 
  Apr 21 16:56:54 p udevd[17521]: seq 7533 done with 0 

udevadm settle is eventually just timing out.  Looking into why:
  # cat /sys/kernel/uevent_seqnum
  7534
  # od -N 2 -t d2 /dev/.udev/queue.bin | head -1
  0000000   7533

So there was another event 7534 that udev never saw, and that's
causing settle to time out.  Weird.  Maybe a kernel bug?
Running "udevadm monitor --kernel --property" in parallel to those
previous commands shows events up to 7533, but not 7534.  And
if I run libvirtd again, it will jump right to 7535.

I'll try to debug this more when I get a chance..

-jim