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

[Andrea Vai <andrea.vai@unipv.it>]

Il giorno lun 26 ago 2019 alle ore 18:33 Alan Stern <
stern@rowland.harvard.edu> ha scritto:
> [...]
> In fact, even the traces where the file doesn't exist beforehand
> show 
> some delays.  Just not as many delays as the traces where the file
> does 
> exist.  And again, each delay is in the middle of a write command,
> not 
> between commands.
> 
> I suppose changes to the upper software layers could affect which
> blocks are assigned when a new file is written.  Perhaps one kernel
> re-uses the same old blocks that had been previously occupied and
> the
> other kernel allocates a completely new set of blocks.  That might
> change the drive's behavior.  The quick way to tell is to record two
> usbmon traces, one under the "good" kernel and one under the "bad"  
> kernel, where each test involves writing over a file that already
> exists (say, 50 MB) -- the same file for both tests.  The block
> numbers
> will appear in the traces.

ok, I performed 10 tests for each kernel, so we have 20 traces.
 
> Also, I wonder if the changing the size of the data transfers would
> make any difference.  This is easy to try; just write "64" to
> /sys/block/sd?/queue/max_sectors_kb (where the ? is the appropriate
> drive letter) after the drive is plugged in but before the test
> starts.

ok, so I duplicated the tests above for the "64" case (it was
initially set as "120", if it is relevant to know), leading to 40 tests named as

bad.mon.out_50000000_64_TIMESTAMP
bad.mon.out_50000000_non64_TIMESTAMP
good.mon.out_50000000_64_TIMESTAMP
good.mon.out_50000000_non64_TIMESTAMP

where "64" denotes the ones done with that value in max_sectors_kb,
and "not64" the ones without it (as far as I can tell, it has been
always "120").

So, we have 40 traces total. Each set of 10 trials is identified by
a text file, which contains the output log of the test script (and the
timestamps), also available in the download zipfile.

Just to summarize here the times, they are respectively (number
expressed  in seconds):

BAD:
  Logs: log_10trials_50MB_BAD_NonCanc_64.txt,
log_10trials_50MB_BAD_NonCanc_non64.txt
  64: 34, 34, 35, 39, 37, 32, 42, 44, 43, 40
  not64: 61, 71, 59, 71, 62, 75, 62, 70, 62, 68
GOOD:
  Logs: log_10trials_50MB_GOOD_NonCanc_64.txt,
log_10trials_50MB_GOOD_NonCanc_non64.txt
  64: 34, 32, 35, 34, 35, 33, 34, 33, 33, 33
  not64: 32, 30, 32, 31, 31, 30, 32, 30, 32, 31

Finally, one note about the workaround proposed by Alan, "delete the
file before copying". My original problem occurred while using a
backup software (dar - see http://dar.linux.free.fr/). So, I tried now
to do the backup by deleting the existing file beforehand, and it
still takes a lot of time with bad kernel: a 900 file backup takes
~160sec with GOOD kernel, and >40min with BAD kernel. I also tried the
"64" tweak in the BAD kernel and it becomes ~300s. Then, I also tried
the "64" case with good kernel, and became ~140s. Detailed data:

GOOD (not "64): 155s, 151s
GOOD ("64"): 142s, 141s

BAD (not "64"): 47minutes, 43minutes
BAD ("64"): 315s, 288s, 268s, 239s, 302s

The command ran is:
$ SECONDS=0; rm /run/media/andrea/BAK_ANDVAI/aero.1.dar && dar -c /run/media/andrea/BAK_ANDVAI/aero -R /home/andrea/Musica/MP3/Aerosmith && umount /run/media/andrea/BAK_ANDVAI; echo "Ci ho messo: $SECONDS secondi."

Speculations:
- It seems the "64" value plays a role, more evident on "bad" kernels
(~halves the time) and less (but still existing?) on "good" kernels;
- dar with the bad kernel, with the "delete beforehand" action, is
still an order of magnitude slower than with the good kernel (so, it
behaves the same way as in the "overwrite" case). Maybe it depends on
the way dar itself writes data... I don't know if you can understand
it, or we should ask for a light to the dar developer(s) about it.

You can grab the traces at

http://fisica.unipv.it/transfer/usbmon_logs_2.zip

Thanks, and bye
Andrea