[Sorry, I had previously sent the message to the list but has been
rejected. Sorry for any duplicate]
Il giorno ven, 23/08/2019 alle 16.42 -0400, Alan Stern ha scritto:
> On Fri, 23 Aug 2019, Andrea Vai wrote:
>
> > 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 :-)
>
> Wow, that sounds like a lot of work.
just a drop in the ocean, compared to yours :-)
> Let's start with the 39-second run for the 10-MB file. If you can
> put
> the trace files on a server somewhere, available for downloading,
> that
> would avoid sending a lot of uninteresting data to the mailing list.
ok, so you can grab them at
http://fisica.unipv.it/transfer/usbmon_logs.zip
(they will be automatically removed from there in a couple of weeks).
For each size there is a .txt file (which contains the terminal
output) and 10 bad.mon.out_.... trace files. The file suffix "NonCanc"
means there has not been file deletion before copy; while "Canc" means
the opposite.
Each trace file name is identified by a timestamp that is also
referenced inside the txt, so if you want to get i.e. the 39-sec trial
for the 10MB filesize you have to open the ...10MB....txt, search for
the 39 seconds total time string ("Dopo stop trace: 39"), look at the
beginning of that trial, a dozen rows before, take note of the
timestamp, and open the corresponding bad.mon.out file (of course, if
there are more trials with the same time, you have to identify it by
counting its position (7th in the example above)).
To make it more simple:
$ seconds=39; size=10MB; grep -B14 "Dopo stop trace: $seconds" log_10trials_"$size"_NonCanc.txt
should show you more straightly the part(s) you need.
> Odd that the delays never occur when you're writing a new file. (If
> nothing else, that gives you a way to work around the problem!)
Thank you, didn't realize that :-) I will try it.
Thanks, and bye
Andrea
--
Andrea Vai
University of Pavia
Department of Physics
Via Bassi, 6
27100 Pavia PV
Tel. +39 0382 987489
Mob. +39 328 3354086
http://fisica.unipv.it
http://www.andreavai.it
