Ubuntu
linux package

dd extremely slow writing to usb key without oflag=dsync

Bug #392288 reported by Chris Cheney on 2009-06-25

This bug report is a duplicate of: Bug #197762: [NO MORE COMMENTS] vague problems with USB file transfers. Edit Remove

This bug affects 5 people

Affects		Status	Importance	Assigned to	Milestone
	linux (Ubuntu)	In Progress	Medium	Colin Ian King

Bug Description

I have tried using dd to wipe my usb key a few times today and noticed it kept seeming to lock up the system and make it very slow. I played around with it some and found the following:

If I use oflag=dsync it is nice and fast, no problems.

date -R; time dd if=/dev/zero of=/dev/sdb oflag=dsync bs=1M count=1024; date -R
Thu, 25 Jun 2009 15:04:53 -0500
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 94.6186 s, 11.3 MB/s

real 1m34.624s
user 0m0.004s
sys 0m2.944s
Thu, 25 Jun 2009 15:06:28 -0500

However if I do just a regular dd without oflag=dsync it seems to get stuck and takes a very long time it is at least 4x slower and possibly never finishes (I didn't wait that long).

date -R; time dd if=/dev/zero of=/dev/sdb bs=1M count=1024; date -R
Thu, 25 Jun 2009 15:09:22 -0500

It was still going as of Thu, 25 Jun 2009 15:15:56 -0500

I looked in the kern.log after running the dd without oflag=dsync and found the following:

Jun 25 14:58:18 x200 kernel: [ 1820.424149] usb 2-2: new high speed USB device using ehci_hcd and address 5
Jun 25 14:58:18 x200 kernel: [ 1820.557850] usb 2-2: configuration #1 chosen from 1 choice
Jun 25 14:58:18 x200 kernel: [ 1820.558328] scsi5 : SCSI emulation for USB Mass Storage devices
Jun 25 14:58:18 x200 kernel: [ 1820.558830] usb-storage: device found at 5
Jun 25 14:58:18 x200 kernel: [ 1820.558835] usb-storage: waiting for device to settle before scanning
Jun 25 14:58:23 x200 kernel: [ 1825.556492] usb-storage: device scan complete
Jun 25 14:58:23 x200 kernel: [ 1825.557236] scsi 5:0:0:0: Direct-Access Ut165 USB2FlashStorage 0.00 PQ: 0 ANSI: 2
Jun 25 14:58:23 x200 kernel: [ 1825.559575] sd 5:0:0:0: Attached scsi generic sg1 type 0
Jun 25 14:58:23 x200 kernel: [ 1825.559903] sd 5:0:0:0: [sdb] 15794176 512-byte hardware sectors: (8.08 GB/7.53 GiB)
Jun 25 14:58:23 x200 kernel: [ 1825.561315] sd 5:0:0:0: [sdb] Write Protect is off
Jun 25 14:58:23 x200 kernel: [ 1825.561323] sd 5:0:0:0: [sdb] Mode Sense: 00 00 00 00
Jun 25 14:58:23 x200 kernel: [ 1825.561329] sd 5:0:0:0: [sdb] Assuming drive cache: write through
Jun 25 14:58:23 x200 kernel: [ 1825.569440] sd 5:0:0:0: [sdb] Assuming drive cache: write through
Jun 25 14:58:23 x200 kernel: [ 1825.569453] sdb: unknown partition table
Jun 25 14:58:23 x200 kernel: [ 1825.758141] sd 5:0:0:0: [sdb] Attached SCSI removable disk
Jun 25 15:13:58 x200 kernel: [ 2760.552137] INFO: task devkit-disks-da:4498 blocked for more than 120 seconds.
Jun 25 15:13:58 x200 kernel: [ 2760.552146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 25 15:13:58 x200 kernel: [ 2760.552153] devkit-disks- D 0000000100087de5 0 4498 4492
Jun 25 15:13:58 x200 kernel: [ 2760.552165] ffff8801300a7c58 0000000000000086 0000000000000001 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552175] ffff880126035d68 0000000000013000 0000000000013000 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552184] 0000000000013000 0000000000013000 ffff880126035d68 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552193] Call Trace:
Jun 25 15:13:58 x200 kernel: [ 2760.552213] [<ffffffff806da977>] __mutex_lock_slowpath+0xd7/0x160
Jun 25 15:13:58 x200 kernel: [ 2760.552225] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552233] [<ffffffff806da696>] mutex_lock+0x26/0x50
Jun 25 15:13:58 x200 kernel: [ 2760.552240] [<ffffffff80328858>] __blkdev_get+0x38/0x3a0
Jun 25 15:13:58 x200 kernel: [ 2760.552251] [<ffffffff80212bce>] ? apic_timer_interrupt+0xe/0x20
Jun 25 15:13:58 x200 kernel: [ 2760.552259] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552266] [<ffffffff80328bcb>] blkdev_get+0xb/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552273] [<ffffffff80328c3c>] blkdev_open+0x6c/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552283] [<ffffffff802fa066>] __dentry_open+0xe6/0x2e0
Jun 25 15:13:58 x200 kernel: [ 2760.552291] [<ffffffff802fa367>] nameidata_to_filp+0x57/0x70
Jun 25 15:13:58 x200 kernel: [ 2760.552301] [<ffffffff803093ba>] do_filp_open+0x28a/0x9c0
Jun 25 15:13:58 x200 kernel: [ 2760.552308] [<ffffffff8032797d>] ? bdput+0xd/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552316] [<ffffffff8032813e>] ? __blkdev_put+0x7e/0x1a0
Jun 25 15:13:58 x200 kernel: [ 2760.552323] [<ffffffff8032826b>] ? blkdev_put+0xb/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552333] [<ffffffff8043e452>] ? __strncpy_from_user+0x22/0x60
Jun 25 15:13:58 x200 kernel: [ 2760.552342] [<ffffffff80313a32>] ? alloc_fd+0x102/0x150
Jun 25 15:13:58 x200 kernel: [ 2760.552350] [<ffffffff802f9ea0>] do_sys_open+0x60/0xf0
Jun 25 15:13:58 x200 kernel: [ 2760.552358] [<ffffffff802f9f5b>] sys_open+0x1b/0x20
Jun 25 15:13:58 x200 kernel: [ 2760.552366] [<ffffffff80212042>] system_call_fastpath+0x16/0x1b
Jun 25 15:13:58 x200 kernel: [ 2760.552376] INFO: task hald-addon-stor:5375 blocked for more than 120 seconds.
Jun 25 15:13:58 x200 kernel: [ 2760.552381] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 25 15:13:58 x200 kernel: [ 2760.552387] hald-addon-st D 0000000100087de5 0 5375 3793
Jun 25 15:13:58 x200 kernel: [ 2760.552397] ffff88012a581c58 0000000000000082 0000000000000002 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552407] ffff8801390603a8 0000000000013000 0000000000013000 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552416] 0000000000013000 0000000000013000 ffff8801390603a8 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552425] Call Trace:
Jun 25 15:13:58 x200 kernel: [ 2760.552434] [<ffffffff806da977>] __mutex_lock_slowpath+0xd7/0x160
Jun 25 15:13:58 x200 kernel: [ 2760.552442] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552450] [<ffffffff806da696>] mutex_lock+0x26/0x50
Jun 25 15:13:58 x200 kernel: [ 2760.552457] [<ffffffff80328858>] __blkdev_get+0x38/0x3a0
Jun 25 15:13:58 x200 kernel: [ 2760.552464] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552472] [<ffffffff80328bcb>] blkdev_get+0xb/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552479] [<ffffffff80328c3c>] blkdev_open+0x6c/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552487] [<ffffffff802fa066>] __dentry_open+0xe6/0x2e0
Jun 25 15:13:58 x200 kernel: [ 2760.552495] [<ffffffff802fa367>] nameidata_to_filp+0x57/0x70
Jun 25 15:13:58 x200 kernel: [ 2760.552503] [<ffffffff803093ba>] do_filp_open+0x28a/0x9c0
Jun 25 15:13:58 x200 kernel: [ 2760.552510] [<ffffffff8032813e>] ? __blkdev_put+0x7e/0x1a0
Jun 25 15:13:58 x200 kernel: [ 2760.552518] [<ffffffff8032826b>] ? blkdev_put+0xb/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552526] [<ffffffff8043e452>] ? __strncpy_from_user+0x22/0x60
Jun 25 15:13:58 x200 kernel: [ 2760.552534] [<ffffffff80313a32>] ? alloc_fd+0x102/0x150
Jun 25 15:13:58 x200 kernel: [ 2760.552542] [<ffffffff802f9ea0>] do_sys_open+0x60/0xf0
Jun 25 15:13:58 x200 kernel: [ 2760.552550] [<ffffffff802f9f5b>] sys_open+0x1b/0x20
Jun 25 15:13:58 x200 kernel: [ 2760.552558] [<ffffffff80212042>] system_call_fastpath+0x16/0x1b
Jun 25 15:13:58 x200 kernel: [ 2760.552565] INFO: task blkid:5785 blocked for more than 120 seconds.
Jun 25 15:13:58 x200 kernel: [ 2760.552570] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 25 15:13:58 x200 kernel: [ 2760.552575] blkid D ffffffffffffffff 0 5785 1
Jun 25 15:13:58 x200 kernel: [ 2760.552586] ffff8800b2c93c58 0000000000000082 ffff8800b2c93e48 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552595] ffff88012608b088 0000000000013000 0000000000013000 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552604] 0000000000013000 0000000000013000 ffff88012608b088 0000000000013000
Jun 25 15:13:58 x200 kernel: [ 2760.552613] Call Trace:
Jun 25 15:13:58 x200 kernel: [ 2760.552622] [<ffffffff806da977>] __mutex_lock_slowpath+0xd7/0x160
Jun 25 15:13:58 x200 kernel: [ 2760.552630] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552639] [<ffffffff806da696>] mutex_lock+0x26/0x50
Jun 25 15:13:58 x200 kernel: [ 2760.552646] [<ffffffff80328858>] __blkdev_get+0x38/0x3a0
Jun 25 15:13:58 x200 kernel: [ 2760.552653] [<ffffffff80328bd0>] ? blkdev_open+0x0/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552660] [<ffffffff80328bcb>] blkdev_get+0xb/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552667] [<ffffffff80328c3c>] blkdev_open+0x6c/0xc0
Jun 25 15:13:58 x200 kernel: [ 2760.552675] [<ffffffff802fa066>] __dentry_open+0xe6/0x2e0
Jun 25 15:13:58 x200 kernel: [ 2760.552684] [<ffffffff802fa367>] nameidata_to_filp+0x57/0x70
Jun 25 15:13:58 x200 kernel: [ 2760.552692] [<ffffffff803093ba>] do_filp_open+0x28a/0x9c0
Jun 25 15:13:58 x200 kernel: [ 2760.552702] [<ffffffff8022f479>] ? default_spin_lock_flags+0x9/0x10
Jun 25 15:13:58 x200 kernel: [ 2760.552710] [<ffffffff8043e452>] ? __strncpy_from_user+0x22/0x60
Jun 25 15:13:58 x200 kernel: [ 2760.552718] [<ffffffff80313a32>] ? alloc_fd+0x102/0x150
Jun 25 15:13:58 x200 kernel: [ 2760.552726] [<ffffffff802f9ea0>] do_sys_open+0x60/0xf0
Jun 25 15:13:58 x200 kernel: [ 2760.552734] [<ffffffff802f9f5b>] sys_open+0x1b/0x20
Jun 25 15:13:58 x200 kernel: [ 2760.552742] [<ffffffff80212042>] system_call_fastpath+0x16/0x1b

