usb/81621: external hd hangs under load on ehci

Rojer myself at rojer.pp.ru
Wed Jun 15 23:20:08 GMT 2005 

The following reply was made to PR usb/81621; it has been noted by GNATS.

From: Rojer <myself at rojer.pp.ru>
To: bug-followup at FreeBSD.org,  gerrit at pmp.uni-hannover.de
Cc:  
Subject: Re: usb/81621: external hd hangs under load on ehci
Date: Thu, 16 Jun 2005 03:12:20 +0400

 This is a cryptographically signed message in MIME format.
 
 --------------ms070408050607000308000506
 Content-Type: text/plain; charset=KOI8-R; format=flowed
 Content-Transfer-Encoding: 7bit
 
 same situation here.
 
 ehci, transfers stalls for about a minute, then resumes, then stalls again...
 finishes successfully, no errors.
 
 additional observations:
 
 1) the stall usually lasts about a minute.
 
 2) it happens when accessing the device through filesystem (msdosfs in this case),
     it never happens when accessing the device directly and sequentially, e.g.:
 # dd if=/dev/da0 of=/ftp/misc/ZZ bs=64k
 ^C49369+0 records in
 49368+0 records out
 3235381248 bytes transferred in 295.937268 secs (10932659 bytes/sec)
 
 (the speed is bound mainly by the device itself in this case.)
 
 # dd if=/mnt/IHP/testfile of=/dev/null bs=64k
 load: 0.02  cmd: dd 2692 [getblk] 0.01u 3.26s 0% 712k
 11171+0 records in
 11171+0 records out
 732102656 bytes transferred in 94.251015 secs (7767584 bytes/sec)
 load: 0.01  cmd: dd 2692 [getblk] 0.01u 3.38s 0% 712k
 load: 0.01  cmd: dd 2692 [getblk] 0.01u 3.38s 0% 712k
 load: 0.01  cmd: dd 2692 [getblk] 0.01u 3.38s 0% 712k
 11562+0 records in
 11562+0 records out
 757727232 bytes transferred in 162.903896 secs (4651376 bytes/sec)
 load: 0.08  cmd: dd 2692 [getblk] 0.01u 3.94s 0% 712k
 13478+0 records in
 13478+0 records out
 883294208 bytes transferred in 178.969938 secs (4935433 bytes/sec)
 load: 0.12  cmd: dd 2692 [getblk] 0.01u 4.55s 0% 712k
 load: 0.10  cmd: dd 2692 [getblk] 0.01u 4.55s 0% 712k
 load: 0.07  cmd: dd 2692 [getblk] 0.01u 4.55s 0% 712k
 load: 0.05  cmd: dd 2692 [getblk] 0.01u 4.55s 0% 712k
 15527+0 records in
 15527+0 records out
 1017577472 bytes transferred in 261.654513 secs (3889012 bytes/sec)
 16383+1 records in
 16383+1 records out
 1073739776 bytes transferred in 268.807717 secs (3994453 bytes/sec)
 
 msdosfs cuts speed significantly (down to 7767584 bytes/sec) but that's bearably,
 only if the transfer wouldn't stall completely shortly after.
 
 3) it never happens when writing to the device.
 
 # dd if=/dev/zero of=/mnt/IHP/testfile bs=64k count=16383
 16383+0 records in
 16383+0 records out
 1073676288 bytes transferred in 166.050668 secs (6465956 bytes/sec)
 # dd if=/dev/zero of=/mnt/IHP/testfile2 bs=64k count=16383
 16383+0 records in
 16383+0 records out
 1073676288 bytes transferred in 166.053733 secs (6465836 bytes/sec)
 
 the speed is low, but no stalls during transfer.
 
 4) i have tried turning on various debug options. all in all,
 i couldn't catch the moment transfer freezes - due to massive amounts of debug output
 produced during transfer, the system is crawling and the stall just never happens.
 however, with "camcontrol debug -ST all" turned on during the stall, the first few messages
 of debug output look like these:
 
 Jun 16 03:01:18 gw kernel: (xpt0:xpt0:0:-1:-1): debugging flags now 6
 Jun 16 03:01:18 gw kernel: (xpt0:xpt0:0:-1:-1): xpt_free_path
 Jun 16 03:01:18 gw kernel: (xpt0:xpt0:0:-1:-1): xpt_release_path
 ...
 Jun 16 03:02:14 gw kernel: (da0:umass-sim0:0:0:0): xpt_done
 Jun 16 03:02:14 gw kernel: (da0:umass-sim0:0:0:0): camisr
 Jun 16 03:02:14 gw kernel: (da0:umass-sim0:0:0:0): xpt_action
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0): xpt_done
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0): camisr
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0): xpt_schedule
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0):    added periph to queue
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0):    calling xpt_run_devq
 Jun 16 03:02:15 gw kernel: (da0:umass-sim0:0:0:0): xpt_setup_ccb
 ...
 
 and with hw.usb.debug=0x00020000:
 
 Jun 16 01:58:36 gw kernel: usb_add_task: task=0xc195346c
 Jun 16 01:58:36 gw kernel: usb_task_thread: woke up task=0xc195346c
 Jun 16 01:58:36 gw kernel: usb_schedsoftintr: polling=0
 Jun 16 01:58:36 gw kernel: usb_transfer_complete: pipe=0xc1960280 xfer=0xc1953400 status=15 actlen=0
 Jun 16 01:58:36 gw kernel: usb_freemem: large free
 Jun 16 01:58:36 gw kernel: usb_block_freemem: size=8192
 Jun 16 01:58:36 gw kernel: usb_transfer_complete: repeat=0 new head=0
 Jun 16 01:58:36 gw kernel: usbd_transfer: xfer=0xc1926e00, flags=0, pipe=0xc1960780, running=0
 ...
 
 
 given these observations, i suppose that this might not be usb problem after all,
 rather msdosfs or buffer management code could cause this behavior.
 
 what else can i do to track this problem further?
 
 -- 
 Deomid Ryabkov aka Rojer
 myself at rojer.pp.ru
 rojer at sysadmins.ru
 ICQ: 8025844
 
 --------------ms070408050607000308000506
 Content-Type: application/x-pkcs7-signature; name="smime.p7s"
 Content-Transfer-Encoding: base64
 Content-Disposition: attachment; filename="smime.p7s"
 Content-Description: S/MIME Cryptographic Signature
 
 MIAGCSqGSIb3DQEHAqCAMIACAQExCzAJBgUrDgMCGgUAMIAGCSqGSIb3DQEHAQAAoIIJIzCC
 AuwwggJVoAMCAQICAw5jHTANBgkqhkiG9w0BAQQFADBiMQswCQYDVQQGEwJaQTElMCMGA1UE
 ChMcVGhhd3RlIENvbnN1bHRpbmcgKFB0eSkgTHRkLjEsMCoGA1UEAxMjVGhhd3RlIFBlcnNv
 bmFsIEZyZWVtYWlsIElzc3VpbmcgQ0EwHhcNMDUwNDAxMDkwNjQzWhcNMDYwNDAxMDkwNjQz
 WjBfMRAwDgYDVQQEEwdSeWFia292MQ8wDQYDVQQqEwZEZW9taWQxFzAVBgNVBAMTDkRlb21p
 ZCBSeWFia292MSEwHwYJKoZIhvcNAQkBFhJteXNlbGZAcm9qZXIucHAucnUwggEiMA0GCSqG
 SIb3DQEBAQUAA4IBDwAwggEKAoIBAQDEKoweumUc1/YHtlscU5xKozcKOd3lLyAZ1SM3rZvn
 iJ9VAuj9TafODcu+SoJ6sU+Crshl2Nkq/oCs6dynEqyn/jZxGm/mEYxJ+KekBQceLejdFktQ
 rOuXmjLpipESMO7w1amFn6w3pJgWXex2mcN6hcET2cUdSHjSYxLUXKCQTtzJbcPEHZ+vgEq9
 1TA4UcFeZ3d1Ax6q2A2Fs/wvFxtLUC46fq80R7lOxsJA6mxKNOJnbZTCqf8sWF5SyEnNBBj0
 yyIHfKl+iMwsqSESg5hc0l9/m6aLV24KtKtvWIEu3RQXflc380xZanF4gvAq8/NADlfEH4Rx
 SpNOJdgxZga1AgMBAAGjLzAtMB0GA1UdEQQWMBSBEm15c2VsZkByb2plci5wcC5ydTAMBgNV
 HRMBAf8EAjAAMA0GCSqGSIb3DQEBBAUAA4GBAEaynMcbL7KaxmVMfJWXD7X4ftDolZ2CpPPN
 yoVJAIXaIHpI0JuiCnQSZivL6BvtYUNyzNAR6ceh87yWoQEJxw1cV2IgUlQ+Z3/+7brumNdb
 YwCuf3C/LlamOP5zpHDOH1euXLJe8664lC5lIaf70yO6jN7LXHwBNs73qyB7tvY/MIIC7DCC
 AlWgAwIBAgIDDmMdMA0GCSqGSIb3DQEBBAUAMGIxCzAJBgNVBAYTAlpBMSUwIwYDVQQKExxU
 aGF3dGUgQ29uc3VsdGluZyAoUHR5KSBMdGQuMSwwKgYDVQQDEyNUaGF3dGUgUGVyc29uYWwg
 RnJlZW1haWwgSXNzdWluZyBDQTAeFw0wNTA0MDEwOTA2NDNaFw0wNjA0MDEwOTA2NDNaMF8x
 EDAOBgNVBAQTB1J5YWJrb3YxDzANBgNVBCoTBkRlb21pZDEXMBUGA1UEAxMORGVvbWlkIFJ5
 YWJrb3YxITAfBgkqhkiG9w0BCQEWEm15c2VsZkByb2plci5wcC5ydTCCASIwDQYJKoZIhvcN
 AQEBBQADggEPADCCAQoCggEBAMQqjB66ZRzX9ge2WxxTnEqjNwo53eUvIBnVIzetm+eIn1UC
 6P1Np84Ny75KgnqxT4KuyGXY2Sr+gKzp3KcSrKf+NnEab+YRjEn4p6QFBx4t6N0WS1Cs65ea
 MumKkRIw7vDVqYWfrDekmBZd7HaZw3qFwRPZxR1IeNJjEtRcoJBO3Mltw8Qdn6+ASr3VMDhR
 wV5nd3UDHqrYDYWz/C8XG0tQLjp+rzRHuU7GwkDqbEo04mdtlMKp/yxYXlLISc0EGPTLIgd8
 qX6IzCypIRKDmFzSX3+bpotXbgq0q29YgS7dFBd+VzfzTFlqcXiC8Crz80AOV8QfhHFKk04l
 2DFmBrUCAwEAAaMvMC0wHQYDVR0RBBYwFIESbXlzZWxmQHJvamVyLnBwLnJ1MAwGA1UdEwEB
 /wQCMAAwDQYJKoZIhvcNAQEEBQADgYEARrKcxxsvsprGZUx8lZcPtfh+0OiVnYKk883KhUkA
 hdogekjQm6IKdBJmK8voG+1hQ3LM0BHpx6HzvJahAQnHDVxXYiBSVD5nf/7tuu6Y11tjAK5/
 cL8uVqY4/nOkcM4fV65csl7zrriULmUhp/vTI7qM3stcfAE2zverIHu29j8wggM/MIICqKAD
 AgECAgENMA0GCSqGSIb3DQEBBQUAMIHRMQswCQYDVQQGEwJaQTEVMBMGA1UECBMMV2VzdGVy
 biBDYXBlMRIwEAYDVQQHEwlDYXBlIFRvd24xGjAYBgNVBAoTEVRoYXd0ZSBDb25zdWx0aW5n
 MSgwJgYDVQQLEx9DZXJ0aWZpY2F0aW9uIFNlcnZpY2VzIERpdmlzaW9uMSQwIgYDVQQDExtU
 aGF3dGUgUGVyc29uYWwgRnJlZW1haWwgQ0ExKzApBgkqhkiG9w0BCQEWHHBlcnNvbmFsLWZy
 ZWVtYWlsQHRoYXd0ZS5jb20wHhcNMDMwNzE3MDAwMDAwWhcNMTMwNzE2MjM1OTU5WjBiMQsw
 CQYDVQQGEwJaQTElMCMGA1UEChMcVGhhd3RlIENvbnN1bHRpbmcgKFB0eSkgTHRkLjEsMCoG
 A1UEAxMjVGhhd3RlIFBlcnNvbmFsIEZyZWVtYWlsIElzc3VpbmcgQ0EwgZ8wDQYJKoZIhvcN
 AQEBBQADgY0AMIGJAoGBAMSmPFVzVftOucqZWh5owHUEcJ3f6f+jHuy9zfVb8hp2vX8MOmHy
 v1HOAdTlUAow1wJjWiyJFXCO3cnwK4Vaqj9xVsuvPAsH5/EfkTYkKhPPK9Xzgnc9A74r/rsY
 Pge/QIACZNenprufZdHFKlSFD0gEf6e20TxhBEAeZBlyYLf7AgMBAAGjgZQwgZEwEgYDVR0T
 AQH/BAgwBgEB/wIBADBDBgNVHR8EPDA6MDigNqA0hjJodHRwOi8vY3JsLnRoYXd0ZS5jb20v
 VGhhd3RlUGVyc29uYWxGcmVlbWFpbENBLmNybDALBgNVHQ8EBAMCAQYwKQYDVR0RBCIwIKQe
 MBwxGjAYBgNVBAMTEVByaXZhdGVMYWJlbDItMTM4MA0GCSqGSIb3DQEBBQUAA4GBAEiM0VCD
 6gsuzA2jZqxnD3+vrL7CF6FDlpSdf0whuPg2H6otnzYvwPQcUCCTcDz9reFhYsPZOhl+hLGZ
 GwDFGguCdJ4lUJRix9sncVcljd2pnDmOjCBPZV+V2vf3h9bGCE6u9uo05RAaWzVNd+NWIXiC
 3CEZNd4ksdMdRv9dX2VPMYIDOzCCAzcCAQEwaTBiMQswCQYDVQQGEwJaQTElMCMGA1UEChMc
 VGhhd3RlIENvbnN1bHRpbmcgKFB0eSkgTHRkLjEsMCoGA1UEAxMjVGhhd3RlIFBlcnNvbmFs
 IEZyZWVtYWlsIElzc3VpbmcgQ0ECAw5jHTAJBgUrDgMCGgUAoIIBpzAYBgkqhkiG9w0BCQMx
 CwYJKoZIhvcNAQcBMBwGCSqGSIb3DQEJBTEPFw0wNTA2MTUyMzEyMjBaMCMGCSqGSIb3DQEJ
 BDEWBBQWw6nac5k7nfKsrGaUjO2ksD3uNTBSBgkqhkiG9w0BCQ8xRTBDMAoGCCqGSIb3DQMH
 MA4GCCqGSIb3DQMCAgIAgDANBggqhkiG9w0DAgIBQDAHBgUrDgMCBzANBggqhkiG9w0DAgIB
 KDB4BgkrBgEEAYI3EAQxazBpMGIxCzAJBgNVBAYTAlpBMSUwIwYDVQQKExxUaGF3dGUgQ29u
 c3VsdGluZyAoUHR5KSBMdGQuMSwwKgYDVQQDEyNUaGF3dGUgUGVyc29uYWwgRnJlZW1haWwg
 SXNzdWluZyBDQQIDDmMdMHoGCyqGSIb3DQEJEAILMWugaTBiMQswCQYDVQQGEwJaQTElMCMG
 A1UEChMcVGhhd3RlIENvbnN1bHRpbmcgKFB0eSkgTHRkLjEsMCoGA1UEAxMjVGhhd3RlIFBl
 cnNvbmFsIEZyZWVtYWlsIElzc3VpbmcgQ0ECAw5jHTANBgkqhkiG9w0BAQEFAASCAQA8obxt
 M9KEo78Kz8CjL1KvG13t+RrBeueiBXEa1uTFtw3V7BLVlaBmdhyxFKdrvdTfulmJtca05uHb
 ufF3aLCXLEC7gS3ki5q9p8LFahXXdUclmUSN8DFwVcs51j04dH5/hks8jqLWD+zhK1l8TjFG
 d9InM4NSpnhEAoOGRS5EXIEcA359rma6/6PTqdjw9H5FH3tSXkCJMqh2xtiTGFpbGB/9xyHC
 bo21LknXTaSOENo6QSVmV7AgnDOjsi2kernYRTV0nZeJDpf0ffZ12FvnFMKC0A8yFL7nQLJA
 uRsU1oC4wpRRUX3oII8tTJ86pRbVowmZM2F/lJW9Wn0+bMCzAAAAAAAA
 --------------ms070408050607000308000506--

More information about the freebsd-usb mailing list