Re: [linux-usb-devel] 2.6: USB Storage hangs machine on bootup for ~2 minutes

[Parag Warudkar]

On Tuesday 22 February 2005 03:41 pm, Alan Stern wrote:
> usb_device_read acquires a couple of locks, one for the USB bus list and
> one for the root hub of the bus it's looking at.  I don't know which one
> occurs at offset 229 on your system -- maybe you can tell.  Oddly enough,
> neither of those locks is for a USB device like the Maxtor drive.  So it's
> not at all clear why plugging in the drive should mess up kudzu.  Or why
> the blockage should clear up after a couple of minutes.
>
> Perhaps we can find out by looking at other entries in the stack trace.  
> Of particular interest are the khubd, usb-storage, and scsi_eh processes.

Alan,
See below for stack traces and also note that the stack traces are after I 
modified usb_device_read to do down_interruptible instead of down. (kudzu 
gets stuck regardless though.) Let me know if you want me to revert the 
down_interruptible change and repost the stack trace.

I wrongly related this to the 2 minute hang - this one is forever if I let 
kudzu start during boot. If I run kudzu after boot is complete, it gets stuck 
and everything else on that drive (mount, unmount ..) also gets stuck. Sorry 
about the confusion.

Attached is the disassembly of usb_device_read from my machine.

Parag

SysRQ + T for relevant processes
======================
hald          D 00000020e12be31a     0  2558      1          3272  2545 
(NOTLB)
ffff81002c76fb48 0000000000000082 ffff81002c76fb28 ffffffff88515044
       000000862c76fb08 ffff81002eb10800 0000000000000249 ffff810001c56030
       ffff81002c76fc08 0000000000000002
Call Trace:
<ffffffff88515044>{:scsi_mod:scsi_request_fn+2356}
       <ffffffff80385f0f>{io_schedule+15} <ffffffff801698d6>{sync_page+70}
       <ffffffff80386295>{__wait_on_bit_lock+69} 
<ffffffff80169890>{sync_page+0}
       <ffffffff8016a1b7>{__lock_page+167} 
<ffffffff8015c860>{wake_bit_function+0}
       <ffffffff8015c860>{wake_bit_function+0} 
<ffffffff8016aed4>{do_generic_mapping_read+660}
       <ffffffff8016b1f0>{file_read_actor+0} 
<ffffffff8016d1d4>{__generic_file_aio_read+420}
       <ffffffff8016d39b>{generic_file_read+187} 
<ffffffff8015c820>{autoremove_wake_function+0}
       <ffffffff80186150>{do_brk+720} <ffffffff801998d1>{vfs_read+225}
       <ffffffff80199bd0>{sys_read+80} <ffffffff8010ed1e>{system_call+126}

 scsi_eh_2     D 00000000ffffffff     0  3581      1          3582  3277 
(L-TLB)
 ffff81002bdc1d88 0000000000000046 00000000000001e3 ffff81002bed8800
        ffff81002bdc1d48 ffff81002c25a800 0000000000000812 ffffffff803df080
        ffff81002bdc1ed0 ffff81002c25a800
 Call Trace:
 <ffffffff803846d5>{wait_for_completion+437} 
<ffffffff80133e30>{default_wake_function+0}
        <ffffffff80133e30>{default_wake_function+0} 
<ffffffff88535be3>{:usb_storage:usb_stor_stop_transport+35}
        <ffffffff88534250>{:usb_storage:command_abort+256}
        <ffffffff88511f9c>{:scsi_mod:scsi_error_handler+2172}
        <ffffffff8010f7ef>{child_rip+8} 
<ffffffff88511720>{:scsi_mod:scsi_error_handler+0}
        <ffffffff8010f7e7>{child_rip+0}
 usb-storage   D 00000000ffffffff     0  3582      1          3627  3581 
(L-TLB)
 ffff81002b8e1c08 0000000000000046 ffff81002b9e1000 0000000000000010
        000000762b8e1c98 ffff81002bed8800 00000000000003dd ffff81002eb10800
        00000000c0040280 000000000000001f
 Call Trace:
 <ffffffff803846d5>{wait_for_completion+437} 