ProblemType: Bug
Architecture: amd64
Date: Thu Jun 25 15:22:23 2009
DistroRelease: Ubuntu 9.10
HibernationDevice: RESUME=UUID=13321251-9192-4083-a9c0-580da4025a03
MachineType: LENOVO 7454CTO
Package: linux-image-2.6.30-10-generic 2.6.30-10.12
ProcCmdLine: root=UUID=f9297094-3bdd-47ab-bd51-f8b1c9388d21 ro quiet splash nomodeset
ProcEnviron:
LANG=en_US.UTF-8
SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.30-10.12-generic
RelatedPackageVersions: linux-backports-modules-2.6.30-10-generic N/A
SourcePackage: linux
Uname: Linux 2.6.30-10-generic x86_64
dmi.bios.date: 04/20/2009
dmi.bios.vendor: LENOVO
dmi.bios.version: 6DET51WW (3.01 )
dmi.board.name: 7454CTO
dmi.board.vendor: LENOVO
dmi.board.version: Not Available
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvr6DET51WW(3.01):bd04/20/2009:svnLENOVO:pn7454CTO:pvrThinkPadX200:rvnLENOVO:rn7454CTO:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 7454CTO
dmi.product.version: ThinkPad X200
dmi.sys.vendor: LENOVO

Tags:

Revision history for this message

Chris Cheney (ccheney) wrote on 2009-06-25:

BootDmesg.gz Edit (13.0 KiB, application/x-gzip)
CurrentDmesg.txt Edit (1.8 KiB, text/plain; charset="utf-8")
Dependencies.txt Edit (1.1 KiB, text/plain; charset="utf-8")
Lspci.txt Edit (13.7 KiB, text/plain; charset="utf-8")
Lsusb.txt Edit (689 bytes, text/plain; charset="utf-8")
ProcCpuinfo.txt Edit (1.5 KiB, text/plain; charset="utf-8")
ProcInterrupts.txt Edit (1.5 KiB, text/plain; charset="utf-8")
ProcModules.txt Edit (3.3 KiB, text/plain; charset="utf-8")
UdevDb.txt Edit (103.1 KiB, text/plain; charset="utf-8")
UdevLog.txt Edit (230.1 KiB, text/plain; charset="utf-8")

Revision history for this message

Chris Cheney (ccheney) wrote on 2009-06-25:

I tried http://kernel.ubuntu.com/~kernel-ppa/mainline/v2.6.31-rc1/linux-image-2.6.31-020631rc1-generic_2.6.31-020631rc1_amd64.deb as Leann Ogasawara suggested but the screen just went black during boot at the point where gdm should have loaded. I imagine its some sort of KMS issue with my system.

