[Apologies to copy recipients - I accidentally replied to only James earlier this evening. I've enclosed the text of my reply in square brackets at the relevant places below, followed, where appropriate, by my findings from tonight's investigations] On Sunday 08 June 2008, James Bottomley wrote: > On Sun, 2008-06-08 at 06:19 +0000, Chris Clayton wrote: > > --Boundary-00=_NG3SIU63+Zdv2JV > > Content-Type: text/plain; > > charset="utf-8" > > Content-Transfer-Encoding: quoted-printable > > Content-Disposition: inline > > > > On Friday 06 June 2008, James Bottomley wrote: > > > On Fri, 2008-06-06 at 11:03 -0700, Andrew Morton wrote: > > > > On Fri, 06 Jun 2008 10:22:22 -0500 James Bottomley=20 > > > > wrote: > > > > > On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote: > > > > > > On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton=20 > > > > wrote: > > > > > > > > > > > > > "CD/DVD-Record= > > > > er > > > > > > > > > not ready." Pretends not to have noticed.> > > > > > > > > > > > > It goes much better when the CD is inserted upside up. > > > > > > > > > > So I can close this regression if I send you a pack of CD ring > > > > > labels with "other way up" on them for you to affix to the > > > > > underside of your CDs ... ? > > > > > > > > Would prefer double-sided CDs. > > > > > > I just discovered my budget only runs to a permanent marker for you to > > > write the instructions on the rim yourself ... > > > > > > > Is this 20-second-delay thing known-about/expected/etc? > > > > > > If it's not the scsi_bus_uevent problem, then no, it isn't. > > > > > > The odd thing is that it occurs in the middle of USB initialisation > > > from > > > > Because of this oddity, I've also built 2.6.26-rc5-git2 with verbose USB > > debugging on. A boot log from that kernel is attached. You will see lots > > of ETIME errors from usb. A log from a similarly verbose 2.6.25.5 kernel > > does not show these errors. usb-devel added to cc list. > > I'm starting to think this might be a distribution problem. I tried > booting my laptop on your config (only system I have with ata_piix) > without an initrd (bit painful for fedora 9) and I didn't see any slow > downs (in fact it was a lot faster than previously; makes note to file > bug with redhat about their initramfs). > [OK, I'll start investigating this line. My desktop system was originally (the now lapsed) Peanut Linux, which was a Slackware derivative. But I've been running it for 3 or 4 years, upgrading and adding packages along the way. My udev setup is based on that in a fairly recent Slackware, although I can't now recall precisely which version.] For the time being I'll try and isolate what it is that causes the delay in icons appearing on my desktop when I plug in a usb-storage device. The script that shows the icon is invoked by adding the script name to udev's run list. Here is a typical rule from /etc/udev/rules.d/20-local.rules: ACTION=="add", KERNEL=="sd[a-z][0-9]", SYSFS{idProduct}=="6545", SYSFS{idVendor}=="0930", SYMLINK+="usbstickc%n", MODE="0666", RUN+="/usr/bin/udevshowicon.sh" I've added a couple of calls to logger (from util-linux-2.12r) to the script. What this has shown is that, when I plug in a usb-storage device, there seems to be a delay between the usb/scsi/usb-storage drivers setting up the device and my icon-showing script being run. Here is the snippet from the kernel log file: Jun 10 20:27:45 upstairs kernel: [ 3200.592107] hub 3-0:1.0: state 7 ports 5 chg 0000 evt 0004 Jun 10 20:27:45 upstairs kernel: [ 3200.592107] ehci_hcd 0000:02:0a.2: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT Jun 10 20:27:45 upstairs kernel: [ 3200.592107] hub 3-0:1.0: port 2, status 0501, change 0001, 480 Mb/s Jun 10 20:27:45 upstairs kernel: [ 3200.695130] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501 Jun 10 20:27:45 upstairs kernel: [ 3200.746270] ehci_hcd 0000:02:0a.2: port 2 high speed Jun 10 20:27:45 upstairs kernel: [ 3200.746279] ehci_hcd 0000:02:0a.2: GetStatus port 2 status 001005 POWER sig=se0 PE CONNECT Jun 10 20:27:45 upstairs kernel: [ 3200.797136] usb 3-2: new high speed USB device using ehci_hcd and address 9 Jun 10 20:27:45 upstairs kernel: [ 3200.811464] usb 3-2: default language 0x0409 Jun 10 20:27:45 upstairs kernel: [ 3200.812116] device: '3-2': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': add device 3-2 Jun 10 20:27:45 upstairs kernel: [ 3200.812116] PM: Adding info for usb:3-2 Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: uevent Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': driver_probe_device: matched device 3-2 with driver usb Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': really_probe: probing driver usb with device 3-2 Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: usb_probe_device Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: configuration #1 chosen from 1 choice Jun 10 20:27:45 upstairs kernel: [ 3200.814424] usb 3-2: adding 3-2:1.0 (config #1, interface 0) Jun 10 20:27:45 upstairs kernel: [ 3200.814434] device: '3-2:1.0': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.814458] bus: 'usb': add device 3-2:1.0 Jun 10 20:27:45 upstairs kernel: [ 3200.814466] PM: Adding info for usb:3-2:1.0 Jun 10 20:27:45 upstairs kernel: [ 3200.814479] usb 3-2:1.0: uevent Jun 10 20:27:45 upstairs kernel: [ 3200.814520] bus: 'usb': driver_probe_device: matched device 3-2:1.0 with driver usb-storage Jun 10 20:27:45 upstairs kernel: [ 3200.814526] bus: 'usb': really_probe: probing driver usb-storage with device 3-2:1.0 Jun 10 20:27:45 upstairs kernel: [ 3200.814569] usb-storage 3-2:1.0: usb_probe_interface Jun 10 20:27:45 upstairs kernel: [ 3200.814577] usb-storage 3-2:1.0: usb_probe_interface - got id Jun 10 20:27:45 upstairs kernel: [ 3200.814982] scsi10 : SCSI emulation for USB Mass Storage devices Jun 10 20:27:45 upstairs kernel: [ 3200.814994] device: 'host10': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.815006] bus: 'scsi': add device host10 Jun 10 20:27:45 upstairs kernel: [ 3200.815020] PM: Adding info for scsi:host10 Jun 10 20:27:45 upstairs kernel: [ 3200.815051] device: 'host10': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.815143] PM: Adding info for No Bus:host10 Jun 10 20:27:45 upstairs kernel: [ 3200.815303] driver: '3-2:1.0': driver_bound: bound to device 'usb-storage' Jun 10 20:27:45 upstairs kernel: [ 3200.815310] bus: 'usb': really_probe: bound device 3-2:1.0 to driver usb-storage Jun 10 20:27:45 upstairs kernel: [ 3200.815325] device: 'usbdev3.9_ep81': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.815375] PM: Adding info for No Bus:usbdev3.9_ep81 Jun 10 20:27:45 upstairs kernel: [ 3200.815401] device: 'usbdev3.9_ep02': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.815421] PM: Adding info for No Bus:usbdev3.9_ep02 Jun 10 20:27:45 upstairs kernel: [ 3200.815437] drivers/usb/core/inode.c: creating file '009' Jun 10 20:27:45 upstairs kernel: [ 3200.815446] driver: '3-2': driver_bound: bound to device 'usb' Jun 10 20:27:45 upstairs kernel: [ 3200.815449] bus: 'usb': really_probe: bound device 3-2 to driver usb Jun 10 20:27:45 upstairs kernel: [ 3200.815459] device: 'usbdev3.9_ep00': device_add Jun 10 20:27:45 upstairs kernel: [ 3200.815478] PM: Adding info for No Bus:usbdev3.9_ep00 Jun 10 20:27:45 upstairs kernel: [ 3200.815492] usb 3-2: New USB device found, idVendor=0930, idProduct=6545 Jun 10 20:27:45 upstairs kernel: [ 3200.815495] usb 3-2: New USB device strings: Mfr=0, Product=2, SerialNumber=3 Jun 10 20:27:45 upstairs kernel: [ 3200.815497] usb 3-2: Product: USB Flash Memory Jun 10 20:27:45 upstairs kernel: [ 3200.815500] usb 3-2: SerialNumber: 0EC065712361A91E Jun 10 20:27:45 upstairs kernel: [ 3200.815769] usb-storage: device found at 9 Jun 10 20:27:45 upstairs kernel: [ 3200.815772] usb-storage: waiting for device to settle before scanning Jun 10 20:27:50 upstairs kernel: [ 3205.817115] scsi 10:0:0:0: Direct-Access USB Flash Memory 5.00 PQ: 0 ANSI: 0 CCS Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: 'target10:0:0': device_add Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': add device target10:0:0 Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for scsi:target10:0:0 Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: '10:0:0:0': device_add Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': add device 10:0:0:0 Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for scsi:10:0:0:0 Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': driver_probe_device: matched device 10:0:0:0 with driver sd Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': really_probe: probing driver sd with device 10:0:0:0 Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: '10:0:0:0': device_add Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for No Bus:10:0:0:0 Jun 10 20:27:51 upstairs kernel: [ 3206.045117] sd 10:0:0:0: [sdd] 2013184 512-byte hardware sectors (1031 MB) Jun 10 20:27:51 upstairs kernel: [ 3206.045369] sd 10:0:0:0: [sdd] Write Protect is off Jun 10 20:27:51 upstairs kernel: [ 3206.045380] sd 10:0:0:0: [sdd] Mode Sense: 23 00 00 00 Jun 10 20:27:51 upstairs kernel: [ 3206.045386] sd 10:0:0:0: [sdd] Assuming drive cache: write through Jun 10 20:27:51 upstairs kernel: [ 3206.045425] device: 'sdd': device_add Jun 10 20:27:51 upstairs kernel: [ 3206.045495] PM: Adding info for No Bus:sdd Jun 10 20:27:51 upstairs kernel: [ 3206.047204] sd 10:0:0:0: [sdd] 2013184 512-byte hardware sectors (1031 MB) Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Write Protect is off Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Mode Sense: 23 00 00 00 Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Assuming drive cache: write through Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sdd: sdd1 Jun 10 20:27:51 upstairs kernel: [ 3206.049452] device: 'sdd1': device_add Jun 10 20:27:51 upstairs kernel: [ 3206.049482] PM: Adding info for No Bus:sdd1 Jun 10 20:27:51 upstairs kernel: [ 3206.049594] device: '8:48': device_add Jun 10 20:27:51 upstairs kernel: [ 3206.049623] PM: Adding info for No Bus:8:48 Jun 10 20:27:51 upstairs kernel: [ 3206.049648] sd 10:0:0:0: [sdd] Attached SCSI removable disk Jun 10 20:27:51 upstairs kernel: [ 3206.049654] driver: '10:0:0:0': driver_bound: bound to device 'sd' Jun 10 20:27:51 upstairs kernel: [ 3206.049660] bus: 'scsi': really_probe: bound device 10:0:0:0 to driver sd Jun 10 20:27:51 upstairs kernel: [ 3206.049667] device: '10:0:0:0': device_add Jun 10 20:27:51 upstairs kernel: [ 3206.049691] PM: Adding info for No Bus:10:0:0:0 Jun 10 20:27:51 upstairs kernel: [ 3206.050108] usb-storage: device scan complete And here is the output from the calls to logger, that get written to /var/log/messages: Jun 10 20:28:07 upstairs logger: udevshowicon: starting to get icon name Jun 10 20:28:07 upstairs logger: udevshowicon: about to show usbstickc1 As you can see, 16 seconds elapses between the drivers finishing and the script being run. That's an awful time on a system that is doing nothing (because I'm busy scratching my head and looking bewildered :-) I'm using udev-121, which is pretty recent. There is a later version, but the changelog doesn't describe any fixes that (to me) sound as if they would come anywhere near this problem. I'll do so more poking about tomorrow night, but if anyone has any ideas in the meantime, I'd be very grateful. > The one thing the patch you identified does is to add the SCSI target to > the BUS and type model for the generic device. What this does is to add > extra uevents for the target. If your hotplug handlers aren't set up to > expect this, they could be delaying the system progress. > > What hotplug scripts are you using (and does /sbin/hotplug exist)? > [ I don't have hotplug installed and CONFIG_UEVENT_HELPER_PATH is set to the empty string.] > > > > upstairs kernel: usb 11-2: Product: USB Flash Memory Jun 6 17:26:31 > > > > upstairs kernel: usb 11-2: SerialNumber: 0EC065712361A91E > > > > > > I'm a bit baffled as to how that could be SCSI related, but I suppose > > > it could be udev related somehow. Perhaps turning on driver core > > > debugging might help (that's CONFIG_DEBUG DRIVER ... it depends on > > > CONFIG_DEBUG_KERNEL for activation). Hopefully the verbose kernel logs > > > from here might tell us what's going on in the lacunae. > > > > Triggered by James' bafflement and for my own peace of mind, I've run > > another bisect session. This time I started with v2.6.26 as good and > > v2.6.26-rc2 as bad. It highlighted the same patch as the "culprit". > > Actually, that's not really necessary. Bisection is taking you back > through kernel history, so unless the bug has two separate causes, it's > pretty likely to home in on the same section of code. > [I appreciate that but I was a tint bit worried that, late i the process, I had reported an erronious good or bad to git bisect and ended up in the wrong place.] > James I've also attached a log from a boot with CONFIG_PRINTK_TIME enabled. Thanks Chris -- Beauty is in the eye of the beerholder.