Bug 2915

Summary:	USB2 Mass Storage Device writing problems on x86-64
Product:	IO/Storage	Reporter:	Heikki Orsila (heikki.orsila)
Component:	SCSI	Assignee:	Andi Kleen (andi-bz)
Status:	REJECTED WILL_NOT_FIX
Severity:	high
Priority:	P2
Hardware:	i386
OS:	Linux
Kernel Version:	2.6.6-2.6.7	Subsystem:
Regression:	---	Bisected commit-id:

Description Heikki Orsila 2004-06-18 13:18:35 UTC

Distribution: Gentoo 2004/1
Hardware Environment:

00:00.0 Host bridge: VIA Technologies, Inc. VT8385 [K8T800 AGP] Host Bridge (rev 01)
00:01.0 PCI bridge: VIA Technologies, Inc. VT8237 PCI bridge [K8T800 South]
00:07.0 FireWire (IEEE 1394): Texas Instruments TSB43AB23 IEEE-1394a-2000
Controller (PHY/Link)
00:0d.0 RAID bus controller: CMD Technology Inc: Unknown device 3114 (rev 02)
00:0e.0 Ethernet controller: 3Com Corporation 3c940 1000Base? (rev 12)
00:0f.0 RAID bus controller: VIA Technologies, Inc.: Unknown device 3149 (rev 80)
00:0f.1 IDE interface: VIA Technologies, Inc.
VT82C586A/B/VT82C686/A/B/VT823x/A/C/VT8235 PIPC Bus Master IDE (rev 06)
00:10.0 USB Controller: VIA Technologies, Inc. VT6202 [USB 2.0 controller] (rev 81)
00:10.1 USB Controller: VIA Technologies, Inc. VT6202 [USB 2.0 controller] (rev 81)
00:10.2 USB Controller: VIA Technologies, Inc. VT6202 [USB 2.0 controller] (rev 81)
00:10.3 USB Controller: VIA Technologies, Inc. VT6202 [USB 2.0 controller] (rev 81)
00:10.4 USB Controller: VIA Technologies, Inc. USB 2.0 (rev 86)
00:11.0 ISA bridge: VIA Technologies, Inc. VT8237 ISA bridge [K8T800 South]
00:11.5 Multimedia audio controller: VIA Technologies, Inc. VT8233/A/8235/8237
AC97 Audio Controller (rev 60)
00:18.0 Host bridge: Advanced Micro Devices [AMD] K8 NorthBridge
00:18.1 Host bridge: Advanced Micro Devices [AMD] K8 NorthBridge
00:18.2 Host bridge: Advanced Micro Devices [AMD] K8 NorthBridge
00:18.3 Host bridge: Advanced Micro Devices [AMD] K8 NorthBridge
01:00.0 VGA compatible controller: Matrox Graphics, Inc. MGA G400 AGP (rev 85)

kernel boot log:
Jun 16 23:38:15 e275d Linux version 2.6.7 (root@e275d) (gcc version 3.3.3
20040217 (Gentoo Linux 3.3.3, propolice-3.3-7)) #1 Wed Jun 16 23:33:56 EEST 200
4
Jun 16 23:38:15 e275d BIOS-provided physical RAM map:
Jun 16 23:38:15 e275d BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
Jun 16 23:38:15 e275d BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
Jun 16 23:38:15 e275d BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
Jun 16 23:38:15 e275d BIOS-e820: 0000000000100000 - 000000003fff0000 (usable)
Jun 16 23:38:15 e275d BIOS-e820: 000000003fff0000 - 000000003fff3000 (ACPI NVS)
Jun 16 23:38:15 e275d BIOS-e820: 000000003fff3000 - 0000000040000000 (ACPI data)
Jun 16 23:38:15 e275d BIOS-e820: 00000000fec00000 - 00000000fec01000 (reserved)
Jun 16 23:38:15 e275d BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
Jun 16 23:38:15 e275d BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
Jun 16 23:38:15 e275d No mptable found.
Jun 16 23:38:15 e275d On node 0 totalpages: 262128
Jun 16 23:38:15 e275d DMA zone: 4096 pages, LIFO batch:1
Jun 16 23:38:15 e275d Normal zone: 258032 pages, LIFO batch:16
Jun 16 23:38:15 e275d HighMem zone: 0 pages, LIFO batch:1
Jun 16 23:38:15 e275d ACPI: RSDP (v000 VIAK8                                   
 ) @ 0x00000000000f7990