Revision history for this message

Leann Ogasawara (leannogasawara) wrote on 2009-06-25:

I pointed Chris to try the latest 2.6.31-rc1 kernel, but he said gdm fails to start with that kernel:

from #ubuntu-kernel
[14:14:18] <ccheney> ogasawara: i tried the 31 kernel and it wouldn't even boot into gdm for me
[14:14:36] <ccheney> ogasawara: it just went black after loading the kernel, i think at the point it tried to start gdm
[14:14:45] <ogasawara> ccheney: well that's no good
[14:14:57] <ccheney> ogasawara: i tried both with and without nomodeset option
[14:15:16] <ccheney> the current karmic kernel gets my resolution wrong so i use nomodeset on it

Changed in linux (Ubuntu):
importance:	Undecided → Medium
status:	New → Triaged

Revision history for this message

Chris Cheney (ccheney) wrote on 2009-07-13:

I reverted to jaunty due to other problems on karmic and noticed that this bug appears to not occur on jaunty.

date -R; time dd if=/dev/zero of=/dev/sdb bs=1M count=1024; date -R
Mon, 13 Jul 2009 14:48:35 -0500
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 103.843 s, 10.3 MB/s

real 1m43.852s
user 0m0.004s
sys 0m1.608s
Mon, 13 Jul 2009 14:50:18 -0500

uname -a
Linux x200 2.6.28-13-generic #45-Ubuntu SMP Tue Jun 30 22:12:12 UTC 2009 x86_64 GNU/Linux

Revision history for this message

Chris Cheney (ccheney) wrote on 2009-07-13:

Also (Not directly related to this bug) I have noticed that using cp even on the kernels that does work properly causes the copy to noticeably slow down. It takes > 36m to copy 3.2G (fat32) and only takes 7.25m using dd.

Revision history for this message

Pete Graner (pgraner) wrote on 2009-07-28:

I can confirm this is happening to me with 2.6.31-4 on Karmic. Here is a run of dd with and without dsync to a USB stick.

pgraner@desktop:~$ sudo dd if=/dev/zero of=/dev/sde1 bs=1M count=1024 oflag=dsync
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 71.9165 s, 14.9 MB/s

pgraner@desktop:~$ sudo dd if=/dev/zero of=/dev/sde1 bs=1M count=1024
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 584.309 s, 1.8 MB/s

Colin Ian King (colin-king) on 2010-01-11

Changed in linux (Ubuntu):
status:	Triaged → In Progress
assignee:	nobody → Colin King (colin-king)

Revision history for this message

Colin Ian King (colin-king) wrote on 2010-01-11:

@Pete, can't seem to reproduce this with my H/W. Can you:

1. Supply details about the laptop and the USB key you were using
2. See if you can reproduce this on the latest Lucid Alpha.

Colin

Revision history for this message

alex_b (barth-alexander) wrote on 2010-01-15:

I have the same problem with my HP 6930p (https://wiki.ubuntu.com/LaptopTestingTeam/HPCompaq6930p/Intel). My USB key is a 1GB Apacer key. The output of lsusb is:

Bus 002 Device 003: ID 1005:b113 Apacer Technology, Inc. Handy Steno 2.0/HT203

Revision history for this message

florin.balate (florin-balate) wrote on 2010-01-15:

Maybe this helps:
I read on some forum while I was searching for an answer about the slow write speed on my usb stick (transf speed dropped quickly from 20 MB/s to 100KB/s) that maybe kde is responsible for this. first I ignored this, but I have just tried it.

I logged out of my regular KDE session, logged in fluxbox, mounted stick by hand, since its not automounted, using only defaults options:
$mount -t ntfs-3g /dev/sdcX /mnt/stick
$mount
/dev/sdc1 on /mnt/stick type fuseblk (rw,nosuid,nodev,allow_other,blksize=4096)

Then I started copying my file ~4.4GB. speed stabilized at 13MB/s

The whole copy process would have taken about 5 minutes, if I hadn't changed the file manager to kde during the last 30 sec.
Guess what -> speed dropped , it is still copying ETA 25 sec