Re: [linux-usb-devel] 2.5.42-ac1, 2.5.42, 2.5.41 boot hang with CONFIG_USB_DEBUG=n

Nicolas Mailhot (Nicolas.Mailhot@laPoste.net)
Fri, 18 Oct 2002 19:45:53 +0200


On 2002.10.15 19:10 David Brownell wrote:

>> I don't know if it's important, but I had to enable usb keyboard
>> legacy mode in the bios to have keyboard support in the bootloader
>> stage. I had a bad feeling about the option though, a good bios is a
>> lean bios.
>
> Unless your boot loader has a small USB stack, leave that emulation
> enabled in the bios. Linux will disable it when you bring up USB.
>
> But it'd be worth seeing if there were any problems with that. In
> fact,
> in drivers/usb/host/ohci-hcd.c there is one dbg() that could affect
> init timing. Experiment: leave all debug messages off, but change
> the first dbg() call in hc_reset() into an err() call. Does that make
> things better?

The answer is yes.

I've been testing like mad, with 2.5.42 then 2.5.43, with original gcc
then new gcc in rawhide ; I dumped the ps/2 mouse and serial io I went
all-usb (keyboard and mouse on usb hub, smartmedia combo reader
directly on usb port) in the hope it would help produce clear-cut
results.

I also did a memtest86 run to see if perhaps 2.5 poke in some bad ram
location while 2.4 didn't. Clean run, it seems my dimms are ok.

I feel changing dbg() in err() is a bit worse than full
CONFIG_USB_DEBUG=y. It certainly did hang more often at boot than with
CONFIG_USB_DEBUG=y. However :
* with err() I get about 50% boot chance
* with err() I've never so far booted with a useless keyboard (sole
times I booted with unchanged kernel and CONFIG_USB_DEBUG=n keyboard
was dead)
* when it hangs with err() the takeover message is printed (never was
before on hang)

Sometimes after 2.5.43 is booted switching to the console freezes the
usb mouse. Don't know if it's related to the boot hang, but
chain-restarting gpm will more often result into an oops than a
recovered mouse. However I've just found that re-pluging it instead of
restarting gpm unfreezes the mouse cursor.

Anyway, here is full dmesg output on a 2.5.43 kernel with err and
CONFIG_USB_DEBUG=n, after it did manage to boot, lost mouse, tried to
recover it via gpm then replugging it :

