Re: Slow I/O on USB media after commit f664a3cc17b7d0a2bc3b3ab96181e1029b0ec0e6

Andrea Vai
2019-08-23T10:40:09Z

[-- Attachment #1: Type: text/plain, Size: 4851 bytes --]

Il giorno mar, 20/08/2019 alle 13.13 -0400, Alan Stern ha scritto:
> On Mon, 19 Aug 2019, Andrea Vai wrote:
>
> > Hi Alan,
> > I attach the two traces, collected as follows:
> >
> > - start the trace;
> > - wait 10 seconds;
> > - plug the drive;
> > - wait 5 seconds;
> > - mount the drive;
> > - wait 5 seconds;
> > - copy a 500 byte file;
> > - wait 5 seconds;
> > - unmount the drive;
> > - wait 5 seconds;
> > - stop the trace.
>
> Still no noticeable differences between the two traces. They both
> include a 1.2 second delay shortly after the writing starts, and
> the
> initialization sequences are the same.
>
> I really don't know where to look for this. The only thing I can
> think
> of at this point is to repeat this test, but using a file large
> enough
> for the difference in writing speed to show up plainly.
>
> By the way, it would be best to run the tests with the smallest
> possible number of other USB devices plugged in. None at all, if
> you
> can arrange it.

Thanks, I went some steps further on this.
The following considerations all apply to the "bad" kernel.

Increasing the filesize lead me to find out that using a file sized
less than roughly 10MB the problem does not happen.

I found these results by making sets of 10 tries for each filesize,
using a filesize of 1kB, 10kB, 100kB, 1MB, 10MB, 100MB, 500MB (so, we
have 70 usbmon logs on these). If we define "fast" a copy that takes
(roughly(*)) no more time to complete than all the other tries in its
set, and "slow" elsewhere (=one or more tries in its set are
(sensibly(*)) faster), I noticed that in each set with a filesize of
10MB or more the behavior can be very different: sometimes the copy is
still "fast", sometimes is "slow". The frequency of the "slow" copies
increases with the filesize. Also, among the "slow" copies in a set,
the time can be very different.

Also, I found that if the file is not present on the target location
(i.e. the USB pendrive), the problem does not happen (I have ten
usbmon logs here, taken in the worst scenario (500MB filesize)).

Tell me which log(s) would you like me to send you: I can sum up here
all the sets of tries, and the time their copies took to complete (in
seconds):

1kB: 26, 27, 26, 26, 27, 26, 26, 27, 26, 27
10kB: 27, 27, 26, 26, 27, 26, 27, 26, 27, 27
100kB: 26, 26, 26, 27, 26, 26, 26, 27, 27, 27
1MB: 26, 27, 27, 27, 27, 27, 27, 27, 27, 26
10MB: 27, 31, 37, 27, 38, 27, 39, 27, 30, 28
100MB: 32, 32, 144, 32, 145, 32, 123, 32, 153, 123
500MB: 56, 1396, 747, 131, 795, 764, 292, 1021, 807, 516

Also, note that the first copy is always "fast", because each file was
initially not present on the pendrive. As said, I did one test of 10
tries by deleting the file on the pendrive before copying it again,
and the results are

500MB: 56, 56, 57, 57, 56, 56, 60, 25***, 55, 56 (***Note the "fake"
25s, doesn't matter because I forgot to plug the pendrive :-/ )

I have made a script to semi-automate all the tests I have done. I
attach the script here, so anyone interested could check it for any
mistake (remember I am not very skilled so I may have wrote buggy
code, done wrong assumptions, etc.). Please note that I decreased the
time between the trace start and the drive plugging from 10s to 5s
(simply to reduce the time needed to me to look at the countdown). Of
course I can do again the test(s) you need with a bigger amount of
$wait.

The script has been run with the command

# for k in {1..10}; do size=1000; ./test_usbmon $size && ping -a -c 5 8.8.8.8 ; done
(example for 1kB filesize)

or, in the set of "delete before copy",

# for k in {1..10}; do size=500000000; ./cancellaTestFile $size && ./test_usbmon $size && ping -a -c 5 8.8.8.8 ; done

The ping command is there just to have a sound alarm when finished.

I also attach the script to delete the file ("cancellaTestFile").

I took care to plug the pendrive exactly at the end of the countdown,
to keep the times in the logs more simple to detect and manage by you.

I have also logged all the terminal output log of the script.

Last note: I ran all the tests without any other USB device connected
but the pendrive (well, actually there is a card reader connected to
the internal USB connector, but on another bus. I didn't want to open
the case and disconnect it but of course I can do it if needed).
Thanks for pointing it out.

Thanks, and bye
Andrea

(*) as an example, on a set that shows the total elapsed time in
seconds being

26, 27, 27, 27, 27, 27, 27, 27, 27, 26

I have assumed all of the copies to be "fast", while in the set

32, 32, 144, 32, 145, 32, 123, 32, 153, 123

I have assumed 5 of the copies as "fast" (the ones that took 32
seconds) and the other "slow". Not going to deepen in some standard
deviation evaluation, etc., but if you'd like to I can provide some
more scientific detailed data :-)

[-- Attachment #2: test_usbmon --]
[-- Type: application/x-shellscript, Size: 1607 bytes --]

[-- Attachment #3: cancellaTestFile --]
[-- Type: application/x-shellscript, Size: 296 bytes --]