[SOLVED] Boot delay with udevadm settle

[penetrode]

Starting today, my system hangs temporarily when creating the mtab symbolic link.

Code: Select all

* Creating mtab symbolic link
 [ ok ]
 * Importing ZFS pool(s)  ...
 [ ok ]

Both of these steps are ordinarily very fast and are now slow. I have to wait about a minute (in total) for them to complete. After and beyond that, the system boots normally.

I do daily world updates, just FYI.

What's causing this? Is there a problem with the proc filesystem? How should I go about troubleshooting this?

[penetrode]

Okay, I did some extensive troubleshooting. It has nothing to do with the mtab service, which completes quickly and normally.

The issue occurs in the udev_trigger function in zfs-functions:

Code: Select all

udev_trigger()
{
        if [ -x /sbin/udevadm ]; then
                /sbin/udevadm --debug trigger -v --action=change --subsystem-match=block
                /sbin/udevadm --debug settle --timeout=20
        elif [ -x /sbin/udevsettle ]; then
                /sbin/udevtrigger
                /sbin/udevsettle
        fi
}

It's udevadm settle where it hangs specifically. udevadm settle is supposed to wait until the event queue clears, but I cannot see what's in the event queue. In Redhat, udevadm spits out the contents of the event queue at timeout, but setting a short timeout here (20 seconds) did not have that effect.

These verbosity/debug settings are pretty useless. They tell me nothing except that settle was called.

Here's what I see in rc.log:

Code: Select all

calling: control
calling: trigger
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-1/2-1.2/2-1.2:1.0/host1/target1:0:0/1:0:0:0/block/sda
/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3/2-3:1.0/host0/target0:0:0/0:0:0:0/block/sdb
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1/nvme0n1p1
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1/nvme0n1p2
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1/nvme0n1p3
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1/nvme0n1p4
/sys/devices/pci0000:00/0000:00:1d.2/0000:3e:00.0/nvme/nvme0/nvme0n1/nvme0n1p5
/sys/devices/virtual/block/loop0
/sys/devices/virtual/block/loop1
/sys/devices/virtual/block/loop2
/sys/devices/virtual/block/loop3
/sys/devices/virtual/block/loop4
/sys/devices/virtual/block/loop5
/sys/devices/virtual/block/loop6
/sys/devices/virtual/block/loop7
/sys/devices/virtual/block/md0
calling: settle

[penetrode]

Okay, I found the cause.

Here's some output from syslog:

Code: Select all

Jun 15 12:35:38 t470 kernel: sd 1:0:0:0: [sda] tag#11 uas_zap_pending 0 uas-tag 1 inflight: CMD 
Jun 15 12:35:38 t470 kernel: sd 1:0:0:0: [sda] tag#11 CDB: Read(10) 28 00 00 00 02 08 00 01 f8 00
Jun 15 12:35:38 t470 kernel: usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jun 15 12:35:40 t470 kernel: scsi host1: uas_eh_device_reset_handler success
Jun 15 12:36:10 t470 kernel: scsi host1: uas_eh_device_reset_handler start
Jun 15 12:36:10 t470 kernel: sd 1:0:0:0: [sda] tag#10 uas_zap_pending 0 uas-tag 1 inflight: CMD 
Jun 15 12:36:10 t470 kernel: sd 1:0:0:0: [sda] tag#10 CDB: Read(10) 28 00 00 00 02 08 00 01 f8 00
Jun 15 12:36:10 t470 kernel: usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jun 15 12:36:12 t470 kernel: scsi host1: uas_eh_device_reset_handler success
Jun 15 12:36:42 t470 kernel: scsi host1: uas_eh_device_reset_handler start
Jun 15 12:36:42 t470 kernel: sd 1:0:0:0: [sda] tag#8 uas_zap_pending 0 uas-tag 1 inflight: CMD 
Jun 15 12:36:42 t470 kernel: sd 1:0:0:0: [sda] tag#8 CDB: Read(10) 28 00 00 00 02 08 00 01 f8 00
Jun 15 12:36:42 t470 kernel: usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jun 15 12:36:44 t470 kernel: scsi host1: uas_eh_device_reset_handler success
Jun 15 12:37:14 t470 kernel: scsi host1: uas_eh_device_reset_handler start
Jun 15 12:37:14 t470 kernel: sd 1:0:0:0: [sda] tag#9 uas_zap_pending 0 uas-tag 1 inflight: 
Jun 15 12:37:14 t470 kernel: sd 1:0:0:0: [sda] tag#9 CDB: Read(10) 28 00 00 00 02 08 00 01 f8 00
Jun 15 12:37:15 t470 kernel: usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jun 15 12:37:15 t470 kernel: scsi host1: uas_eh_device_reset_handler success
Jun 15 12:37:15 t470 kernel: sd 1:0:0:0: [sda] tag#9 FAILED Result: hostbyte=DID_RESET driverbyte=DRIVER_OK
Jun 15 12:37:15 t470 kernel: sd 1:0:0:0: [sda] tag#9 CDB: Read(10) 28 00 00 00 02 08 00 01 f8 00

The issue was an attached disk docking station with no disk in it that had inadvertently been left switched on. I turned it off, restarted the machine, boom, everything works.