Linux version 2.5.43-rous4 (root@rousalka) (gcc version 3.2 20021015
(Red Hat Linux 8.0 3.2-10)) #1 Fri Oct 18 18:55:59 CEST 2002
Video mode to be used for restore is f00
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000000fff0000 (usable)
BIOS-e820: 000000000fff0000 - 000000000fff3000 (ACPI NVS)
BIOS-e820: 000000000fff3000 - 0000000010000000 (ACPI data)
BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
255MB LOWMEM available.
On node 0 totalpages: 65520
DMA zone: 4096 pages
Normal zone: 61424 pages
HighMem zone: 0 pages
Building zonelist for node : 0
Kernel command line: ro root=/dev/hdc1
No local APIC present or hardware disabled
Initializing CPU#0
Detected 549.008 MHz processor.
Console: colour dummy device 80x25
Calibrating delay loop... 1081.34 BogoMIPS
Memory: 255320k/262080k available (1987k kernel code, 6376k reserved,
624k data, 124k init, 0k highmem)
Security Scaffold v1.0.0 initialized
Dentry cache hash table entries: 32768 (order: 6, 262144 bytes)
Inode-cache hash table entries: 16384 (order: 5, 131072 bytes)
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: Before vendor init, caps: 0081f9ff c0c1f9ff 00000000, vendor = 2
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 512K (64 bytes/line)
CPU: After vendor init, caps: 0081f9ff c0c1f9ff 00000000 00000000
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
Machine check exception polling timer started.
CPU: After generic, caps: 0081f9ff c0c1f9ff 00000000 00000000
CPU: Common caps: 0081f9ff c0c1f9ff 00000000 00000000
CPU: AMD-K7(tm) Processor stepping 02
Checking 'hlt' instruction... OK.
POSIX conformance testing by UNIFIX
Linux NET4.0 for Linux 2.4
Based upon Swansea University Computer Society NET3.039
Initializing RT netlink socket
mtrr: v2.0 (20020519)
PCI: Using configuration type 1
adding '' to cpu class interfaces
drivers/usb/core/usb.c: registered new driver usbfs
drivers/usb/core/usb.c: registered new driver hub
PCI: Probing PCI hardware
PCI: Probing PCI hardware (bus 00)
Starting kswapd
BIO: pool of 256 setup, 15Kb (60 bytes/bio)
biovec pool[0]: 1 bvecs: 256 entries (12 bytes)
biovec pool[1]: 4 bvecs: 256 entries (48 bytes)
biovec pool[2]: 16 bvecs: 256 entries (192 bytes)
biovec pool[3]: 64 bvecs: 256 entries (768 bytes)
biovec pool[4]: 128 bvecs: 256 entries (1536 bytes)
biovec pool[5]: 256 bvecs: 256 entries (3072 bytes)
aio_setup: sizeof(struct page) = 40
VFS: Disk quotas vdquot_6.5.1
Journalled Block Device driver loaded
udf: registering filesystem
Capability LSM initialized
matroxfb: Matrox G400 (AGP) detected
MTRR: setting reg 1
matroxfb: MTRR's turned on
matroxfb: 640x480x32bpp (virtual: 640x6552)
matroxfb: framebuffer at 0xDE000000, mapped to 0xd0812000, size 33554432
Console: switching to colour frame buffer device 80x30
fb0: MATROX VGA frame buffer device
pty: 256 Unix98 ptys configured
Real Time Clock Driver v1.11
Non-volatile memory driver v1.2
Linux agpgart interface v0.99 (c) Jeff Hartmann
agpgart: Maximum main memory to use for agp memory: 203M
agpgart: Detected AMD Irongate chipset
agpgart: AGP aperture is 32M @ 0xdc000000
[drm] AGP 0.99 on AMD Irongate @ 0xdc000000 32MB
MTRR: setting reg 2
[drm] Initialized mga 3.0.2 20010321 on minor 0
block request queues:
128 requests per read queue
128 requests per write queue
8 requests per batch
enter congestion at 31
exit congestion at 33
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
ne2k-pci.c:v1.02 10/19/2000 D. Becker/P. Gortmaker
http://www.scyld.com/network/ne2k-pci.html
eth0: RealTek RTL-8029 found at 0xe800, IRQ 11, 52:54:00:EB:D1:C6.
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with
idebus=xx
AMD7409: IDE controller at PCI slot 00:07.1
AMD7409: chipset revision 3
AMD7409: not 100% native mode: will probe irqs later
AMD7409: disabling single-word DMA support (revision < C4)
ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:DMA
ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:DMA
hda: IBM-DJNA-371350, ATA DISK drive
hdb: TOSHIBA DVD-ROM SD-M1302, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
hdc: MAXTOR 6L080J4, ATA DISK drive
hdd: YAMAHA CRW2100E, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
hda: host protected area => 1
hda: 26520480 sectors (13578 MB) w/1966KiB Cache, CHS=1650/255/63,
UDMA(33)
hda: hda1 hda2 < hda5 hda6 >
hdc: host protected area => 1
hdc: 156355584 sectors (80054 MB) w/1819KiB Cache, CHS=155114/16/63,
UDMA(66)
hdc: hdc1 hdc2
hdb: ATAPI 40X DVD-ROM drive, 256kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.12
end_request: I/O error, dev 03:40, sector 0
end_request: I/O error, dev 03:40, sector 0
end_request: I/O error, dev 16:40, sector 0
hdd: ATAPI 40X CD-ROM CD-R/RW drive, 8192kB Cache, UDMA(25)
end_request: I/O error, dev 16:40, sector 0
end_request: I/O error, dev 16:40, sector 0
SCSI subsystem driver Revision: 1.00
scsi0 : SCSI host adapter emulation for IDE ATAPI devices
matroxfb_crtc2: secondary head of fb0 was registered as fb1
drivers/usb/core/hcd-pci.c: ohci-hcd @ 00:07.4, Advanced Micro Devices
[AMD] AMD-756 [Viper] USB
drivers/usb/core/hcd-pci.c: irq 12, pci mem d282c000
drivers/usb/core/hcd.c: new USB bus registered, assigned bus number 1
drivers/usb/host/ohci-pci.c: 00:07.4: AMD756 erratum 4 workaround
drivers/usb/host/ohci-hcd.c: USB HC TakeOver from SMM
drivers/usb/core/hub.c: USB hub found at 0
drivers/usb/core/hub.c: 4 ports detected
Initializing USB Mass Storage driver...
drivers/usb/core/usb.c: registered new driver usb-storage
USB Mass Storage support registered.
drivers/usb/core/usb.c: registered new driver hid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
register interface 'mouse' with class 'input
mice: PS/2 mouse device common for all mice
input: PC Speaker
Advanced Linux Sound Architecture Driver Version 0.9.0rc3 (Mon Oct 14
16:41:26 2002 UTC).
request_module[snd-card-0]: not ready
request_module[snd-card-1]: not ready
request_module[snd-card-2]: not ready
request_module[snd-card-3]: not ready
request_module[snd-card-4]: not ready
request_module[snd-card-5]: not ready
request_module[snd-card-6]: not ready
request_module[snd-card-7]: not ready
specify snd_port
ALSA device list:
#0: Ensoniq AudioPCI ES1371 at 0xe400, irq 10
NET4: Linux TCP/IP 1.0 for NET4.0
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP: Hash tables configured (established 16384 bind 32768)
ip_conntrack version 2.1 (2047 buckets, 16376 max) - 296 bytes per
conntrack
ip_tables: (C) 2000-2002 Netfilter core team
NET4: Unix domain sockets 1.0/SMP for Linux NET4.0.
kjournald starting. Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 124k freed
drivers/usb/core/hub.c: Cannot enable port 2 of hub 0, disabling port.
drivers/usb/core/hub.c: Maybe the USB cable is bad?
drivers/usb/core/hub.c: new USB device 00:07.4-4, assigned address 2
70 00 0C 00 00 00 00 0B 00 00 00 00 60 CB 00 00 00 00
scsi1 : SCSI emulation for USB Mass Storage devices
Vendor: Model: Rev:
Type: Direct-Access ANSI SCSI revision: 02
Vendor: SCM Micr Model: eUSB SmartMedia Rev: 0208
Type: Direct-Access ANSI SCSI revision: 02
Attached scsi disk sda at scsi1, channel 0, id 0, lun 0
Attached scsi removable disk sdb at scsi1, channel 0, id 0, lun 1
SCSI device sda: drive cache: write through
sda : sector size 0 reported, assuming 512.
SCSI device sda: 1 512-byte hdwr sectors (0 MB)
sda: unknown partition table
sdb : MODE SENSE failed.
sdb : status = 0, message = 00, host = 7, driver = 00
sdb : sense not available.
sdb : assuming drive cache: write through
usb_stor_clear_halt() WORKED!
usb_stor_clear_halt() WORKED!
sddr09: could not read card info
WARNING: USB Mass Storage data integrity not assured
USB Mass Storage device found at 2
drivers/usb/core/hub.c: new USB device 00:07.4-2, assigned address 3
drivers/usb/core/hub.c: USB hub found at 2
drivers/usb/core/hub.c: 4 ports detected
EXT3 FS 2.4-0.9.16, 02 Dec 2001 on ide1(22,1), internal journal
Adding 262072k swap on /dev/hdc2. Priority:-1 extents:1
Adding 265032k swap on /dev/hda6. Priority:-2 extents:1
drivers/usb/core/hub.c: new USB device 00:07.4-2.3, assigned address 4
input: USB HID v1.10 Mouse [Logitech USB Mouse] on usb-00:07.4-2.3
drivers/usb/core/hub.c: new USB device 00:07.4-2.4, assigned address 5
input: USB HID v1.00 Keyboard [046a:0001] on usb-00:07.4-2.4
drivers/usb/host/ohci-q.c: 00:07.4 bad entry f9791c1
drivers/usb/host/ohci-q.c: 00:07.4 bad entry afb7b7e1
drivers/usb/host/ohci-q.c: 00:07.4 bad entry ffffffe1
usbfs: process 1125 (lsusb) did not claim interface 0 before use
usbfs: process 1125 (lsusb) did not claim interface 0 before use
usbfs: USBDEVFS_CONTROL failed dev 3 rqt 128 rq 6 len 256 ret -32
usbfs: USBDEVFS_CONTROL failed dev 3 rqt 128 rq 6 len 256 ret -32
drivers/usb/host/ohci-q.c: 00:07.4 bad entry 5fb7d1e1
drivers/usb/host/ohci-q.c: 00:07.4 bad entry ffffffe1
drivers/usb/host/ohci-q.c: 00:07.4 bad entry 5fb7d1e1
drivers/usb/host/ohci-q.c: 00:07.4 bad entry ffffffe1
drivers/usb/core/usb.c: USB disconnect on device 4
drivers/usb/core/hub.c: new USB device 00:07.4-2.3, assigned address 6
input: USB HID v1.10 Mouse [Logitech USB Mouse] on usb-00:07.4-2.3