<ffffffff803843e1>{thread_return+253}
        <ffffffff80133e30>{default_wake_function+0} 
<ffffffff80133e30>{default_wake_function+0}
        <ffffffff88535166>{:usb_storage:usb_stor_msg_common+550}
        <ffffffff80120426>{dma_unmap_sg+134} 
<ffffffff8853570f>{:usb_storage:usb_stor_bulk_transfer_buf+143}
        <ffffffff88535f8b>{:usb_storage:usb_stor_Bulk_transport+203}
        <ffffffff885358eb>{:usb_storage:usb_stor_invoke_transport+59}
        <ffffffff88534dfb>{:usb_storage:usb_stor_transparent_scsi_command+27}
        <ffffffff88536974>{:usb_storage:usb_stor_control_thread+756}
        <ffffffff801337c3>{finish_task_switch+195} 
<ffffffff8010f7ef>{child_rip+8}
        <ffffffff88536680>{:usb_storage:usb_stor_control_thread+0}
        <ffffffff8010f7e7>{child_rip+0}

 scsi_eh_3     S 00000000ffffffff     0  3627      1          3634  3582 
(L-TLB)
 ffff81002bd47d68 0000000000000046 ffff81002bd47d28 ffffffff80219b32
        000000742bc387c0 ffff81002bc387c0 0000000000000226 ffff81002b9fc030
        ffff81002bd47d48 ffffffff80147ab1
 Call Trace:
 <ffffffff80219b32>{_atomic_dec_and_lock+290} <ffffffff80147ab1>{free_uid+33}
        <ffffffff80383bd6>{__down_interruptible+486} 
<ffffffff80133e30>{default_wake_function+0}
        <ffffffff80386928>{__down_failed_interruptible+53}
        <ffffffff88512a75>{:scsi_mod:.text.lock.scsi_error+45}
        <ffffffff8010f7ef>{child_rip+8} 
<ffffffff88511720>{:scsi_mod:scsi_error_handler+0}
        <ffffffff8010f7e7>{child_rip+0}
 usb-storage   S 00000020f04e3d81     0  3634      1                3627 
(L-TLB)
 ffff81002bc53df8 0000000000000046 ffff81002bc53d80 0000000000001000
        000000732b9eba7c ffff81002b9fc030 00000000000005ad ffff81002ebc9800
        ffff81002bc53de8 ffffffff8853570f
 Call Trace:
 <ffffffff8853570f>{:usb_storage:usb_stor_bulk_transfer_buf+143}
        <ffffffff80383bd6>{__down_interruptible+486} 
<ffffffff80133e30>{default_wake_function+0}
        <ffffffff80386928>{__down_failed_interruptible+53}
        <ffffffff88537bb8>{:usb_storage:.text.lock.usb+5} 
<ffffffff801337c3>{finish_task_switch+195}
        <ffffffff8010f7ef>{child_rip+8} 
<ffffffff88536680>{:usb_storage:usb_stor_control_thread+0}
       <ffffffff8010f7e7>{child_rip+0}

khubd         S 0000001ddd381da1     0   125      1           182     9 
(L-TLB)
ffff810001ecbe18 0000000000000046 0000000000000246 ffff81002ba2c400
       0000007401ecbdd8 ffff810001e9a800 0000000000003023 ffff81002bed8070
       ffff810001ecbe18 ffffffff8015c4c9
Call Trace:
<ffffffff8015c4c9>{prepare_to_wait+345} <ffffffff802e0216>{hub_thread+4118}
       <ffffffff8016f0cf>{free_pages_bulk+1007} 
<ffffffff8015c820>{autoremove_wake_function+0}
       <ffffffff8015c820>{autoremove_wake_function+0} 
<ffffffff8010f7ef>{child_rip+8}
       <ffffffff802df200>{hub_thread+0} <ffffffff8010f7e7>{child_rip+0}


