2.6.33: USB drive detection problem

I am testing the 2.6.33-rc8 kernel, and have a problem with detection of USB drives at bootup.

The 'init' script runs 'dmesg' to look for certain messages after the usb-storage kernel module has been loaded, such as:

usb-storage: device found at 3
usb-storage: waiting for device to settle before scanning
usb-storage: device scan complete


However, these are no longer output, so the 'init' script times-out waiting for them, which greatly slows bootup time.

I searched and found that drivers/usb/storage/usb.c in the kernel source was changed at 2.6.33-rc1:

-   printk(KERN_DEBUG

- "usb-storage: device found at %d\n", us->pusb_dev->devnum);
+ dev_dbg(&us->pusb_intf->dev, "device found\n");

set_freezable();
/* Wait for the timeout to expire or for a disconnect */
if (delay_use > 0) {
- printk(KERN_DEBUG "usb-storage: waiting for device "
- "to settle before scanning\n");
+ dev_dbg(&us->pusb_intf->dev, "waiting for device to settle "
+ "before scanning\n");
wait_event_freezable_timeout(us->delay_wait,
test_bit(US_FLIDX_DONT_SCAN, &us->dflags),
delay_use * HZ);
@@ -832,7 +839,7 @@ static int usb_stor_scan_thread(void * __us)
mutex_unlock(&us->dev_mutex);
}
scsi_scan_host(us_to_host(us));
- printk(KERN_DEBUG "usb-storage: device scan complete\n");
+ dev_dbg(&us->pusb_intf->dev, "scan complete\n");

/* Should we unbind if no devices were detected? */
}


Here is the full change file:
http://www.linuxhq.com/kernel/v2.6/33-rc1/drivers/usb/storage/usb.c

- printk(KERN_DEBUG "usb-storage: device scan complete\n");
+ dev_dbg(&us->pusb_intf->dev, "scan complete\n");


...this change is something I don't understand. Can any C expert tell me where that new "scan complete" message is going?

I suppose, I could patch usb.c and bring back those printk statements!


Posted on 17 Feb 2010, 2:30


Comments:

Posted on 17 Feb 2010, 2:57 by BarryK
usb-storage debug
I thought maybe that I had to turn on debug mode for the usb-storage module, to get those messages.
So, I recompiled the kernel, tested it, and do get a lot of information but not those particular messages. I don't know where they are going to.



Posted on 17 Feb 2010, 5:17 by technosaurus
No Usb boot in 2.6.33?
Good catch on that one.
Not a C guru, but will try & work through it...
Is there a separate kernel switch for device debugging (vice kern_debug)?
if not is patching to revert to printk where needed acceptable? I'm sure you aren't the only one who has used this for init
also... what other stuff might similar patches have broken? sda, netsetup etc... they tend to change things like that across the board if for a seemingly good reason.


Posted on 17 Feb 2010, 8:50 by technosaurus
debug_level sysfs
I thought I remembered seeing something about per device debugging back when you were building the .31 kernel - here is a link mentioning it for iwlwifi
http://patchwork.kernel.org/patch/40034/

it talks about debug_level & sysfs... so perhaps the debug messages are going to /sys/bus/usb/drivers

I wonder if this is a method to allow turning off printk to speed up boot by not writing so many messages


Posted on 17 Feb 2010, 9:14 by BarryK
Nothing in /sys
I poked around in /sys, can't find those messages.

I noticed something odd. Running the 2.6.31.5 kernel, I have /sys/module/usb_storage, but in 2.6.33-rc8 the /sys/module/usb_storage directory is missing, even though the module is loaded.

...that seems very wrong. Seems that someone is stuffing up the usb_storage module, just before 2.6.33 final is to be released?




Posted on 17 Feb 2010, 9:28 by Dionicio
Vala on Gnome Jornal
http://www.gnomejournal.org/article/80/writing-multimedia-applications-with-vala

Maybe of your interest

:)


Posted on 17 Feb 2010, 9:29 by Raymundo Dionicio
Vala on Gnome Jornal
http://www.gnomejournal.org/article/80/writing-multimedia-applications-with-vala

Maybe of your interest

:)


Posted on 17 Feb 2010, 9:47 by BarryK
USB bugs reports
I have filed bug reports:

http://bugzilla.kernel.org/show_bug.cgi?id=15332
http://bugzilla.kernel.org/show_bug.cgi?id=15333



Posted on 17 Feb 2010, 11:15 by j3
printk and dev_dbg
It looks like dev_dbg is used to allow the message to be generated on debug kernels when the logging level is set to 8, but dev_dbg will be omitted from non-debug kernels. It seems odd that these messages would be switched off unless there's now a better way of detecting the device.
Reference:
http://kernelnewbies.org/FAQ/LinuxKernelDebug101


Posted on 18 Feb 2010, 5:35 by technosaurus
mdev -s (busybox)
Are we just using these to populate /dev from /sys ?

busybox can do this using mdev... I know with your recent experiment with busybox this may seem like a bad plan, but "Cross Linux From Scratch" uses it by default ... I couldn't speculate on any speed gains or losses though, nor what it's full capabilities are

here are a couple of primers for using busybox mdev
http://cross-lfs.org/view/clfs-embedded-0.0.1/x86/bootscripts/mdev.html
http://wildanm.wordpress.com/2007/08/21/mdev-mini-udev-in-busybox/


Posted on 18 Feb 2010, 7:53 by BarryK
re mdev
Puppy uses a quasi-static system.

There is a static /dev, in both initramfs and the main f.s.

udevd will create new devnodes on an as-needed basis, when a device driver loads. It does this automatically, don't even need any udev rules (which is one reason why you will find /etc/udev/rules.d is relatively unpopulated in Puppy compared with other distros (most of the files in there were added by rerwin, deemed by him necessary for modems, but my original design only had 2-3 files).

This approach is very simple, and is the fastest. All that stuff about mounting a tmpfs on /dev then populating it, is unnecessary.



Posted on 19 Feb 2010, 23:42 by Dougal
P1
You're really not going to get any help that way...
Both gregkh and akpm are nice fellas, but if you set it to high priority and demand they change it, quoting distro-specific usage, you're not likely to get much help.
It would have made more sense to set it to a medium/low priority and just ask what happened (quoting the bit of code that changed).



Posted on 20 Feb 2010, 11:04 by BarryK
Re: usb-storage messages
Dougal,
Yeah, I know I approached it wrong. I got annoyed by the reply of one of those fellows that "no distros" (other than Puppy) read those log messages.

So now I have got their backs up and they won't reconsider.

So, I'll just patch the file.



Posted on 24 Feb 2010, 13:53 by technosaurus
No other distro is smart enough
"No, you should not be grepping kernel logs for init sequences, no other distro
needs this. Please file a bug with your distro to fix their code."

Yeah Barry didn't you realize that kernel logs were only for leisurely reading - not for anything useful.

God forbid you do something a better way that the "big dogs" can't adapt to compete against.

I don' think you approached it wrong at all - the flat NO without considering the reason for the request was inappropriate at best and at least inconsistent with the principles of open source.

Forcing everyone to use udevd or similar is the equivalent of hard-coding a large kernel module to be enabled on all builds when it is only needed in some.


Posted on 26 Feb 2010, 2:45 by Chad
Hmm...
Looking at the log from my Ubuntu Karmic system, I think I see how to get around it... unless 2.6.33 removes those lines too ;)

[363247.332791] scsi6 : SCSI emulation for USB Mass Storage devices
[363247.333083] usb-storage: device found at 6
[363247.333089] usb-storage: waiting for device to settle before scanning
[363252.332872] usb-storage: device scan complete
[363252.389611] scsi 6:0:0:0: Direct-Access RIM BlackBerry SD 0003 PQ: 0 ANSI: 4 CCS

Assuming the two bookending SCSI lines are there it should be possible to pick apart when scsi gets the mass storage device and the actual scan from the scsi 6:0:0:0... line.


Posted on 4 Mar 2010, 17:34 by BarryK
usb-storage patch
Note that I am using 2.6.33-git7 in Quirky 008, and this has a patch to restore the old 'printk' statements in the usb-storage code. Link to source and patches:

http://bkhome.org/blog/?viewDetailed=01419



Posted on 12 Sep 2012, 4:58 by K Godt
RE : Where are they going to
Am at going to compile a "full-featured kernel" and was undecided if i still a) need the prink statements and b) if i could insert them from memory . When i first started to compile kernels two years ago i did thought that these prink messages were introduced by puppy . Now i understand things better .

