Bug 9790

Summary:	strange USB related problem
Product:	Drivers	Reporter:	Serge Gavrilov (serge)
Component:	USB	Assignee:	Greg Kroah-Hartman (greg)
Status:	CLOSED CODE_FIX
Severity:	normal	CC:	stern
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.23 and above	Subsystem:
Regression:	Yes	Bisected commit-id:
Bug Depends on:
Bug Blocks:	5089

Description Serge Gavrilov 2008-01-21 10:23:45 UTC

Latest working kernel version: 2.6.22.12 

Earliest failing kernel version: 2.6.23.9

Distribution: Gentoo

Hardware Environment: 

00:00.0 Host bridge: Intel Corporation 975X Express Memory Controller Hub (rev c0)
        Subsystem: ASUSTeK Computer Inc. Unknown device 8178
        Flags: bus master, fast devsel, latency 0
        Capabilities: [e0] Vendor Specific Information

00:01.0 PCI bridge: Intel Corporation 975X Express PCI Express Root Port (rev c0) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=06, subordinate=06, sec-latency=0
        I/O behind bridge: 0000c000-0000cfff
        Memory behind bridge: faa00000-feafffff
        Prefetchable memory behind bridge: 00000000cff00000-00000000efefffff
        Capabilities: [88] Subsystem: Intel Corporation Unknown device 0000
        Capabilities: [80] Power Management version 2
        Capabilities: [90] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [a0] Express Root Port (Slot+) IRQ 0

00:1c.0 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 1 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=05, subordinate=05, sec-latency=0
        Prefetchable memory behind bridge: 00000000cfe00000-00000000cfefffff
        Capabilities: [40] Express Root Port (Slot+) IRQ 0
        Capabilities: [80] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [90] Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Capabilities: [a0] Power Management version 2

00:1c.3 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 4 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=04, subordinate=04, sec-latency=0
        I/O behind bridge: 0000b000-0000bfff
        Memory behind bridge: fa900000-fa9fffff
        Capabilities: [40] Express Root Port (Slot-) IRQ 0
        Capabilities: [80] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [90] Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Capabilities: [a0] Power Management version 2

00:1c.4 PCI bridge: Intel Corporation 82801GR/GH/GHM (ICH7 Family) PCI Express Port 5 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=03, subordinate=03, sec-latency=0
        I/O behind bridge: 0000a000-0000afff
        Memory behind bridge: fa800000-fa8fffff
        Capabilities: [40] Express Root Port (Slot-) IRQ 0
        Capabilities: [80] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [90] Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Capabilities: [a0] Power Management version 2

