On Thu, 4 Jan 2018 10:50:06 +0300 Andrei Borzenkov <arvidjaar@gmail.com> wrote:
03.01.2018 18:57, Paul Neuwirth пишет:
journalctl shows best, that it is in fact udevd..
Actually udevd is probably just the messenger here. Annotated log
Jan 03 11:25:27 kappa kernel: scsi 0:0:3:0: Direct-Access TEAC FC-5 HGF 00 RV D PQ: 0 ANSI: 1 CCS Jan 03 11:25:27 kappa kernel: sd 0:0:3:0: Attached scsi generic sg4 type 0 Jan 03 11:25:27 kappa kernel: sd 0:0:3:0: Power-on or device reset occurred Jan 03 11:25:27 kappa kernel: sd 0:0:3:0: [sdc] Spinning up disk...
This comes from kernel directly. It does it as the first step when probing for new SCSI disk. Note that if device explicitly says that medium is not present, "Spinning up" is skipped.
Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Read Capacity(10) failed: Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Sense Key : Not Ready [current] Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Add. Sense: Logical unit not ready, cause not reportable Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Write Protect is on Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Mode Sense: 37 88 80 08 Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Asking for cache data failed Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Assuming drive cache: write through
The above is executed only if driver thinks that medium is present (otherwise there is no point to even attempt to read capacity). Driver starts with assumption it is. Again - if device returns proper sense code indicating no medium is present, this step should have been skipped. Still, as READ CAPACITY fails we should have reset "medium present" indication ...
... and we announce block device sdc to user space (i.e. udevd) now. So udevd spawns handler thread.
Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Spinning up disk...
Still kernel directly.
Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Spinning up disk...
And *this* comes from udevd handler trying to open device node. Which triggers device revalidation. And apparently it also resets "medium not present" flag back because driver has never received proper response from device. And because driver flips this flag from TRUE to FALSE it apparently generates change event. Which spawns yet another udevd handler which tries to open device node ... notice incrementing event numbers:
Jan 03 11:28:09 kappa systemd-udevd[613]: seq 2990 '/devices/pci0000:00/0000:00:0a.0/0000:01: 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time Jan 03 11:31:30 kappa systemd-udevd[613]: seq 2991 '/devices/pci0000:00/0000:00:0a.0/0000:01: 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time Jan 03 11:36:31 kappa systemd-udevd[613]: seq 2992 '/devices/pci0000:00/0000:00:0a.0/0000:01: 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time Jan 03 11:41:32 kappa systemd-udevd[613]: seq 2993 '/devices/pci0000:00/0000:00:0a.0/0000:01: 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time
Could you please reproduce it once more and provide output of "udevadm monitor -k" to confirm this.
thank you for your help. just reloaded kernel modue, and output of command: # udevadm monitor -k monitor will print the received events for: KERNEL - the kernel uevent ^Z [1]+ Stopped udevadm monitor -k # rmmod aic7xxx # fg udevadm monitor -k KERNEL[487599.298381] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/bsg/0:0:0:0 (bsg) KERNEL[487599.298422] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_generic/sg3 (scsi_generic) KERNEL[487599.298440] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_device/0:0:0:0 (scsi_device) KERNEL[487599.298465] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0 (scsi) KERNEL[487599.298481] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/spi_transport/target0:0:0 (spi_transport) KERNEL[487599.298506] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0 (scsi) KERNEL[487599.298531] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/bsg/0:0:3:0 (bsg) KERNEL[487599.298556] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_generic/sg4 (scsi_generic) KERNEL[487599.298571] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_device/0:0:3:0 (scsi_device) KERNEL[487599.298587] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_disk/0:0:3:0 (scsi_disk) KERNEL[487599.298600] remove /devices/virtual/bdi/8:32 (bdi) KERNEL[487599.298624] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[487599.298646] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi) KERNEL[487599.298663] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/spi_transport/target0:0:3 (spi_transport) KERNEL[487599.298685] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3 (scsi) KERNEL[487599.298709] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/bsg/0:0:4:0 (bsg) KERNEL[487599.298733] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_generic/sg5 (scsi_generic) KERNEL[487599.298749] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_device/0:0:4:0 (scsi_device) KERNEL[487599.298770] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0 (scsi) KERNEL[487599.298785] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/spi_transport/target0:0:4 (spi_transport) KERNEL[487599.298806] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4 (scsi) KERNEL[487599.298830] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/bsg/0:0:5:0 (bsg) KERNEL[487599.298856] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_generic/sg7 (scsi_generic) KERNEL[487599.298871] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_device/0:0:5:0 (scsi_device) KERNEL[487599.298894] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0 (scsi_tape) KERNEL[487599.298918] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0 (scsi_tape) KERNEL[487599.298941] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0l (scsi_tape) KERNEL[487599.298965] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0l (scsi_tape) KERNEL[487599.298990] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0m (scsi_tape) KERNEL[487599.299014] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0m (scsi_tape) KERNEL[487599.299038] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0a (scsi_tape) KERNEL[487599.299061] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0a (scsi_tape) KERNEL[487599.299083] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0 (scsi) KERNEL[487599.299098] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/spi_transport/target0:0:5 (spi_transport) KERNEL[487599.299119] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5 (scsi) KERNEL[487599.299134] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/spi_host/host0 (spi_host) KERNEL[487599.299148] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/scsi_host/host0 (scsi_host) KERNEL[487599.299168] remove /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0 (scsi) KERNEL[487599.299183] remove /bus/pci/drivers/aic7xxx (drivers) KERNEL[487599.299196] remove /module/aic7xxx (module) ^Z [1]+ Stopped udevadm monitor -k # modprobe aic7xxx; fg udevadm monitor -k KERNEL[487838.926097] add /module/aic7xxx (module) KERNEL[487838.926140] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0 (scsi) KERNEL[487838.926157] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/scsi_host/host0 (scsi_host) KERNEL[487838.926172] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/spi_host/host0 (spi_host) KERNEL[487838.926199] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0 (scsi) KERNEL[487838.926215] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/spi_transport/target0:0:0 (spi_transport) KERNEL[487838.926238] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0 (scsi) KERNEL[487838.926253] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_device/0:0:0:0 (scsi_device) KERNEL[487838.926278] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_generic/sg3 (scsi_generic) KERNEL[487838.926304] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/bsg/0:0:0:0 (bsg) KERNEL[487838.926326] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3 (scsi) KERNEL[487838.926340] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/spi_transport/target0:0:3 (spi_transport) KERNEL[487838.926363] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi) KERNEL[487838.926378] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_disk/0:0:3:0 (scsi_disk) KERNEL[487838.926392] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_device/0:0:3:0 (scsi_device) KERNEL[487838.926415] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_generic/sg4 (scsi_generic) KERNEL[487838.926440] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/bsg/0:0:3:0 (bsg) KERNEL[487838.926465] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi) KERNEL[487838.926488] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4 (scsi) KERNEL[487838.926503] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/spi_transport/target0:0:4 (spi_transport) KERNEL[487838.926525] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0 (scsi) KERNEL[487838.926540] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_device/0:0:4:0 (scsi_device) KERNEL[487838.926563] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_generic/sg5 (scsi_generic) KERNEL[487838.926587] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/bsg/0:0:4:0 (bsg) KERNEL[487838.926609] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5 (scsi) KERNEL[487838.926623] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/spi_transport/target0:0:5 (spi_transport) KERNEL[487838.926645] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0 (scsi) KERNEL[487838.926669] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0 (scsi_tape) KERNEL[487838.926694] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0 (scsi_tape) KERNEL[487838.926717] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0l (scsi_tape) KERNEL[487838.926741] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0l (scsi_tape) KERNEL[487838.926766] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0m (scsi_tape) KERNEL[487838.926790] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0m (scsi_tape) KERNEL[487838.926813] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0a (scsi_tape) KERNEL[487838.926838] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0a (scsi_tape) KERNEL[487838.926853] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_device/0:0:5:0 (scsi_device) KERNEL[487838.926877] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_generic/sg7 (scsi_generic) KERNEL[487838.926902] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/bsg/0:0:5:0 (bsg) KERNEL[487838.926917] add /bus/pci/drivers/aic7xxx (drivers) KERNEL[487838.926930] add /devices/virtual/bdi/8:32 (bdi) KERNEL[487838.926954] add /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[487838.926986] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[487838.927021] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[487838.927054] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[487939.384425] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[488039.884765] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block) KERNEL[488039.895676] change /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)