So i delved inside the source with grep and finally came up with :
CONFIG_DYNAMIC_DEBUG:
This mechanism implicitly enables all pr_debug() and dev_dbg() calls. The impact of this compile option is a larger kernel text size of about 2%.

Thus, the debugfs filesystem must first be mounted before making use of this feature.

#

So it would be something like
"
Traditionally debugfs is supposed to be mounted at /sys/kernel/debug with the following command:

mount -t debugfs none /sys/kernel/debug/


That's the recommended place to put it."

http://lwn.net/Articles/323307/


Posted on 12 Sep 2012, 5:28 by K Godt
waiting for devices to settle :
And further, they do not go somewhere into a log file in /sys/kernel/debug .

Attaching an usb-hdd , dmesg shows :

[21017.321019] usb 1-3: new high-speed USB device number 3 using ehci_hcd
[21017.436132] usb 1-3: New USB device found, idVendor=4971, idProduct=1014
[21017.436136] usb 1-3: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[21017.436139] usb 1-3: Product: Touro Mobile 3.0
[21017.436140] usb 1-3: Manufacturer: HitachiGST
[21017.436142] usb 1-3: SerialNumber: 21001110150000000758
[21017.437254] scsi14 : usb-storage 1-3:1.0
[21020.451294] scsi 14:0:0:0: Direct-Access HitachiG ST 0000 PQ: 0 ANSI: 6
[21020.451544] sd 14:0:0:0: Attached scsi generic sg6 type 0
[21022.471276] sd 14:0:0:0: [sdd] 976773116 512-byte logical blocks: (500 GB/465 GiB)
[21022.472022] sd 14:0:0:0: [sdd] Write Protect is off
[21022.472027] sd 14:0:0:0: [sdd] Mode Sense: 27 00 00 00
[21022.472768] sd 14:0:0:0: [sdd] No Caching mode page present
[21022.472772] sd 14:0:0:0: [sdd] Assuming drive cache: write through
[21022.475390] sd 14:0:0:0: [sdd] No Caching mode page present
[21022.475395] sd 14:0:0:0: [sdd] Assuming drive cache: write through
[21022.580020] sdd: sdd1 sdd2 sdd3 < sdd5 sdd6 sdd7 sdd8 sdd9 sdd10 >
[21022.585396] sd 14:0:0:0: [sdd] No Caching mode page present
[21022.585401] sd 14:0:0:0: [sdd] Assuming drive cache: write through
[21022.585405] sd 14:0:0:0: [sdd] Attached SCSI disk

*
Then
echo -n 'module usb_storage +p' >/sys/kernel/debug/dynamic_debug/control

gives me output in dmesg :
[21776.119277] dynamic_debug:ddebug_exec_queries: processed 1 queries, with 3 matches, 0 errs
[21799.975073] usb 1-3: USB disconnect, device number 3
[21841.849022] usb 1-3: new high-speed USB device number 4 using ehci_hcd
[21841.964177] usb 1-3: New USB device found, idVendor=4971, idProduct=1014
.
.
.
.
[21841.965484] scsi15 : usb-storage 1-3:1.0
[21841.965568] usb-storage 1-3:1.0: waiting for device to settle before scanning
[21842.968018] usb-storage 1-3:1.0: starting scan
[21844.979718] scsi 15:0:0:0: Direct-Access HitachiG ST 0000 PQ: 0 ANSI: 6
[21844.979969] sd 15:0:0:0: Attached scsi generic sg6 type 0
[21844.980814] sd 15:0:0:0: [sdd] 976773116 512-byte logical blocks: (500 GB/465 GiB)
.
.
[21844.982311] sd 15:0:0:0: [sdd] No Caching mode page present
[21844.982315] sd 15:0:0:0: [sdd] Assuming drive cache: write through
[21844.983971] usb-storage 1-3:1.0: scan complete
[21844.984688] sd 15:0:0:0: [sdd] No Caching mode page present
[21844.984693] sd 15:0:0:0: [sdd] Assuming drive cache: write through
[21845.071307] sdd: sdd1 sdd2 sdd3 < sdd5 sdd6 sdd7 sdd8 sdd9 sdd10 >
.
.
[21845.074058] sd 15:0:0:0: [sdd] Attached SCSI disk