The « drivers/usb/host/ohci-q.c: 00:07.4 bad entry » are triggerred
by gpm failing to restart.

And in case you need it, here is the new lsusb output :

Bus 001 Device 006: ID 046d:c001 Logitech Inc. N48/M-BB48 [FirstMouse
Plus]
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.10
bDeviceClass 0 Interface
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 8
idVendor 0x046d Logitech Inc.
idProduct 0xc001 N48/M-BB48 [FirstMouse Plus]
bcdDevice 4.10
iManufacturer 1 Logitech
iProduct 2 USB Mouse
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 34
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xa0
Remote Wakeup
MaxPower 50mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Devices
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 2 Mouse
iInterface 0
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.10
bCountryCode 0
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 68
cannot get report descriptor
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type none
wMaxPacketSize 4
bInterval 10
Language IDs: (length=4)
0409 English(US)

Bus 001 Device 005: ID 046a:0001 Cherry Mikroschalter GmbH My3000
Keyboard
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.00
bDeviceClass 0 Interface
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 8
idVendor 0x046a Cherry Mikroschalter GmbH
idProduct 0x0001 My3000 Keyboard
bcdDevice 9.08
iManufacturer 0
iProduct 0
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 34
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xa0
Remote Wakeup
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Devices
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 1 Keyboard
iInterface 0
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.00
bCountryCode 0
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 63
cannot get report descriptor
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type none
wMaxPacketSize 8
bInterval 12
Language IDs: (length=4)
0009 English(English)