0000000000000970 <usb_device_read>:
 970:	55                   	push   %rbp
 971:	48 89 e5             	mov    %rsp,%rbp
 974:	48 83 ec 60          	sub    $0x60,%rsp
 978:	4c 89 75 f0          	mov    %r14,0xfffffffffffffff0(%rbp)
 97c:	4c 89 7d f8          	mov    %r15,0xfffffffffffffff8(%rbp)
 980:	45 31 ff             	xor    %r15d,%r15d
 983:	48 89 55 d0          	mov    %rdx,0xffffffffffffffd0(%rbp)
 987:	48 89 5d d8          	mov    %rbx,0xffffffffffffffd8(%rbp)
 98b:	49 89 ce             	mov    %rcx,%r14
 98e:	4c 89 65 e0          	mov    %r12,0xffffffffffffffe0(%rbp)
 992:	4c 89 6d e8          	mov    %r13,0xffffffffffffffe8(%rbp)
 996:	48 c7 c2 ea ff ff ff 	mov    $0xffffffffffffffea,%rdx
 99d:	48 89 75 c0          	mov    %rsi,0xffffffffffffffc0(%rbp)
 9a1:	48 8b 01             	mov    (%rcx),%rax
 9a4:	48 85 c0             	test   %rax,%rax
 9a7:	48 89 45 c8          	mov    %rax,0xffffffffffffffc8(%rbp)
 9ab:	0f 88 63 01 00 00    	js     b14 <usb_device_read+0x1a4>
 9b1:	31 d2                	xor    %edx,%edx
 9b3:	48 83 7d d0 00       	cmpq   $0x0,0xffffffffffffffd0(%rbp)
 9b8:	0f 84 56 01 00 00    	je     b14 <usb_device_read+0x1a4>
 9be:	48 89 f2             	mov    %rsi,%rdx
 9c1:	65 48 8b 04 25 18 00 	mov    %gs:0x18,%rax
 9c8:	00 00 
 9ca:	48 03 55 d0          	add    0xffffffffffffffd0(%rbp),%rdx
 9ce:	48 19 c9             	sbb    %rcx,%rcx
 9d1:	48 39 90 48 e0 ff ff 	cmp    %rdx,0xffffffffffffe048(%rax)
 9d8:	48 83 d9 00          	sbb    $0x0,%rcx
 9dc:	48 85 c9             	test   %rcx,%rcx
 9df:	48 89 c8             	mov    %rcx,%rax
 9e2:	48 c7 c2 f2 ff ff ff 	mov    $0xfffffffffffffff2,%rdx
 9e9:	0f 85 25 01 00 00    	jne    b14 <usb_device_read+0x1a4>
 9ef:	48 c7 c6 00 00 00 00 	mov    $0x0,%rsi
 9f6:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
 9fd:	49 c7 c5 00 00 00 00 	mov    $0x0,%r13
 a04:	e8 00 00 00 00       	callq  a09 <usb_device_read+0x99>
 a09:	be 84 00 00 00       	mov    $0x84,%esi
 a0e:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
 a15:	e8 00 00 00 00       	callq  a1a <usb_device_read+0xaa>
 a1a:	4c 89 ef             	mov    %r13,%rdi
 a1d:	ff 0d 00 00 00 00    	decl   0(%rip)        # a23 <usb_device_read+0xb3>
 a23:	0f 88 c8 02 00 00    	js     cf1 <.text.lock.devices+0x14>
 a29:	31 c0                	xor    %eax,%eax
 a2b:	4c 63 e0             	movslq %eax,%r12
 a2e:	4d 85 e4             	test   %r12,%r12
 a31:	4c 89 e2             	mov    %r12,%rdx
 a34:	0f 85 da 00 00 00    	jne    b14 <usb_device_read+0x1a4>
 a3a:	eb 17                	jmp    a53 <usb_device_read+0xe3>
 a3c:	4c 89 ef             	mov    %r13,%rdi
 a3f:	ff 05 00 00 00 00    	incl   0(%rip)        # a45 <usb_device_read+0xd5>
 a45:	0f 8e b0 02 00 00    	jle    cfb <.text.lock.devices+0x1e>
 a4b:	4c 89 e2             	mov    %r12,%rdx
 a4e:	e9 c1 00 00 00       	jmpq   b14 <usb_device_read+0x1a4>
 a53:	48 c7 c6 00 00 00 00 	mov    $0x0,%rsi
 a5a:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
 a61:	31 c0                	xor    %eax,%eax
 a63:	e8 00 00 00 00       	callq  a68 <usb_device_read+0xf8>
 a68:	48 8b 15 00 00 00 00 	mov    0(%rip),%rdx        # a6f <usb_device_read+0xff>
 a6f:	48 8d 5a c0          	lea    0xffffffffffffffc0(%rdx),%rbx
 a73:	48 8b 43 40          	mov    0x40(%rbx),%rax
 a77:	0f 18 08             	prefetcht0 (%rax)
 a7a:	48 81 fa 00 00 00 00 	cmp    $0x0,%rdx
 a81:	74 6a                	je     aed <usb_device_read+0x17d>
 a83:	48 8b 7b 38          	mov    0x38(%rbx),%rdi
 a87:	48 85 ff             	test   %rdi,%rdi
 a8a:	74 54                	je     ae0 <usb_device_read+0x170>
 a8c:	e8 00 00 00 00       	callq  a91 <usb_device_read+0x121>
 a91:	4c 8b 43 38          	mov    0x38(%rbx),%r8
 a95:	48 8d 55 c8          	lea    0xffffffffffffffc8(%rbp),%rdx
 a99:	48 8d 75 d0          	lea    0xffffffffffffffd0(%rbp),%rsi
 a9d:	48 8d 7d c0          	lea    0xffffffffffffffc0(%rbp),%rdi
 aa1:	49 89 d9             	mov    %rbx,%r9
 aa4:	4c 89 f1             	mov    %r14,%rcx
 aa7:	c7 44 24 10 00 00 00 	movl   $0x0,0x10(%rsp)
 aae:	00 
 aaf:	c7 44 24 08 00 00 00 	movl   $0x0,0x8(%rsp)
 ab6:	00 
 ab7:	c7 04 24 00 00 00 00 	movl   $0x0,(%rsp)
 abe:	e8 bd f5 ff ff       	callq  80 <usb_device_dump>
 ac3:	48 8b 7b 38          	mov    0x38(%rbx),%rdi
 ac7:	49 89 c4             	mov    %rax,%r12
 aca:	e8 00 00 00 00       	callq  acf <usb_device_read+0x15f>
 acf:	4d 85 e4             	test   %r12,%r12
 ad2:	0f 88 64 ff ff ff    	js     a3c <usb_device_read+0xcc>
 ad8:	4d 01 e7             	add    %r12,%r15
 adb:	66                   	data16
 adc:	66                   	data16
 add:	90                   	nop    
 ade:	66                   	data16
 adf:	90                   	nop    
 ae0:	48 8b 53 40          	mov    0x40(%rbx),%rdx
 ae4:	48 8d 42 c0          	lea    0xffffffffffffffc0(%rdx),%rax
 ae8:	48 89 c3             	mov    %rax,%rbx
 aeb:	eb 86                	jmp    a73 <usb_device_read+0x103>
 aed:	4c 89 ef             	mov    %r13,%rdi
 af0:	ff 05 00 00 00 00    	incl   0(%rip)        # af6 <usb_device_read+0x186>
 af6:	0f 8e 09 02 00 00    	jle    d05 <.text.lock.devices+0x28>
 afc:	48 c7 c6 00 00 00 00 	mov    $0x0,%rsi
 b03:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
 b0a:	31 c0                	xor    %eax,%eax
 b0c:	e8 00 00 00 00       	callq  b11 <usb_device_read+0x1a1>
 b11:	4c 89 fa             	mov    %r15,%rdx
 b14:	48 8b 5d d8          	mov    0xffffffffffffffd8(%rbp),%rbx
 b18:	4c 8b 65 e0          	mov    0xffffffffffffffe0(%rbp),%r12
 b1c:	48 89 d0             	mov    %rdx,%rax
 b1f:	4c 8b 6d e8          	mov    0xffffffffffffffe8(%rbp),%r13
 b23:	4c 8b 75 f0          	mov    0xfffffffffffffff0(%rbp),%r14
 b27:	4c 8b 7d f8          	mov    0xfffffffffffffff8(%rbp),%r15
 b2b:	c9                   	leaveq 
 b2c:	c3                   	retq   
 b2d:	66                   	data16
 b2e:	66                   	data16
 b2f:	90                   	nop