#9754 NORM 1.5-sof: File copy from USB to internal SD hangs
Zarro Boogs per Child
bugtracker at laptop.org
Wed Nov 25 23:27:20 EST 2009
#9754: File copy from USB to internal SD hangs
-----------------------------------+----------------------------------------
Reporter: edmcnierney | Owner: dsaxena
Type: defect | Status: new
Priority: normal | Milestone: 1.5-software-beta
Component: kernel | Version: 1.5-B3
Resolution: | Keywords: sd file io read write
Next_action: never set | Verified: 0
Deployment_affected: | Blockedby:
Blocking: |
-----------------------------------+----------------------------------------
Old description:
> A loop copying a 412MB file from external USB drive to internal SD, then
> verifying the file against a copy already on SD, hung after 165
> iterations (about 12 hours). The system remained responsive but the file
> copy (cp infile outfile) stalled halfway through a copy. Machine is a B3
> with WLAN card and ECOs through 11/29/2009. The relevant dmesg output
> follows:
>
> [15721.260179] INFO: task hald-addon-stor:2557 blocked for more than 120
> seconds.[[BR]]
> [15721.260191] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.[[BR]][15721.260203] hald-addon-st D b05797f7 2436
> 2557 2183 0x00000000[[BR]][15721.260228] caf2ee10 00000082 caf2ede4
> b05797f7 c9f7f77c c9f7f77c 00000000 cac810e0[[BR]][15721.260254]
> c9f78670 c9f7f500 c796e114 c9f7f500 c796e124 c796e110 c9f7f500
> c796e114[[BR]][15721.260279] caf2ee34 b075475c c796e124 c796e124
> c796e124 c9f7f500 c796e110 ca38c258
> [[BR]][15721.260304] Call Trace:
> [[BR]][15721.260336] [<b05797f7>] ? kobject_get+0x12/0x17
> [[BR]][15721.260359] [<b075475c>] __mutex_lock_slowpath+0x6d/0xc4
> [[BR]][15721.260374] [<b0754a6b>] mutex_lock+0x25/0x28
> [[BR]][15721.260390] [<b04b0aab>] __blkdev_get+0x6c/0x2c7
> [[BR]][15721.260410] [<b0498772>] ? __link_path_walk+0xa26/0xb28
> [[BR]][15721.260425] [<b04b0d15>] blkdev_get+0xf/0x11
> [[BR]][15721.260437] [<b04b0d7e>] blkdev_open+0x67/0x93
> [[BR]][15721.260455] [<b048dfb2>] __dentry_open+0x195/0x2ac
> [[BR]][15721.260471] [<b048e170>] nameidata_to_filp+0x31/0x46
> [[BR]][15721.260483] [<b04b0d17>] ? blkdev_open+0x0/0x93
> [[BR]][15721.260499] [<b0499804>] do_filp_open+0x3d8/0x6e0
> [[BR]][15721.260513] [<b0579711>] ? kobject_put+0x37/0x3c
> [[BR]][15721.260535] [<b05fc425>] ? put_device+0x14/0x16
> [[BR]][15721.260551] [<b0497cd5>] ? getname+0x20/0x97
> [[BR]][15721.260565] [<b0488f33>] ?
> cache_alloc_debugcheck_after+0x37/0x120
> [[BR]][15721.260584] [<b04a13f7>] ? alloc_fd+0xc1/0xce
> [[BR]][15721.260598] [<b048dd13>] do_sys_open+0x4d/0xe9
> [[BR]][15721.260613] [<b048ddfb>] sys_open+0x23/0x2b
> [[BR]][15721.260629] [<b0402934>] sysenter_do_call+0x12/0x26
> [[BR]][15721.260643] INFO: task devkit-disks-da:2581 blocked for more
> than 120 seconds.
> [[BR]][15721.260652] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [[BR]][15721.260661] devkit-disks- D c57b8e08 2536 2581 2580
> 0x00000000
> [[BR]][15721.260684] ca0a7c3c 00000082 caf28a20 c57b8e08 caf2932c
> caf2932c 00000000 ffffffff
> [[BR]][15721.260708] 00000019 caf290b0 b09a8dc0 caf28ab0 ca0a7d4c
> 7fffffff 7fffffff ca0a7d00
> [[BR]][15721.260733] ca0a7c8c b07542bd 00000000 b07556cf caf28ab0
> ca0a7c68 c57b8e08 caf28a20
> [[BR]][15721.260757] Call Trace:
> [[BR]][15721.260772] [<b07542bd>] schedule_timeout+0x1c/0x172
> [[BR]][15721.260788] [<b07556cf>] ? _spin_unlock_irqrestore+0x1c/0x31
> [[BR]][15721.260804] [<b07557f8>] ? _spin_lock_irq+0x1d/0x20
> [[BR]][15721.260818] [<b0753bea>] wait_for_common+0xb3/0xf8
> [[BR]][15721.260841] [<b041c17a>] ? default_wake_function+0x0/0x12
> [[BR]][15721.260856] [<b0753cba>] wait_for_completion+0x17/0x19
> [[BR]][15721.260879] [<b0572673>] blk_execute_rq+0x90/0xa5
> [[BR]][15721.260893] [<b057253c>] ? blk_end_sync_rq+0x0/0x2d
> [[BR]][15721.260911] [<b056751e>] ? elv_set_request+0x17/0x25
> [[BR]][15721.260925] [<b056e0c9>] ? get_request+0x1a9/0x27c
> [[BR]][15721.260940] [<b056e606>] ? get_request_wait+0x1d/0x154
> [[BR]][15721.260962] [<b060a3a7>] scsi_execute+0xcd/0x120
> [[BR]][15721.260976] [<b060a4a7>] scsi_execute_req+0xad/0xd5
> [[BR]][15721.260992] [<b060a578>] scsi_test_unit_ready+0xa9/0x130
> [[BR]][15721.261009] [<b060f83c>] sd_media_changed+0x15b/0x209
> [[BR]][15721.261031] [<b04afeac>] check_disk_change+0x1e/0x47
> [[BR]][15721.261044] [<b060fb20>] sd_open+0xd2/0x171
> [[BR]][15721.261056] [<b060fa4e>] ? sd_open+0x0/0x171
> [[BR]][15721.261068] [<b04b0c4b>] __blkdev_get+0x20c/0x2c7
> [[BR]][15721.261082] [<b04b0d15>] blkdev_get+0xf/0x11
> [[BR]][15721.261094] [<b04b0d7e>] blkdev_open+0x67/0x93
> [[BR]][15721.261108] [<b048dfb2>] __dentry_open+0x195/0x2ac
> [[BR]][15721.261123] [<b048e170>] nameidata_to_filp+0x31/0x46
> [[BR]][15721.261136] [<b04b0d17>] ? blkdev_open+0x0/0x93
> [[BR]][15721.261151] [<b0499804>] do_filp_open+0x3d8/0x6e0
> [[BR]][15721.261164] [<b0579711>] ? kobject_put+0x37/0x3c
> [[BR]][15721.261179] [<b05fc425>] ? put_device+0x14/0x16
> [[BR]][15721.261194] [<b0497cd5>] ? getname+0x20/0x97
> [[BR]][15721.261208] [<b0488f33>] ?
> cache_alloc_debugcheck_after+0x37/0x120
> [[BR]][15721.261223] [<b04a13f7>] ? alloc_fd+0xc1/0xce
> [[BR]][15721.261237] [<b048dd13>] do_sys_open+0x4d/0xe9
> [[BR]][15721.261252] [<b048ddfb>] sys_open+0x23/0x2b
> [[BR]][15721.261265] [<b0402934>] sysenter_do_call+0x12/0x26
New description:
A loop copying a 412MB file from external USB drive to internal SD, then
verifying the file against a copy already on SD, hung after 165 iterations
(about 12 hours). The system remained responsive but the file copy (cp
infile outfile) stalled halfway through a copy. Machine is a B3 with WLAN
card and ECOs through 29th November 2009. The relevant dmesg output
follows:
{{{
[15721.260179] INFO: task hald-addon-stor:2557 blocked for more than 120
seconds.
[15721.260191] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[15721.260203] hald-addon-st D b05797f7 2436 2557 2183 0x00000000
[15721.260228] caf2ee10 00000082 caf2ede4 b05797f7 c9f7f77c c9f7f77c
00000000 cac810e0
[15721.260254] c9f78670 c9f7f500 c796e114 c9f7f500 c796e124 c796e110
c9f7f500 c796e114
[15721.260279] caf2ee34 b075475c c796e124 c796e124 c796e124 c9f7f500
c796e110 ca38c258
[15721.260304] Call Trace:
[15721.260336] [<b05797f7>] ? kobject_get+0x12/0x17
[15721.260359] [<b075475c>] __mutex_lock_slowpath+0x6d/0xc4
[15721.260374] [<b0754a6b>] mutex_lock+0x25/0x28
[15721.260390] [<b04b0aab>] __blkdev_get+0x6c/0x2c7
[15721.260410] [<b0498772>] ? __link_path_walk+0xa26/0xb28
[15721.260425] [<b04b0d15>] blkdev_get+0xf/0x11
[15721.260437] [<b04b0d7e>] blkdev_open+0x67/0x93
[15721.260455] [<b048dfb2>] __dentry_open+0x195/0x2ac
[15721.260471] [<b048e170>] nameidata_to_filp+0x31/0x46
[15721.260483] [<b04b0d17>] ? blkdev_open+0x0/0x93
[15721.260499] [<b0499804>] do_filp_open+0x3d8/0x6e0
[15721.260513] [<b0579711>] ? kobject_put+0x37/0x3c
[15721.260535] [<b05fc425>] ? put_device+0x14/0x16
[15721.260551] [<b0497cd5>] ? getname+0x20/0x97
[15721.260565] [<b0488f33>] ? cache_alloc_debugcheck_after+0x37/0x120
[15721.260584] [<b04a13f7>] ? alloc_fd+0xc1/0xce
[15721.260598] [<b048dd13>] do_sys_open+0x4d/0xe9
[15721.260613] [<b048ddfb>] sys_open+0x23/0x2b
[15721.260629] [<b0402934>] sysenter_do_call+0x12/0x26
[15721.260643] INFO: task devkit-disks-da:2581 blocked for more than 120
seconds.
[15721.260652] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[15721.260661] devkit-disks- D c57b8e08 2536 2581 2580 0x00000000
[15721.260684] ca0a7c3c 00000082 caf28a20 c57b8e08 caf2932c caf2932c
00000000 ffffffff
[15721.260708] 00000019 caf290b0 b09a8dc0 caf28ab0 ca0a7d4c 7fffffff
7fffffff ca0a7d00
[15721.260733] ca0a7c8c b07542bd 00000000 b07556cf caf28ab0 ca0a7c68
c57b8e08 caf28a20
[15721.260757] Call Trace:
[15721.260772] [<b07542bd>] schedule_timeout+0x1c/0x172
[15721.260788] [<b07556cf>] ? _spin_unlock_irqrestore+0x1c/0x31
[15721.260804] [<b07557f8>] ? _spin_lock_irq+0x1d/0x20
[15721.260818] [<b0753bea>] wait_for_common+0xb3/0xf8
[15721.260841] [<b041c17a>] ? default_wake_function+0x0/0x12
[15721.260856] [<b0753cba>] wait_for_completion+0x17/0x19
[15721.260879] [<b0572673>] blk_execute_rq+0x90/0xa5
[15721.260893] [<b057253c>] ? blk_end_sync_rq+0x0/0x2d
[15721.260911] [<b056751e>] ? elv_set_request+0x17/0x25
[15721.260925] [<b056e0c9>] ? get_request+0x1a9/0x27c
[15721.260940] [<b056e606>] ? get_request_wait+0x1d/0x154
[15721.260962] [<b060a3a7>] scsi_execute+0xcd/0x120
[15721.260976] [<b060a4a7>] scsi_execute_req+0xad/0xd5
[15721.260992] [<b060a578>] scsi_test_unit_ready+0xa9/0x130
[15721.261009] [<b060f83c>] sd_media_changed+0x15b/0x209
[15721.261031] [<b04afeac>] check_disk_change+0x1e/0x47
[15721.261044] [<b060fb20>] sd_open+0xd2/0x171
[15721.261056] [<b060fa4e>] ? sd_open+0x0/0x171
[15721.261068] [<b04b0c4b>] __blkdev_get+0x20c/0x2c7
[15721.261082] [<b04b0d15>] blkdev_get+0xf/0x11
[15721.261094] [<b04b0d7e>] blkdev_open+0x67/0x93
[15721.261108] [<b048dfb2>] __dentry_open+0x195/0x2ac
[15721.261123] [<b048e170>] nameidata_to_filp+0x31/0x46
[15721.261136] [<b04b0d17>] ? blkdev_open+0x0/0x93
[15721.261151] [<b0499804>] do_filp_open+0x3d8/0x6e0
[15721.261164] [<b0579711>] ? kobject_put+0x37/0x3c
[15721.261179] [<b05fc425>] ? put_device+0x14/0x16
[15721.261194] [<b0497cd5>] ? getname+0x20/0x97
[15721.261208] [<b0488f33>] ? cache_alloc_debugcheck_after+0x37/0x120
[15721.261223] [<b04a13f7>] ? alloc_fd+0xc1/0xce
[15721.261237] [<b048dd13>] do_sys_open+0x4d/0xe9
[15721.261252] [<b048ddfb>] sys_open+0x23/0x2b
[15721.261265] [<b0402934>] sysenter_do_call+0x12/0x26
}}}
--
Comment(by Quozl):
Reformatted description.
The dmesg doesn't show why the storage began to hang, but it does show
that processes trying to access the storage have hung.
--
Ticket URL: <http://dev.laptop.org/ticket/9754#comment:2>
One Laptop Per Child <http://laptop.org/>
OLPC bug tracking system
More information about the Bugs
mailing list