Jun 16 23:38:15 e275d ACPI: RSDT (v001 VIAK8  AWRDACPI 0x42302e31 AWRD
0x00000000) @ 0x000000003fff3000
Jun 16 23:38:15 e275d ACPI: FADT (v001 VIAK8  AWRDACPI 0x42302e31 AWRD
0x00000000) @ 0x000000003fff3040
Jun 16 23:38:15 e275d ACPI: BOOT (v001 VIAK8  AWRDACPI 0x42302e31 AWRD
0x00000000) @ 0x000000003fff7fc0
Jun 16 23:38:15 e275d ACPI: MADT (v001 VIAK8  AWRDACPI 0x42302e31 AWRD
0x00000000) @ 0x000000003fff8000
Jun 16 23:38:15 e275d ACPI: DSDT (v001 VIAK8  AWRDACPI 0x00001000 MSFT
0x0100000e) @ 0x0000000000000000
Jun 16 23:38:15 e275d ACPI: Local APIC address 0xfee00000
Jun 16 23:38:15 e275d ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Jun 16 23:38:15 e275d Processor #0 15:4 APIC version 16
Jun 16 23:38:15 e275d ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
Jun 16 23:38:15 e275d ACPI: IOAPIC (id[0x02] address[0xfec00000]
global_irq_base[0x0])
Jun 16 23:38:15 e275d IOAPIC[0]: Assigned apic_id 2
Jun 16 23:38:15 e275d IOAPIC[0]: apic_id 2, version 3, address 0xfec00000, GSI 0-23
Jun 16 23:38:15 e275d ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
Jun 16 23:38:15 e275d ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
Jun 16 23:38:15 e275d ACPI: IRQ0 used by override.
Jun 16 23:38:15 e275d ACPI: IRQ2 used by override.
Jun 16 23:38:15 e275d ACPI: IRQ9 used by override.
Jun 16 23:38:15 e275d Using ACPI (MADT) for SMP configuration information
Jun 16 23:38:15 e275d Checking aperture...
Jun 16 23:38:15 e275d CPU 0: aperture @ d0000000 size 128 MB
Jun 16 23:38:15 e275d Built 1 zonelists
Jun 16 23:38:15 e275d Kernel command line: root=/dev/hdc1 vga=ext console=tty0
Jun 16 23:38:15 e275d Initializing CPU#0
Jun 16 23:38:15 e275d PID hash table entries: 16 (order 4: 256 bytes)
Jun 16 23:38:15 e275d time.c: Using 1.193182 MHz PIT timer.
Jun 16 23:38:15 e275d time.c: Detected 2043.133 MHz processor.
Jun 16 23:38:15 e275d Console: colour VGA+ 80x50
Jun 16 23:38:15 e275d Memory: 1027756k/1048512k available (3250k kernel code,
19968k reserved, 1241k data, 476k init)
Jun 16 23:38:15 e275d Calibrating delay loop... 4030.46 BogoMIPS
Jun 16 23:38:15 e275d Dentry cache hash table entries: 131072 (order: 8, 1048576
bytes)
Jun 16 23:38:15 e275d Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
Jun 16 23:38:15 e275d Mount-cache hash table entries: 256 (order: 0, 4096 bytes)
Jun 16 23:38:15 e275d CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64
bytes/line)
Jun 16 23:38:15 e275d CPU: L2 Cache: 512K (64 bytes/line)
Jun 16 23:38:15 e275d CPU: AMD Athlon(tm) 64 Processor 3000+ stepping 08
Jun 16 23:38:15 e275d Using local APIC NMI watchdog using perfctr0
Jun 16 23:38:15 e275d ENABLING IO-APIC IRQs
Jun 16 23:38:15 e275d init IO_APIC IRQs
Jun 16 23:38:15 e275d IO-APIC (apicid-pin) 2-0, 2-16, 2-17, 2-18, 2-19, 2-20,
2-21, 2-22, 2-23 not connected.
Jun 16 23:38:15 e275d ..TIMER: vector=0x31 pin1=2 pin2=-1
Jun 16 23:38:15 e275d Using local APIC timer interrupts.
Jun 16 23:38:15 e275d Detected 12.769 MHz APIC timer.
Jun 16 23:38:15 e275d NET: Registered protocol family 16
Jun 16 23:38:15 e275d PCI: Using configuration type 1
Jun 16 23:38:15 e275d mtrr: v2.0 (20020519)
Jun 16 23:38:15 e275d ACPI: Subsystem revision 20040326
Jun 16 23:38:15 e275d tbxface-0117 [03] acpi_load_tables      : ACPI Tables
successfully acquired
Jun 16 23:38:15 e275d Parsing all Control
Methods:.......................................................................................................
............................................................................
Jun 16 23:38:15 e275d Table [DSDT](id F004) - 669 Objects with 57 Devices 179
Methods 39 Regions
Jun 16 23:38:15 e275d ACPI Namespace successfully loaded at root ffffffff805c7040
Jun 16 23:38:15 e275d evxfevnt-0093 [04] acpi_enable           : Transition to
ACPI mode successful
Jun 16 23:38:15 e275d evgpeblk-0867 [06] ev_create_gpe_block   : GPE 00 to 15
[_GPE] 2 regs at 0000000000000420 on int 9
Jun 16 23:38:15 e275d evgpeblk-0925 [06] ev_create_gpe_block   : Found 0 Wake,
Enabled 6 Runtime GPEs in this block
Jun 16 23:38:15 e275d Completing Region/Field/Buffer/Package
initialization:.............................................................................
.....................
Jun 16 23:38:15 e275d Initialized 39/39 Regions 18/18 Fields 19/19 Buffers 22/22
Packages (678 nodes)
Jun 16 23:38:15 e275d Executing all Device _STA and_INI
methods:.....................................................
Jun 16 23:38:15 e275d 53 Devices found containing: 53 _STA, 1 _INI methods
Jun 16 23:38:15 e275d ACPI: Interpreter enabled
Jun 16 23:38:15 e275d ACPI: Using IOAPIC for interrupt routing
Jun 16 23:38:15 e275d ACPI: PCI Root Bridge [PCI0] (00:00)
Jun 16 23:38:15 e275d PCI: Probing PCI hardware (bus 00)
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 6 7 10 11 12) *5
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 6 7 *10 11 12)
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 6 *7 10 11 12)
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 6 7 10 11 12)
*0, disabled.
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 6 7 10 11 12)
*0, disabled.
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 6 7 10 11 12) *0
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 6 7 10 11 *12)
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [LNK1] (IRQs *3 4 6 7 10 11 12)
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [ALKA] (IRQs 20) *0
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [ALKB] (IRQs 21) *0
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [ALKC] (IRQs 22) *0
Jun 16 23:38:15 e275d ACPI: PCI Interrupt Link [ALKD] (IRQs 23) *0, disabled.
Jun 16 23:38:15 e275d SCSI subsystem initialized
Jun 16 23:38:15 e275d usbcore: registered new driver usbfs
Jun 16 23:38:15 e275d usbcore: registered new driver hub
Jun 16 23:38:15 e275d IOAPIC[0]: Set PCI routing entry (2-16 -> 0xa9 -> IRQ 16
Mode:1 Active:1)
Jun 16 23:38:15 e275d 00:00:08[A] -> 2-16 -> IRQ 16
Jun 16 23:38:15 e275d IOAPIC[0]: Set PCI routing entry (2-17 -> 0xb1 -> IRQ 17
Mode:1 Active:1)
Jun 16 23:38:15 e275d 00:00:08[B] -> 2-17 -> IRQ 17
Jun 16 23:38:15 e275d IOAPIC[0]%