00:1c.5 PCI bridge: Intel Corporation 82801GR/GH/GHM (ICH7 Family) PCI Express Port 6 (rev 01) (prog-if 00 [Normal decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=02, subordinate=02, sec-latency=0
        I/O behind bridge: 00009000-00009fff
        Memory behind bridge: fa700000-fa7fffff
        Capabilities: [40] Express Root Port (Slot-) IRQ 0
        Capabilities: [80] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [90] Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Capabilities: [a0] Power Management version 2

00:1d.0 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI #1 (rev 01) (prog-if 00 [UHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 22
        I/O ports at e480 [size=32]

00:1d.1 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI #2 (rev 01) (prog-if 00 [UHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 18
        I/O ports at e800 [size=32]

00:1d.2 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI #3 (rev 01) (prog-if 00 [UHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 21
        I/O ports at e880 [size=32]

00:1d.3 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI #4 (rev 01) (prog-if 00 [UHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 17
        I/O ports at ec00 [size=32]

00:1d.7 USB Controller: Intel Corporation 82801G (ICH7 Family) USB2 EHCI Controller (rev 01) (prog-if 20 [EHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 22
        Memory at febffc00 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2
        Capabilities: [58] Debug port

00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev e1) (prog-if 01 [Subtractive decode])
        Flags: bus master, fast devsel, latency 0
        Bus: primary=00, secondary=01, subordinate=01, sec-latency=32
        I/O behind bridge: 00008000-00008fff
        Memory behind bridge: fa600000-fa6fffff
        Prefetchable memory behind bridge: 00000000cfd00000-00000000cfdfffff
        Capabilities: [50] Subsystem: ASUSTeK Computer Inc. Unknown device 8179

00:1f.0 ISA bridge: Intel Corporation 82801GB/GR (ICH7 Family) LPC Interface Bridge (rev 01)
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0
        Capabilities: [e0] Vendor Specific Information

00:1f.1 IDE interface: Intel Corporation 82801G (ICH7 Family) IDE Controller (rev 01) (prog-if 8a [Master SecP PriP])
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: bus master, medium devsel, latency 0, IRQ 20
        I/O ports at 01f0 [size=8]
        I/O ports at 03f4 [size=1]
        I/O ports at 0170 [size=8]
        I/O ports at 0374 [size=1]
        I/O ports at ffa0 [size=16]

00:1f.2 SATA controller: Intel Corporation 82801GR/GH (ICH7 Family) Serial ATA Storage Controller AHCI (rev 01) (prog-if 01 [AHCI 1.0])
        Subsystem: ASUSTeK Computer Inc. Unknown device 2606
        Flags: bus master, 66MHz, medium devsel, latency 0, IRQ 19
        I/O ports at e400 [size=8]
        I/O ports at e080 [size=4]
        I/O ports at e000 [size=8]
        I/O ports at dc00 [size=4]
        I/O ports at d880 [size=16]
        Memory at febff800 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [80] Message Signalled Interrupts: Mask- 64bit- Queue=0/0 Enable-
        Capabilities: [70] Power Management version 2

00:1f.3 SMBus: Intel Corporation 82801G (ICH7 Family) SMBus Controller (rev 01)
        Subsystem: ASUSTeK Computer Inc. Unknown device 8179
        Flags: medium devsel, IRQ 19
        I/O ports at 0400 [size=32]

01:00.0 Multimedia audio controller: VIA Technologies Inc. VT1720/24 [Envy24PT/HT] PCI Multi-Channel Audio Controller (rev 01)
        Subsystem: TERRATEC Electronic GmbH Aureon 7.1 Space
        Flags: bus master, medium devsel, latency 64, IRQ 23
        I/O ports at 8c00 [size=32]
        I/O ports at 8880 [size=128]
        Capabilities: [80] Power Management version 1

01:01.0 Multimedia video controller: Brooktree Corporation Bt878 Video Capture (rev 11)
        Subsystem: Avermedia Technologies Inc AVerTV WDM Video Capture
        Flags: bus master, medium devsel, latency 64, IRQ 20
        Memory at cfdfe000 (32-bit, prefetchable) [size=4K]
        Capabilities: [44] Vital Product Data
        Capabilities: [4c] Power Management version 2

01:01.1 Multimedia controller: Brooktree Corporation Bt878 Audio Capture (rev 11)
        Subsystem: Avermedia Technologies Inc AVerTV WDM Audio Capture
        Flags: bus master, medium devsel, latency 64, IRQ 5
        Memory at cfdff000 (32-bit, prefetchable) [size=4K]
        Capabilities: [44] Vital Product Data
        Capabilities: [4c] Power Management version 2

01:03.0 FireWirrog-if 10 [OHCI])
        Subsystem: ASUSTeK Computer Inc. Unknown device 815b
        Flags: bus master, medium devsel, latency 64, IRQ 23
        Memory at fa6ff800 (32-bit, non-prefetchable) [size=2K]
        Memory at fa6f8000 (32-bit, non-prefetchable) [size=16K]
        Capabilities: [44] Power Management version 2

02:00.0 SATA controller: JMicron Technologies, Inc. JMicron 20360/20363 AHCI Controller (rev 02) (prog-if 01 [AHCI 1.0])
        Subsystem: ASUSTeK Computer Inc. Unknown device 81e4
        Flags: bus master, fast devsel, latency 0, IRQ 18
        Memory at fa7fe000 (32-bit, non-prefetchable) [size=8K]
        Expansion ROM at fa7e0000 [disabled] [size=64K]
        Capabilities: [68] Power Management version 2
        Capabilities: [50] Express Legacy Endpoint IRQ 1

02:00.1 IDE interface: JMicron Technologies, Inc. JMicron 20360/20363 AHCI Controller (rev 02) (prog-if 85 [Master SecO PriO])
        Subsystem: ASUSTeK Computer Inc. Unknown device 81e4
        Flags: bus master, fast devsel, latency 0, IRQ 21
        I/O ports at 9c00 [size=8]
        I/O ports at 9880 [size=4]
        I/O ports at 9800 [size=8]
        I/O ports at 9480 [size=4]
        I/O ports at 9400 [size=16]
        Capabilities: [68] Power Management version 2

03:00.0 Ethernet controller: Marvell Technology Group Ltd. 88E8053 PCI-E Gigabit Ethernet Controller (rev 20)
        Subsystem: ASUSTeK Computer Inc. Marvell 88E8053 Gigabit Ethernet controller PCIe (Asus)
        Flags: bus master, fast devsel, latency 0, IRQ 16
        Memory at fa8fc000 (64-bit, non-prefetchable) [size=16K]
        I/O ports at a800 [size=256]
        Expansion ROM at fa8c0000 [disabled] [size=128K]
        Capabilities: [48] Power Management version 2
        Capabilities: [50] Vital Product Data
        Capabilities: [5c] Message Signalled Interrupts: Mask- 64bit+ Queue=0/1 Enable-
        Capabilities: [e0] Express Legacy Endpoint IRQ 0

04:00.0 Ethernet controller: Marvell Technology Group Ltd. 88E8053 PCI-E Gigabit Ethernet Controller (rev 20)
        Subsystem: ASUSTeK Computer Inc. Marvell 88E8053 Gigabit Ethernet controller PCIe (Asus)
        Flags: bus master, fast devsel, latency 0, IRQ 17
        Memory at fa9fc000 (64-bit, non-prefetchable) [size=16K]
        I/O ports at b800 [size=256]
        Expansion ROM at fa9c0000 [disabled] [size=128K]
        Capabilities: [48] Power Management version 2
        Capabilities: [50] Vital Product Data
        Capabilities: [5c] Message Signalled Interrupts: Mask- 64bit+ Queue=0/1 Enable-
        Capabilities: [e0] Express Legacy Endpoint IRQ 0

06:00.0 VGA compatible controller: nVidia Corporation Unknown device 0393 (rev a1) (prog-if 00 [VGA])
        Subsystem: ASUSTeK Computer Inc. Unknown device 820e
        Flags: bus master, fast devsel, latency 0, IRQ 16
        Memory at fd000000 (32-bit, non-prefetchable) [size=16M]
        Memory at d0000000 (64-bit, prefetchable) [size=256M]
        Memory at fc000000 (64-bit, non-prefetchable) [size=16M]
        I/O ports at cc00 [size=128]
        [virtual] Expansion ROM at feae0000 [disabled] [size=128K]
        Capabilities: [60] Power Management version 2
        Capabilities: [68] Message Signalled Interrupts: Mask- 64bit+ Queue=0/0 Enable-
        Capabilities: [78] Express Endpoint IRQ 0

Problem Description:

First of all, I am sorry for the stupid bug title. Perhaps, you can suggest Bus the better one :).

I use Nikon Coolscan V film scanner to scan the negative films. 

002 Device 005: ID 04b8:0110 Seiko Epson Corp. Perfection 1650

The software is Vuescan (http://www.hamrick.com). This is closed source, commercial product. I need this since I need infrared cleaning :(. This software
uses libusb library to access the scanner. 

So, after upgrade from 2.6.20 to 2.6.23 the strange things become occur.
After scanning approx 30-35 frames (one frame is approximately 150Mb of data) vuescan freezes (precisely, it goes into interruptible sleep). This can happen 
while scanning, and also is can happen while image processing (when the software 
does not talk with the scanner). Strace shows that the last system call is 
msync(..,MS_ASYNC). After that another processes marked as 'D' appear, and after some time the system becomes unresponsible. To prevent, it is possible kill X server. After that there are no processes marked as 'D' and the system seems to be absolutely normal. But, it is not the case. After some time 'D'-processes begin to appear again and the system become more or less unresponsible. So the system becomes completely broken and I need to reboot. I compiled the kernel with all possible debug options, but this error is not accompanies by any kernel message :(. With 2.6.23 this is absolutely reproducible result. But to reproduce  I need approx 2 hours (this is scanning time) :(

I also have tested 2.6.22 and 2.6.24. 

2.6.22 seems to be not broken. 
With 2.6.24-rc8 the situation becomes worse: the system completely freezes after several scans. 

Thanks a lot for your work.

Comment 1 Serge Gavrilov 2008-01-21 10:28:04 UTC

Sorry, I gave wrong description of the scanner:

Bus 001 Device 008: ID 04b0:4001 Nikon Corp.

Also, I forget to say that I try to use the scanner as USB 1.1 device (plugging it  into usb 1.1 hub) and obtain the same result.

Comment 2 Anonymous Emailer 2008-01-21 11:40:57 UTC

Reply-To: akpm@linux-foundation.org

On Mon, 21 Jan 2008 10:23:48 -0800 (PST) bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=9790
> 
>            Summary: strange USB related problem
>            Product: Drivers
>            Version: 2.5
>      KernelVersion: 2.6.23 and above
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: USB
>         AssignedTo: greg@kroah.com
>         ReportedBy: serge@pdmi.ras.ru
> 
> 
> Latest working kernel version: 2.6.22.12 
> 
> Earliest failing kernel version: 2.6.23.9

Regression...

> Distribution: Gentoo
> 
> Hardware Environment: 
> 
> ...
> 
> Problem Description:
> 
> First of all, I am sorry for the stupid bug title. Perhaps, you can suggest
> Bus
> the better one :).
> 
> I use Nikon Coolscan V film scanner to scan the negative films. 
> 
> 002 Device 005: ID 04b8:0110 Seiko Epson Corp. Perfection 1650
> 
> The software is Vuescan (http://www.hamrick.com). This is closed source,
> commercial product. I need this since I need infrared cleaning :(. This
> software
> uses libusb library to access the scanner. 
> 
> So, after upgrade from 2.6.20 to 2.6.23 the strange things become occur.
> After scanning approx 30-35 frames (one frame is approximately 150Mb of data)
> vuescan freezes (precisely, it goes into interruptible sleep). This can
> happen 
> while scanning, and also is can happen while image processing (when the
> software 
> does not talk with the scanner). Strace shows that the last system call is 
> msync(..,MS_ASYNC). After that another processes marked as 'D' appear, and
> after some time the system becomes unresponsible. To prevent, it is possible
> kill X server. After that there are no processes marked as 'D' and the system
> seems to be absolutely normal. But, it is not the case. After some time
> 'D'-processes begin to appear again and the system become more or less
> unresponsible. So the system becomes completely broken and I need to reboot.
> I
> compiled the kernel with all possible debug options, but this error is not
> accompanies by any kernel message :(. With 2.6.23 this is absolutely
> reproducible result. But to reproduce  I need approx 2 hours (this is
> scanning
> time) :(
> 
> I also have tested 2.6.22 and 2.6.24. 
> 
> 2.6.22 seems to be not broken. 
> With 2.6.24-rc8 the situation becomes worse: the system completely freezes
> after several scans. 

When things are stuck in D state, please hit ALT-SYSRQ-W or type "echo w >
/proc/sysrq-trigger" and then send us (via reply-to-all to this email) the
resulting dmesg output, thanks.

Comment 3 Serge Gavrilov 2008-01-21 15:06:00 UTC

This is with gentoo 2.6.23 kernel: 

Sched Debug Version: v0.05-v20, 2.6.23-gentoo-r5 #2
now at 9040171717158 nsecs

cpu#0, 1869.895 MHz
  .nr_running                    : 3
  .load                          : 5169
  .ls.delta_fair                 : 664772323
  .ls.delta_exec                 : 4091541087
  .nr_switches                   : 10544602
  .nr_load_updates               : 4325482
  .nr_uninterruptible            : 4294961682
  .jiffies                       : 8740172
  .next_balance                  : 8740166
  .curr->pid                     : 0
  .clock                         : 4324829045057
  .idle_clock                    : 0
  .prev_clock_raw                : 9066780320360
  .clock_warps                   : 0
  .clock_overflows               : 4715123
  .clock_deep_idle_events        : 0
  .clock_max_delta               : 999848
  .cpu_load[0]                   : 0
  .cpu_load[1]                   : 0
  .cpu_load[2]                   : 0
  .cpu_load[3]                   : 0
  .cpu_load[4]                   : 0

cfs_rq
  .fair_clock                    : 1056766578052
  .exec_clock                    : 1060302060293
  .wait_runtime                  : 0
  .wait_runtime_overruns         : 0
  .wait_runtime_underruns        : 0
  .sleeper_bonus                 : 10510116
  .wait_runtime_rq_sum           : 40047342

runnable tasks:
            task   PID        tree-key         delta       waiting  switches  prio        sum-exec        sum-wait       sum-sleep    wait-overrun   wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
        events/0     9   1056753454054     -13123998      40000000     17253   115               0               0               0               0               0
 hald-addon-keyb 10512   1056726578052     -40000000      40000000      6512   120               0               0               0               0               0
               X 12835   1056806530710      39952658     -39952658   1337718   120               0               0               0               0               0

cpu#1, 1869.895 MHz
  .nr_running                    : 1
  .load                          : 1024
  .ls.delta_fair                 : 1024090210
  .ls.delta_exec                 : 653910632
  .nr_switches                   : 8659200
  .nr_load_updates               : 4150215
  .nr_uninterruptible            : 5620
  .jiffies                       : 8740172
  .next_balance                  : 8740246
  .curr->pid                     : 10053
  .clock                         : 4149587041612
  .idle_clock                    : 0
  .prev_clock_raw                : 9066779873123
  .clock_warps                   : 0
  .clock_overflows               : 4345713
  .clock_deep_idle_events        : 0
  .clock_max_delta               : 999848
  .cpu_load[0]                   : 1024
  .cpu_load[1]                   : 522
  .cpu_load[2]                   : 331
  .cpu_load[3]                   : 262
  .cpu_load[4]                   : 226

cfs_rq
  .fair_clock                    : 949189481552
  .exec_clock                    : 948539490194
  .wait_runtime                  : 0
  .wait_runtime_overruns         : 0
  .wait_runtime_underruns        : 0
  .sleeper_bonus                 : 3994179
  .wait_runtime_rq_sum           : 40000000

runnable tasks:
            task   PID        tree-key         delta       waiting  switches  prio        sum-exec        sum-wait       sum-sleep    wait-overrun   wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
R      syslog-ng 10053    949149481552     -40000000      40000000      1209   120               0               0               0               0               0

SysRq : Show Blocked State
  task                PC stack   pid father
syslog-ng     D c066ce00  5848 10053      1
       dfa75c00 00000046 c066ce00 c066ce00 00000282 dfa75be0 c046c0f9 dfdb7780 
       c066ce00 c2071080 dfbe2c70 00000000 00857e29 00000282 dfa75c10 00857e29 
       dfa75c70 dfa75c38 c0469d66 00000046 c058a120 d8adfdc4 ceb5dc10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
mono          D c066ce00  6464 13500      1
       e08bbdb4 00200046 c066ce00 c066ce00 00200282 e08bbd94 c046c0f9 df8fe780 
       c066ce00 c2071080 d6e12000 00000000 00857e29 00200282 e08bbdc4 00857e29 
       e08bbe24 e08bbdec c0469d66 00200046 c058a120 c066cf74 e1ba9b94 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c016a1d1>] set_page_dirty_balance+0x41/0x50
 [<c0172bd6>] do_wp_page+0x256/0x470
 [<c01740b9>] handle_mm_fault+0x239/0x2a0
 [<c011c247>] do_page_fault+0x157/0x660
 [<c046c5b2>] error_code+0x72/0x78
 =======================
nautilus      D c066ce00  5168 16054  16007
       d40e1c00 00000046 c066ce00 c066ce00 00000282 d40e1be0 c046c0f9 d4077000 
       c066ce00 c2071080 d40de000 00000000 00857e29 00000282 d40e1c10 00857e29 
       d40e1c70 d40e1c38 c0469d66 00000046 c058a120 ceb5dc10 c066cf74 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
python        D c5b8d8d0  7084  3248      1
       daf9befc 00200046 00000000 c5b8d8d0 00200046 00000000 00000000 d3ea0c80 
       c046a00c c2071080 f5b8ac70 c5b8d8d0 daf9befc 00200046 c5b8d894 00200246 
       f5b8ac70 daf9bf48 c046a0fe 00000000 00000002 c046a00c d90bc800 c5b8d8d0 
Call Trace:
 [<c046a0fe>] __mutex_lock_slowpath+0xde/0x2f0
 [<c046a00c>] mutex_lock+0x1c/0x20
 [<c0186cee>] generic_file_llseek+0x2e/0xe0
 [<c0186fda>] vfs_llseek+0x3a/0x50
 [<c01870dd>] sys_llseek+0x4d/0xa0
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
vuescan       D c066ce00  4972 25367      1
       d8adfdb4 00000046 c066ce00 c066ce00 00000282 d8adfd94 c046c0f9 d878ac80 
       c066ce00 c2071080 d8be6c70 00000000 00857e29 00000282 d8adfdc4 00857e29 
       d8adfe24 d8adfdec c0469d66 00000046 c058a120 e1ba9b94 dfa75c10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c016a1d1>] set_page_dirty_balance+0x41/0x50
 [<c0172bd6>] do_wp_page+0x256/0x470
 [<c01740b9>] handle_mm_fault+0x239/0x2a0
 [<c011c247>] do_page_fault+0x157/0x660
 [<c046c5b2>] error_code+0x72/0x78
 =======================
uucico        D c066ce00  5972  3174      1
       ceb5dc00 00000046 c066ce00 c066ce00 00000282 ceb5dbe0 c046c0f9 c5af6000 
       c066ce00 c2071080 d2cdcc70 00000000 00857e29 00000282 ceb5dc10 00857e29 
       ceb5dc70 ceb5dc38 c0469d66 00000046 c058a120 dfa75c10 d40e1c10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
df            D c066ce00  5364  3238  16223
       e1ba9b84 00000046 c066ce00 c066ce00 00000282 e1ba9b64 c046c0f9 d878ac80 
       c066ce00 c2071080 d8968c70 00000000 00857e29 00000282 e1ba9b94 00857e29 
       e1ba9bf4 e1ba9bbc c0469d66 00000046 c058a120 e08bbdc4 d8adfdc4 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0158637>] do_acct_process+0x297/0x2d0
 [<c015882a>] acct_process+0x3a/0x60
 [<c012bb64>] do_exit+0x324/0x450
 [<c012bce9>] do_group_exit+0x29/0x70
 [<c012bd3f>] sys_exit_group+0xf/0x20
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
nvidia-settin D c5b051d0  6620  3245   3244
       ea14dd90 00000046 00000000 c5b051d0 00000046 00000000 00000000 cc8a5c80 
       c046a00c c2071080 d72d6c70 c5b051d0 ea14dd90 00000046 c5b05194 00000246 
       d72d6c70 ea14dddc c046a0fe 00000000 00000002 c046a00c 00000000 c5b051d0 
Call Trace:
 [<c046a0fe>] __mutex_lock_slowpath+0xde/0x2f0
 [<c046a00c>] mutex_lock+0x1c/0x20
 [<c0166d37>] generic_file_aio_write+0x47/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0158637>] do_acct_process+0x297/0x2d0
 [<c015882a>] acct_process+0x3a/0x60
 [<c012bb64>] do_exit+0x324/0x450
 [<c012bce9>] do_group_exit+0x29/0x70
 [<c012bd3f>] sys_exit_group+0xf/0x20
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================

Comment 4 Serge Gavrilov 2008-01-21 15:30:28 UTC

This is with gentoo 2.6.23 kernel: 

Sched Debug Version: v0.05-v20, 2.6.23-gentoo-r5 #2
now at 9040171717158 nsecs

cpu#0, 1869.895 MHz
  .nr_running                    : 3
  .load                          : 5169
  .ls.delta_fair                 : 664772323
  .ls.delta_exec                 : 4091541087
  .nr_switches                   : 10544602
  .nr_load_updates               : 4325482
  .nr_uninterruptible            : 4294961682
  .jiffies                       : 8740172
  .next_balance                  : 8740166
  .curr->pid                     : 0
  .clock                         : 4324829045057
  .idle_clock                    : 0
  .prev_clock_raw                : 9066780320360
  .clock_warps                   : 0
  .clock_overflows               : 4715123
  .clock_deep_idle_events        : 0
  .clock_max_delta               : 999848
  .cpu_load[0]                   : 0
  .cpu_load[1]                   : 0
  .cpu_load[2]                   : 0
  .cpu_load[3]                   : 0
  .cpu_load[4]                   : 0

cfs_rq
  .fair_clock                    : 1056766578052
  .exec_clock                    : 1060302060293
  .wait_runtime                  : 0
  .wait_runtime_overruns         : 0
  .wait_runtime_underruns        : 0
  .sleeper_bonus                 : 10510116
  .wait_runtime_rq_sum           : 40047342

runnable tasks:
            task   PID        tree-key         delta       waiting  switches 
prio        sum-exec        sum-wait       sum-sleep    wait-overrun  
wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
        events/0     9   1056753454054     -13123998      40000000     17253  
115               0               0               0               0            
  0
 hald-addon-keyb 10512   1056726578052     -40000000      40000000      6512  
120               0               0               0               0            
  0
               X 12835   1056806530710      39952658     -39952658   1337718  
120               0               0               0               0            
  0

cpu#1, 1869.895 MHz
  .nr_running                    : 1
  .load                          : 1024
  .ls.delta_fair                 : 1024090210
  .ls.delta_exec                 : 653910632
  .nr_switches                   : 8659200
  .nr_load_updates               : 4150215
  .nr_uninterruptible            : 5620
  .jiffies                       : 8740172
  .next_balance                  : 8740246
  .curr->pid                     : 10053
  .clock                         : 4149587041612
  .idle_clock                    : 0
  .prev_clock_raw                : 9066779873123
  .clock_warps                   : 0
  .clock_overflows               : 4345713
  .clock_deep_idle_events        : 0
  .clock_max_delta               : 999848
  .cpu_load[0]                   : 1024
  .cpu_load[1]                   : 522
  .cpu_load[2]                   : 331
  .cpu_load[3]                   : 262
  .cpu_load[4]                   : 226

cfs_rq
  .fair_clock                    : 949189481552
  .exec_clock                    : 948539490194
  .wait_runtime                  : 0
  .wait_runtime_overruns         : 0
  .wait_runtime_underruns        : 0
  .sleeper_bonus                 : 3994179
  .wait_runtime_rq_sum           : 40000000

runnable tasks:
            task   PID        tree-key         delta       waiting  switches 
prio        sum-exec        sum-wait       sum-sleep    wait-overrun  
wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
R      syslog-ng 10053    949149481552     -40000000      40000000      1209  
120               0               0               0               0            
  0

SysRq : Show Blocked State
  task                PC stack   pid father
syslog-ng     D c066ce00  5848 10053      1
       dfa75c00 00000046 c066ce00 c066ce00 00000282 dfa75be0 c046c0f9 dfdb7780 
       c066ce00 c2071080 dfbe2c70 00000000 00857e29 00000282 dfa75c10 00857e29 
       dfa75c70 dfa75c38 c0469d66 00000046 c058a120 d8adfdc4 ceb5dc10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
mono          D c066ce00  6464 13500      1
       e08bbdb4 00200046 c066ce00 c066ce00 00200282 e08bbd94 c046c0f9 df8fe780 
       c066ce00 c2071080 d6e12000 00000000 00857e29 00200282 e08bbdc4 00857e29 
       e08bbe24 e08bbdec c0469d66 00200046 c058a120 c066cf74 e1ba9b94 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c016a1d1>] set_page_dirty_balance+0x41/0x50
 [<c0172bd6>] do_wp_page+0x256/0x470
 [<c01740b9>] handle_mm_fault+0x239/0x2a0
 [<c011c247>] do_page_fault+0x157/0x660
 [<c046c5b2>] error_code+0x72/0x78
 =======================
nautilus      D c066ce00  5168 16054  16007
       d40e1c00 00000046 c066ce00 c066ce00 00000282 d40e1be0 c046c0f9 d4077000 
       c066ce00 c2071080 d40de000 00000000 00857e29 00000282 d40e1c10 00857e29 
       d40e1c70 d40e1c38 c0469d66 00000046 c058a120 ceb5dc10 c066cf74 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
python        D c5b8d8d0  7084  3248      1
       daf9befc 00200046 00000000 c5b8d8d0 00200046 00000000 00000000 d3ea0c80 
       c046a00c c2071080 f5b8ac70 c5b8d8d0 daf9befc 00200046 c5b8d894 00200246 
       f5b8ac70 daf9bf48 c046a0fe 00000000 00000002 c046a00c d90bc800 c5b8d8d0 
Call Trace:
 [<c046a0fe>] __mutex_lock_slowpath+0xde/0x2f0
 [<c046a00c>] mutex_lock+0x1c/0x20
 [<c0186cee>] generic_file_llseek+0x2e/0xe0
 [<c0186fda>] vfs_llseek+0x3a/0x50
 [<c01870dd>] sys_llseek+0x4d/0xa0
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
vuescan       D c066ce00  4972 25367      1
       d8adfdb4 00000046 c066ce00 c066ce00 00000282 d8adfd94 c046c0f9 d878ac80 
       c066ce00 c2071080 d8be6c70 00000000 00857e29 00000282 d8adfdc4 00857e29 
       d8adfe24 d8adfdec c0469d66 00000046 c058a120 e1ba9b94 dfa75c10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c016a1d1>] set_page_dirty_balance+0x41/0x50
 [<c0172bd6>] do_wp_page+0x256/0x470
 [<c01740b9>] handle_mm_fault+0x239/0x2a0
 [<c011c247>] do_page_fault+0x157/0x660
 [<c046c5b2>] error_code+0x72/0x78
 =======================
uucico        D c066ce00  5972  3174      1
       ceb5dc00 00000046 c066ce00 c066ce00 00000282 ceb5dbe0 c046c0f9 c5af6000 
       c066ce00 c2071080 d2cdcc70 00000000 00857e29 00000282 ceb5dc10 00857e29 
       ceb5dc70 ceb5dc38 c0469d66 00000046 c058a120 dfa75c10 d40e1c10 00857e29 
Call Trace:
 [<c0469d66>] schedule_timeout+0x46/0x90
 [<c0469cee>] io_schedule_timeout+0x1e/0x30
 [<c016fdcb>] congestion_wait+0x7b/0xa0
 [<c016a0ce>] balance_dirty_pages+0xae/0x170
 [<c016a277>] balance_dirty_pages_ratelimited_nr+0x97/0xb0
 [<c0166320>] generic_file_buffered_write+0x2b0/0x660
 [<c0166917>] __generic_file_aio_write_nolock+0x247/0x560
 [<c0166d4a>] generic_file_aio_write+0x5a/0xd0
 [<c01fd04d>] ext3_file_write+0x2d/0xc0
 [<c0187577>] do_sync_write+0xc7/0x120
 [<c0187730>] vfs_write+0x160/0x170
 [<c01877ed>] sys_write+0x3d/0x70
 [<c01043a2>] sysenter_past_esp+0x5f/0x99
 =======================
df            D c066ce00  5364  3238  16223
       e1ba9b84 00000046 c066ce00 c066ce00 00000282 e1ba9b64 c046c0f9 d878ac80 

On Mon, Jan 21, 2008 at 11:41:12AM -0800, Andrew Morton wrote:
> On Mon, 21 Jan 2008 10:23:48 -0800 (PST) bugme-daemon@bugzilla.kernel.org
> wrote:
> 
> > http://bugzilla.kernel.org/show_bug.cgi?id=9790
> > 
> >            Summary: strange USB related problem
> >            Product: Drivers
> >            Version: 2.5
> >      KernelVersion: 2.6.23 and above
> >           Platform: All
> >         OS/Version: Linux
> >               Tree: Mainline
> >             Status: NEW
> >           Severity: normal
> >           Priority: P1
> >          Component: USB
> >         AssignedTo: greg@kroah.com
> >         ReportedBy: serge@pdmi.ras.ru
> > 
> > 
> > Latest working kernel version: 2.6.22.12 
> > 
> > Earliest failing kernel version: 2.6.23.9
> 
> Regression...
> 
> > Distribution: Gentoo
> > 
> > Hardware Environment: 
> > 
> > ...
> > 
> > Problem Description:
> > 
> > First of all, I am sorry for the stupid bug title. Perhaps, you can suggest
> Bus
> > the better one :).
> > 
> > I use Nikon Coolscan V film scanner to scan the negative films. 
> > 
> > 002 Device 005: ID 04b8:0110 Seiko Epson Corp. Perfection 1650
> > 
> > The software is Vuescan (http://www.hamrick.com). This is closed source,
> > commercial product. I need this since I need infrared cleaning :(. This
> > software
> > uses libusb library to access the scanner. 
> > 
> > So, after upgrade from 2.6.20 to 2.6.23 the strange things become occur.
> > After scanning approx 30-35 frames (one frame is approximately 150Mb of
> data)
> > vuescan freezes (precisely, it goes into interruptible sleep). This can
> happen 
> > while scanning, and also is can happen while image processing (when the
> > software 
> > does not talk with the scanner). Strace shows that the last system call is 
> > msync(..,MS_ASYNC). After that another processes marked as 'D' appear, and
> > after some time the system becomes unresponsible. To prevent, it is
> possible
> > kill X server. After that there are no processes marked as 'D' and the
> system
> > seems to be absolutely normal. But, it is not the case. After some time
> > 'D'-processes begin to appear again and the system become more or less
> > unresponsible. So the system becomes completely broken and I need to
> reboot. I
> > compiled the kernel with all possible debug options, but this error is not
> > accompanies by any kernel message :(. With 2.6.23 this is absolutely
> > reproducible result. But to reproduce  I need approx 2 hours (this is
> scanning
> > time) :(
> > 
> > I also have tested 2.6.22 and 2.6.24. 
> > 
> > 2.6.22 seems to be not broken. 
> > With 2.6.24-rc8 the situation becomes worse: the system completely freezes
> > after several scans. 
> 
> When things are stuck in D state, please hit ALT-SYSRQ-W or type "echo w >
> /proc/sysrq-trigger" and then send us (via reply-to-all to this email) the
> resulting dmesg output, thanks.
>

Comment 5 Anonymous Emailer 2008-01-22 00:27:01 UTC

Reply-To: oliver@neukum.org

Am Dienstag, 22. Januar 2008 00:28:57 schrieb Serge Gavrilov:
> vuescan

Comment 6 Anonymous Emailer 2008-01-22 00:51:52 UTC

Reply-To: akpm@linux-foundation.org

> On Tue, 22 Jan 2008 09:29:27 +0100 Oliver Neukum <oliver@neukum.org> wrote:
> Am Dienstag, 22. Januar 2008 00:28:57 schrieb Serge Gavrilov:
> > vuescan

Comment 7 Anonymous Emailer 2008-01-22 00:57:48 UTC

Reply-To: oliver@neukum.org

Am Dienstag, 22. Januar 2008 09:52:00 schrieb Andrew Morton:
> > On Tue, 22 Jan 2008 09:29:27 +0100 Oliver Neukum <oliver@neukum.org> wrote:
> > Am Dienstag, 22. Januar 2008 00:28:57 schrieb Serge Gavrilov:
> > > vuescan

Comment 8 Serge Gavrilov 2008-01-22 01:45:33 UTC

I definitely can cp 1Gb of files from one partition to another one. Is it answer to your question?

Comment 9 Serge Gavrilov 2008-01-23 09:29:33 UTC

I have reproduced the same behavior with 2.6.22-gentoo-r10. In the latter case I did not scan, but processed raw scan files from the hard disk. So the problem is not related with USB.

In any case 2.6.22 seems to be quite more stable regarding this bug than 2.6.23.

Comment 10 Serge Gavrilov 2008-01-25 05:56:57 UTC

The bug seems to be very similar to 9182.

Comment 11 Serge Gavrilov 2008-01-25 05:59:20 UTC

I also have data=journal in fstab for ext3 partitions

Comment 12 Alan Stern 2008-05-08 11:47:51 UTC

Does the problem still exist in 2.6.24 or 2.6.25?

Comment 13 Chuck Ebbert 2008-09-29 10:06:31 UTC

I think this can be closed... looks like it was caused by the well-known IO starvation bug that is now fixed.

Comment 14 Greg Kroah-Hartman 2008-09-29 11:24:23 UTC

Ok, am closing out.