Bus 001 Device 003: ID 0409:0058 NEC Systems
cannot get string descriptor 1, error = Broken pipe(32)
cannot get string descriptor 2, error = Broken pipe(32)
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 9 Hub
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x0409 NEC Systems
idProduct 0x0058
bcdDevice 1.00
iManufacturer 1
iProduct 2
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 25
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 9 Hub
bInterfaceSubClass 0
bInterfaceProtocol 0
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type none
wMaxPacketSize 1
bInterval 255
Language IDs: (length=4)
0409 English(US)

Bus 001 Device 002: ID 04e6:0005 Shuttle Technology Inc.
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.10
bDeviceClass 0 Interface
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 16
idVendor 0x04e6 Shuttle Technology Inc.
idProduct 0x0005
bcdDevice 2.08
iManufacturer 1 SCM Microsystems Inc.
iProduct 2 eUSB SmartMedia / CompactFlash Adapter
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 39
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 3
bmAttributes 0x80
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 3
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 1
bInterfaceProtocol 1
iInterface 4 CBC Interface
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x01 EP 1 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type none
wMaxPacketSize 64
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 2
Transfer Type Bulk
Synch Type none
wMaxPacketSize 64
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type none
wMaxPacketSize 2
bInterval 32
Language IDs: (length=4)
0409 English(US)

Bus 001 Device 001: ID 0000:0000 Virtual Hub
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.10
bDeviceClass 9 Hub
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 8
idVendor 0x0000 Virtual
idProduct 0x0000 Hub
bcdDevice 2.05
iManufacturer 3 Linux 2.5.43-rous4 ohci-hcd
iProduct 2 Advanced Micro Devices [AMD] AMD-756
[Viper] USB
iSerial 1 00:07.4
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 25
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0x40
Self Powered
MaxPower 0mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 9 Hub
bInterfaceSubClass 0
bInterfaceProtocol 0
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type none
wMaxPacketSize 2
bInterval 255
Language IDs: (length=4)
0409 English(US)

RH 8 2.4.18-kernel still runs like a charm.

I hope this can give you a hint to what problem is :(

Regards,

--
Nicolas Mailhot
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/