Comment 1 Heikki Orsila 2004-06-18 13:25:56 UTC

The server gives me internal error before submitting the whole message. Always
stops at the same location, see the last kernel log line that came. Here is the
relevant information as addition:

Jun 16 23:38:15 e275d ehci_hcd 0000:00:10.4: VIA Technologies, Inc. USB 2.0
Jun 16 23:38:15 e275d ehci_hcd 0000:00:10.4: irq 21, pci mem ffffff00000bd000
Jun 16 23:38:15 e275d ehci_hcd 0000:00:10.4: new USB bus registered, assigned
bus number 1
Jun 16 23:38:15 e275d ehci_hcd 0000:00:10.4: USB 2.0 enabled, EHCI 1.00, driver
2004-May-10
Jun 16 23:38:15 e275d hub 1-0:1.0: USB hub found
Jun 16 23:38:15 e275d hub 1-0:1.0: 8 ports detected
Jun 16 23:38:15 e275d ohci_hcd: 2004 Feb 02 USB 1.1 'Open' Host Controller
(OHCI) Driver (PCI)
Jun 16 23:38:15 e275d ohci_hcd: block sizes: ed 80 td 96
Jun 16 23:38:15 e275d USB Universal Host Controller Interface driver v2.2
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.0: VIA Technologies, Inc. VT82xxxxx
UHCI USB 1.1 Controller
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.0: irq 21, io base 000000000000d400
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.0: new USB bus registered, assigned
bus number 2
Jun 16 23:38:15 e275d hub 2-0:1.0: USB hub found
Jun 16 23:38:15 e275d hub 2-0:1.0: 2 ports detected
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.1: VIA Technologies, Inc. VT82xxxxx
UHCI USB 1.1 Controller (#2)
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.1: irq 21, io base 000000000000d800
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.1: new USB bus registered, assigned
bus number 3
Jun 16 23:38:15 e275d hub 3-0:1.0: USB hub found
Jun 16 23:38:15 e275d hub 3-0:1.0: 2 ports detected
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.2: VIA Technologies, Inc. VT82xxxxx
UHCI USB 1.1 Controller (#3)
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.2: irq 21, io base 000000000000dc00
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.2: new USB bus registered, assigned
bus number 4
Jun 16 23:38:15 e275d hub 4-0:1.0: USB hub found
Jun 16 23:38:15 e275d hub 4-0:1.0: 2 ports detected
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.3: VIA Technologies, Inc. VT82xxxxx
UHCI USB 1.1 Controller (#4)
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.3: irq 21, io base 000000000000e000
Jun 16 23:38:15 e275d uhci_hcd 0000:00:10.3: new USB bus registered, assigned
bus number 5
Jun 16 23:38:15 e275d hub 5-0:1.0: USB hub found
Jun 16 23:38:15 e275d hub 5-0:1.0: 2 ports detected
Jun 16 23:38:15 e275d usbcore: registered new driver usblp
Jun 16 23:38:15 e275d drivers/usb/class/usblp.c: v0.13: USB Printer Device Class
driver
Jun 16 23:38:15 e275d Initializing USB Mass Storage driver...
Jun 16 23:38:15 e275d usbcore: registered new driver usb-storage
Jun 16 23:38:15 e275d USB Mass Storage support registered.
Jun 16 23:38:15 e275d usbcore: registered new driver usbhid
Jun 16 23:38:15 e275d drivers/usb/input/hid-core.c: v2.0:USB HID core driver


Software Environment:
Linux version 2.6.7 (root@e275d) (gcc version 3.3.3 20040217 (Gentoo Linux
3.3.3, propolice-3.3-7))

Problem Description:
Writing on USB2 Mass Storage device through SCSI layer freezes a short time
after writing. Top shows heavily increased load but no process on the top seems
to take that CPU time. This happened with an USB2 plugged hard disk. The kernel
 has no patches. Also, there are no third party drivers. Pure 2.6.7 Vanilla.
Reading from the same USB2 hard disk causes no problems. I was trying to write
on a VFAT device. Writing on the same disk on the other machine on 2.4.26 with
USB1 didn't cause any problems.

Kernel log says:

Jun 16 23:49:41 e275d scsi: Device offlined - not ready after error recovery: h\
ost 4 channel 0 id 0 lun 0
Jun 16 23:49:41 e275d SCSI error : <4 0 0 0> return code = 0x50000
Jun 16 23:49:41 e275d end_request: I/O error, dev sdd, sector 471193
Jun 16 23:49:41 e275d Buffer I/O error on device sdd1, logical block 471130
Jun 16 23:49:41 e275d lost page write due to I/O error on sdd1
Jun 16 23:49:41 e275d scsi4 (0:0): rejecting I/O to offline device
Jun 16 23:49:41 e275d Buffer I/O error on device sdd1, logical block 471131
Jun 16 23:49:41 e275d lost page write due to I/O error on sdd1
Jun 16 23:49:41 e275d Buffer I/O error on device sdd1, logical block 471132
Jun 16 23:49:41 e275d lost page write due to I/O error on sdd1
...
Jun 16 23:49:41 e275d Buffer I/O error on device sdd1, logical block 471139
Jun 16 23:49:41 e275d lost page write due to I/O error on sdd1
Jun 16 23:49:41 e275d scsi4 (0:0): rejecting I/O to offline device
Jun 16 23:49:41 e275d scsi4 (0:0): rejecting I/O to offline device
Jun 16 23:49:41 e275d scsi4 (0:0): rejecting I/O to offline device
...
many thousand lines of reject.




Steps to reproduce:
Plug a hard disk with USB2. Create a filesystem with mkfs.vfat, start writing to
a file, say dd if=/dev/zero of=/mnt/usb2/foobar. Soon after write buffers are
started to be flushed on the disk the writing stops and machine load increases
by 2-3. Writing small amounts of data does not cause problems even if written on
the disk.

Comment 2 Georgios E. Kylafas 2004-07-19 00:08:29 UTC

I had similar problems ("rejecting I/O to offline device") with my USB hard 
drive on x86. 
 
They were solved by _not_ compiling "SCSI generic" support (CONFIG_CHR_DEV_SG) 
either into the kernel or as a module (following the discussion in bug 1827). 
 
Does it work for you too?

Comment 3 Heikki Orsila 2004-07-19 09:59:33 UTC

Georgios, I will try that later and report here. Thanks in advance.

Comment 4 Andi Kleen 2005-07-19 15:33:43 UTC

There have been lots of changes in that subsystem. I will assume 
for now it's fixed. If not please reopen and assign to USB maintainers
instead.

Comment 5 Heikki Orsila 2005-07-19 17:04:32 UTC

The side-effect that load starts to increase doesn't happen anymore with linux
kernel 2.6.12. But USB2 doesn't still work perfectly. Now I'm able to write
approximately 60 to 120 GiB before I get problems:

  scsi4 (0:0): rejecting I/O to dead device
  FAT: FAT read failed (blocknr 44749)
  scsi4 (0:0): rejecting I/O to dead device
  ...

I will file another bug report when I've made some more tests. Now USB2 is only
annoying, but at least it works a little because I can write relatively large
amounts of data before failure.