Bug 41472

Created attachment 69552 [details]
High I/O example

(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

On Sun, 21 Aug 2011 14:04:46 GMT
bugzilla-daemon@bugzilla.kernel.org wrote:

> https://bugzilla.kernel.org/show_bug.cgi?id=41472
> 
>            Summary: Slow files copying into a usb drive
>            Product: IO/Storage
>            Version: 2.5
>     Kernel Version: 3.0
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: Other
>         AssignedTo: io_other@kernel-bugs.osdl.org
>         ReportedBy: aheaven87@gmail.com
>         Regression: No
> 
> 
> Description:
> I am suffering from very slow files copying and it does not matter is it an
> usb
> 1 or 2 devise. I mean that it happens both with uhci and ehci (can not test
> xhci because haven't a usb 3.0 device). During files copying KDE notification
> show me the progress and all seems to be alright, but I can not umount the
> devise after the copy operation was finished (orienting by KDE's
> notifications). I always receive an error message that devise is busy, when
> trying to umount it. htop shows high I/O that you can see on the screenshot.
> It
> also does not matter was this device mounted by dolphin or by hand in
> console.
> Also, a few upgrades ago (perhaps with kernel 2.6.38) arch hung tightly
> during
> copying on usb drive and came to life after operations complete (or after
> hard
> devise disconnecting)
> 
> Additional info:
> I noticed it a long time ago, not sure in which kernel version. Already tried
> lts and 3.0 kernels. Now I trying with 2.6.39-ck and it also has the same
> problem.
> 
> Steps to reproduce:
> Just connect an usb devise and try to copy files on it. I tried it with my
> phone flash card and with different usb drives and it is reproducible with
> both
> small and big files.
> 
> Hardware:
> I have the Intel i7 processor and the Asus Sabertooth motherboard on the X58
> chipset.
> 
> Please tell me if I could provide some useful information.
> Bug report on bugs.archlinux.org with a few comments ___
> https://bugs.archlinux.org/task/25461

On Mon, 22 Aug 2011, Andrew Morton wrote:

> > https://bugzilla.kernel.org/show_bug.cgi?id=41472
> > 
> >            Summary: Slow files copying into a usb drive
> > 
> > Description:
> > I am suffering from very slow files copying and it does not matter is it an
> usb
> > 1 or 2 devise. I mean that it happens both with uhci and ehci (can not test
> > xhci because haven't a usb 3.0 device).

How slow do you mean by "very slow"?

> >  During files copying KDE notification
> > show me the progress and all seems to be alright, but I can not umount the
> > devise after the copy operation was finished (orienting by KDE's
> > notifications).

Were you copying files _from_ the device or _to_ the device?

Was the device mounted with the "-o sync" option?

> >  I always receive an error message that devise is busy, when
> > trying to umount it. htop shows high I/O that you can see on the
> screenshot. It
> > also does not matter was this device mounted by dolphin or by hand in
> console.
> > Also, a few upgrades ago (perhaps with kernel 2.6.38) arch hung tightly
> during
> > copying on usb drive and came to life after operations complete (or after
> hard
> > devise disconnecting)

Were there any error messages in the kernel log?

Alan Stern

> How slow do you mean by "very slow"?
12 mp3 files (87mb):
Copying _from_ 2m 50s
Copying _to_ 5m 30s + when all seems to be done I've tried to umount the device but high i/o appeared again and I have waited 1 minute more.

> Were you copying files _from_ the device or _to_ the device?
Seems that all okay when I copying files from the device, because it was my phone (full speed device), so speed was ≈ 500kb/s. At least I could see the operation progress. When I copying files back to the device I no see the progress, anything, only high i/o that you can see on the attached screenshot. But even this i/o doesn't appear immediately, should take about 30 seconds before it start.

> Was the device mounted with the "-o sync" option?
Tried to Mount it with "-o sync" and to copy the same files — now I can see the progress, but speed is ≈ 20-30kb/s. Remount without the sync option and have the same as with KDE's Dolpnin — mc progress window appeared on 1 second, already with 100% and disappeared. After 20-30 second high i/o in htop. All the same.

Kernel logs:
After plug in
usb 3-2: new full speed USB device number 5 using uhci_hcd
usb 3-2: USB disconnect, device number 5
usb 3-2: new full speed USB device number 6 using uhci_hcd
usbcore: registered new interface driver uas
Initializing USB Mass Storage driver...
scsi14 : usb-storage 3-2:2.0
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
scsi 14:0:0:0: Direct-Access     Sony Eri Memory Stick     0000 PQ: 0 ANSI: 0
sd 14:0:0:0: Attached scsi generic sg3 type 0
sd 14:0:0:0: [sdb] Attached SCSI removable disk
sd 14:0:0:0: [sdb] 487261 512-byte logical blocks: (249 MB/237 MiB)
sd 14:0:0:0: [sdb] Test WP failed, assume Write Enabled
sd 14:0:0:0: [sdb] Asking for cache data failed
sd 14:0:0:0: [sdb] Assuming drive cache: write through
sd 14:0:0:0: [sdb] Test WP failed, assume Write Enabled
sd 14:0:0:0: [sdb] Asking for cache data failed
sd 14:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sdb: p1 size 487261 extends beyond EOD, enabling native capacity
sd 14:0:0:0: [sdb] Test WP failed, assume Write Enabled
sd 14:0:0:0: [sdb] Asking for cache data failed
sd 14:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sdb: p1 size 487261 extends beyond EOD, truncated

Sometimes happens before disconnecting the device:
usb 3-2: USB disconnect, device number 9
sd 15:0:0:0: [sdb] Unhandled error code
sd 15:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x00
sd 15:0:0:0: [sdb] CDB: cdb[0]=0x28: 28 00 00 07 6e 80 00 00 08 00
end_request: I/O error, dev sdb, sector 487040
quiet_error: 14 callbacks suppressed
Buffer I/O error on device sdb, logical block 487040
Buffer I/O error on device sdb, logical block 487041
Buffer I/O error on device sdb, logical block 487042
Buffer I/O error on device sdb, logical block 487043
Buffer I/O error on device sdb, logical block 487044
Buffer I/O error on device sdb, logical block 487045
Buffer I/O error on device sdb, logical block 487046
Buffer I/O error on device sdb, logical block 487047
sdb: detected capacity change from 249477632 to 0

I also can reproduce this with ipod device.

Okay.  500 KB/s is a reasonable rate for a full-speed device.  Not great, but acceptable.  The 260 KB/s you got in the other direction is pretty bad.  I guess we can blame that on the phone, however.  As you found out, the "-o sync" option makes everything much worse -- that's why I asked about it.

What rates do you get when copying to and from a high-speed (USB-2.0) device, like a flash drive, using ehci-hcd?

Believe it or not, the pattern of I/O activity you observed is normal.  When copying data to the phone, Linux first buffers the data in the computer's memory.  You probably have lots of memory available, so that part of the copy is very quick and the progress window shows that it finishes quickly.  But then the actual data transfer from memory to the phone is much slower.  That explains the I/O load you saw after the progress window disappeared.

The umount command has to wait for the entire transfer to complete; that's why it takes so long.  And those error messages you got when you unplugged the device indicate that a READ operation was in progress at the time -- of course it failed once the plug was pulled.

> What rates do you get when copying to and from a high-speed (USB-2.0) device,
like a flash drive, using ehci-hcd?
When copying from the device, KDE shows ≈ 7Mb(not MB)/s and about 50Mb/s when copying to the devise. So 700 megabytes folder was copied to the device in seconds, but then progress notification disappeared and still high I/O in htop for a few minutes. But agree, it was about 10 times faster, because it took ≈ the same time as I needed to copy 80Mb on full-speed device.

Seems that the operation progress is completely wrong because of: "Linux first buffers the data in the computer's memory.  You probably have lots of memory available, so that part of the copy is very quick and the progress window shows that it finishes quickly." and progress window show the speed which data is copied into the RAM instead (and 50Mb/s it is my HDD read/write limitation, this is why it's not faster), what is absolutely incorrect. I think it still should display the actual data transfer progress.

Also, when I tried to copy a few folders with many small files it fail, when tried to copy a single big file (about 1.2Gb) it fail too. In all cases I get I/O error 5.
dmesg:
 8043.150163] hub 5-0:1.0: unable to enumerate USB device on port 1
[ 8048.730065] usb 3-1: new high speed USB device number 26 using ehci_hcd
[ 8048.854765] scsi24 : usb-storage 3-1:1.0
[ 8049.853150] scsi 24:0:0:0: Direct-Access     FLY E170  FLASH DISK      6235 PQ: 0 ANSI: 0 CCS
[ 8049.854025] sd 24:0:0:0: Attached scsi generic sg3 type 0
[ 8049.854210] sd 24:0:0:0: [sdb] 7744512 512-byte logical blocks: (3.96 GB/3.69 GiB)
[ 8049.854582] scsi 24:0:0:1: Direct-Access     FLY E170  FLASH DISK      6235 PQ: 0 ANSI: 0 CCS
[ 8049.854876] sd 24:0:0:1: Attached scsi generic sg4 type 0
[ 8049.855118] sd 24:0:0:0: [sdb] Write Protect is off
[ 8049.855120] sd 24:0:0:0: [sdb] Mode Sense: 03 00 00 00
[ 8049.855883] sd 24:0:0:0: [sdb] No Caching mode page present
[ 8049.855887] sd 24:0:0:0: [sdb] Assuming drive cache: write through
[ 8049.856266] sd 24:0:0:1: [sdc] 50000 512-byte logical blocks: (25.6 MB/24.4 MiB)
[ 8049.856989] sd 24:0:0:1: [sdc] Write Protect is off
[ 8049.856992] sd 24:0:0:1: [sdc] Mode Sense: 03 00 00 00
[ 8049.857740] sd 24:0:0:1: [sdc] No Caching mode page present
[ 8049.857742] sd 24:0:0:1: [sdc] Assuming drive cache: write through
[ 8049.859735] sd 24:0:0:0: [sdb] No Caching mode page present
[ 8049.859737] sd 24:0:0:0: [sdb] Assuming drive cache: write through
[ 8049.862285]  sdb: sdb1
[ 8049.863677] sd 24:0:0:1: [sdc] No Caching mode page present
[ 8049.863681] sd 24:0:0:1: [sdc] Assuming drive cache: write through
[ 8049.867710]  sdc:
[ 8049.870076] sd 24:0:0:0: [sdb] No Caching mode page present
[ 8049.870079] sd 24:0:0:0: [sdb] Assuming drive cache: write through
[ 8049.870082] sd 24:0:0:0: [sdb] Attached SCSI removable disk
[ 8049.871985] sd 24:0:0:1: [sdc] No Caching mode page present
[ 8049.871987] sd 24:0:0:1: [sdc] Assuming drive cache: write through
[ 8049.871989] sd 24:0:0:1: [sdc] Attached SCSI removable disk
[ 8246.681313] sd 24:0:0:0: [sdb] Unhandled sense code
[ 8246.681318] sd 24:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x08
[ 8246.681322] sd 24:0:0:0: [sdb]  Sense Key : 0x4 [current] 
[ 8246.681326] sd 24:0:0:0: [sdb]  ASC=0x0 ASCQ=0x0
[ 8246.681330] sd 24:0:0:0: [sdb] CDB: cdb[0]=0x2a: 2a 00 00 00 c0 00 00 00 10 00
[ 8246.681339] end_request: I/O error, dev sdb, sector 49152
[ 8246.686399] sd 24:0:0:0: [sdb] Unhandled sense code
[ 8246.686403] sd 24:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x08
[ 8246.686406] sd 24:0:0:0: [sdb]  Sense Key : 0x4 [current] 
[ 8246.686410] sd 24:0:0:0: [sdb]  ASC=0x0 ASCQ=0x0
[ 8246.686413] sd 24:0:0:0: [sdb] CDB: cdb[0]=0x2a: 2a 00 00 00 5c 78 00 00 01 00
[ 8246.686422] end_request: I/O error, dev sdb, sector 23672
[ 8246.686425] quiet_error: 837 callbacks suppressed
[ 8246.686428] Buffer I/O error on device sdb1, logical block 15480
[ 8246.686430] lost page write due to I/O error on sdb1
[ 8257.176393] sd 24:0:0:0: [sdb] Unhandled sense code
[ 8257.176398] sd 24:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x08
[ 8257.176402] sd 24:0:0:0: [sdb]  Sense Key : 0x4 [current] 
[ 8257.176407] sd 24:0:0:0: [sdb]  ASC=0x0 ASCQ=0x0
[ 8257.176410] sd 24:0:0:0: [sdb] CDB: cdb[0]=0x28: 28 00 00 00 5c 78 00 00 01 00
[ 8257.176419] end_request: I/O error, dev sdb, sector 23672
[ 8257.176493] FAT-fs (sdb1): unable to read inode block for updating (i_pos 247684)
[ 8272.167888] sd 24:0:0:0: [sdb] Unhandled sense code
[ 8272.167893] sd 24:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x08
[ 8272.167897] sd 24:0:0:0: [sdb]  Sense Key : 0x4 [current] 
[ 8272.167901] sd 24:0:0:0: [sdb]  ASC=0x0 ASCQ=0x0
[ 8272.167905] sd 24:0:0:0: [sdb] CDB: cdb[0]=0x2a: 2a 00 00 00 5c 80 00 00 01 00
[ 8272.167913] end_request: I/O error, dev sdb, sector 23680
[ 8272.167918] Buffer I/O error on device sdb1, logical block 15488
[ 8272.167921] lost page write due to I/O error on sdb1
[ 8272.172603] sd 24:0:0:0: [sdb] Unhandled sense code
[ 8272.172606] sd 24:0:0:0: [sdb]  Result: hostbyte=0x07 driverbyte=0x08
[ 8272.172610] sd 24:0:0:0: [sdb]  Sense Key : 0x4 [current] 
[ 8272.172614] sd 24:0:0:0: [sdb]  ASC=0x0 ASCQ=0x0
[ 8272.172617] sd 24:0:0:0: [sdb] CDB: cdb[0]=0x2a: 2a 00 00 00 20 01 00 00 01 00
[ 8272.172625] end_request: I/O error, dev sdb, sector 8193
[ 8272.172627] Buffer I/O error on device sdb1, logical block 1
[ 8272.172628] lost page write due to I/O error on sdb1

Re-mounted the device under win7 (vmware) and copied the same folder with small files and operation succeed on about 1.2Mb/s. Tried to copy the same big file and it succeed too on the same 1.2-1.4Mb/s.

When I re-mounted the device back to the Linux and tried to copy the same file — it fail again. Retrying and now see the KDE's "fast" notification about 50Mb/s. After 1 gigabyte was transferred speed decreases to 2Ms/s (I assume now it display the real transfer speed) and after a while (when the remain 200 megabytes was transferred too) notification disappears and again only high I/O in htop tells that something going on. Finally the file was copied in about the same time as it was taken in win7 (≈ 10 minutes), BUT during this operation my system hung a few times. Also after operation was completed (I guess that) I could not delete these files because of the same errors in dmesg. Trying to umount it — ok, try to mount it back — got this error:
[11255.875793] FAT-fs (sdb1): unable to read boot sector

So I was forced to unplug and then plug the device back. Only then I could remove files but with this errors in dmesg:
[11496.180098] FAT-fs (sdb1): error, fat_free_clusters: deleting FAT entry beyond EOF
[11496.180102] FAT-fs (sdb1): Filesystem has been set read-only

High speed should be more like 40 times faster than full speed, not 10 times.

Yes, the information displayed in the progress window is off.  This really isn't a kernel problem so much as a problem in KDE.

It's hard to tell exactly what went wrong during your file copies.  Clearly the device itself is buggy.  You could try using a different brand of flash drive.

Some of the problems you described might go away if you repartition and reformat the flash drive.  Using fdisk or the equivalent, erase the existing partition and create a new one.  Then use mkdosfs to create a filesystem on the new partition.

> High speed should be more like 40 times faster than full speed, not 10 times.
When I tried different devices it was not much faster, but I agree that it is rather due to the device limitations.

> Yes, the information displayed in the progress window is off.  This really
> isn't a kernel problem so much as a problem in KDE.
Okay, thank for your patience, I will send a bug report about wrong copying progress to the KDE team. With a working progress I, at least, will know, when copying operations will completed :)

> It's hard to tell exactly what went wrong during your file copies.  Clearly
> the device itself is buggy.  You could try using a different brand of flash
> drive.
I already tried different flash drives and agree that the last problems I have described is only related to this device, so it really could be broken.

> Some of the problems you described might go away if you repartition and
> reformat the flash drive.
Tried to recreate all the partition using gparted but still to copy my files backup back to the device I need to run win7...

Thank you.

It may be that this device requires some particular quirk to be set, although it's hard to say which one.  What does "lsusb -v" show with this FLY E170 flash drive plugged in?

This device is a phone with 4Gb of flash memory.

Bus 001 Device 003: ID 0e8d:0002 MediaTek Inc. 
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x0e8d MediaTek Inc.
  idProduct          0x0002 
  bcdDevice            1.00
  iManufacturer           2 FLY E170    
  iProduct                3 FLY E170
  iSerial                 4 535319403434320
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           32
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk (Zip)
      iInterface              1 FLY E170Stora
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  bNumConfigurations      1
Device Status:     0x0000
  (Bus Powered)

I tried to use usb 3.0 with xhci_hcd and behavior was the same. Strange thing is that it takes from 30 seconds to 1 minute before start (before I can see i/o in htop). Also now I wait a bit longer and did not tried to umount the device, as result, when operation was completed dolphin show empty window, but also it show that something has taken some place on the device (what is ≈ to the copied files size).

I also noticed that sometimes this device fail in win7 too, but works then, after formatting, what does not help in linux. Never mind, think this is a bad device and I should try with something of better quality.

I was going to suggest you add a module parameter for the usb-storage module:

   modprobe usb-storage quirks=e8d:2:m

This will cause usb-storage to use smaller data transfers when communicating with the phone, which might prevent the errors you've been seeing.

But you're right; for testing you should use a more reliable device.

Hello. Sorry for asking about it here as it is not related to the report, but I've created a bug report on bugs.kde.org about wrong copying progress and kde devs asked me about "a POSIX interface way to tell us when and how fast this buffered data is actually written to the disk, without causing massive slow downs that any "sync" type calls would cause?"

As far as I understood, to display correct progress, device should be mounted with the sync option but that would cause significant slowdown (what I described in the comment #4). Is there any other way to show the correct operation progress in linux?

Best,
Alex.

I don't know of any other way.

Hi Alan, thanks for your answers in email, seems like all my problems is completely related to the low devises quality. I have tried with more reliable ones and everything seems to be ok. Progress is still wrong but copying was finished very fast.

But there is still one moment I want to clarify. After I pasted files to the flash drive copying starts after delay in 30-50 seconds. It happens every time and even if files are very small so very often this is hard to understand if the copying has finished or not yet started. Is there any way to debug this?