Re: dar became very slow (and process in D state?)

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

On 21/05/2019 16:11, Andrea Vai wrote:
> Il giorno sab, 18/05/2019 alle 12.23 +0200, Denis Corbin ha
> scritto:

[...]

>> message shows, which is the last message you get before the
>> problem arise, correct?
> 
> well, if we assume that the problem itself is that dar takes
> longer than usual to complete, then what I see is that the complete
> output
> 

[...]

> Writing down archive trailer... Writing down the second archive
> terminator... Closing archive low layer... ---------------FIRST
> PART END-------------------------
> 
> , then a lot of time passes, and then a second part shows:
> 
> ---------------SECOND PART BEGIN----------------------- Archive is
> closed.
> 

[...]

> 
> ...so I would say the answer to your last question is "no, not 
> correct", because the last message I get before the "problem"
> arises is "Closing archive low layer...". (I don't know for sure if
> the time needed to reach the "Closing archive low layer" message is
> more than usual, doesn't seem so, but I can try to see and tell you
> if you think it matters).

OK, this is completely different from what I had figured out. At that
time, dar closes the last layers of the internal stack, which may
contains some pending data to be written (cache) so there should be
some write() system call followed by a close() on the slice file
descriptor.... rawly the same as what 'cp' does, at the difference
that cp does also some read() concurrently while here all read() have
already been made.

(more details on internal stack and structure at
  http://dar.linux.free.fr/doc/Notes.html#archive_structure )


> 
> 
> 
>> 
>> [...]
>> 
>> Just a question, when dar is running, do you see it making the 
>> system swapping? (you check that using "vmstat 60" for example).
> 
> no, vmstat shows si/so=0/0 all the time

OK, this makes sense now, the 'D' state is not due to memory being
release and I/O problem, but is due to disk write() and close().

> 
>> 
>>> 
>>> So, I think we can say it's a kernel problem, and I would
>>> report a bug or something to the correct bug tracker/mailing
>>> list (which
>> one
>>> is the correct one?), but I'd like to have an advice from you
>> about
>>> it (and, of course, your corrections if I am wrong in some 
>>> conclusions).
>> 
>> it seems probable yes... I would fill a support request against
>> your disto maintainer... maybe someone in the list has a better
>> idea?
> 
> In the meantime, if anyone is interested, I have issued a request
> at
> 
> https://ask.fedoraproject.org/t/slow-i-o-kernel-5-bug-on-usb-media/151
8
>
> 
Excellent ;-)

>> 
>>> 
>>> As a side note, I also tried to copy a file to the pendrive
>>> and the behaviour is similar: we have a factor of 5 between
>>> copying a 1.1 GB file from the internal SATA HD to the
>>> pendrive, using the working kernel vs. the faulty one.
>> 
>> OK, so I understand that the simple 'cp' command also suffers
>> from some important execution time difference, but much less than
>> dar, correct?
> 
> Yes, I have just made other tests and it results that dar is
> roughly 20 times slower with kernel 5.0.1 vs k-4.20; while "cp" is
> about 10 times slower. (Average data calculated on 10-15 single
> operations).

OK, as this is not dar specific and as this is kernel dependent, at
this stage of investigation we will wait for the feedback from kernel
side, though, this thread is not closed...

> 
> Thank you, and bye Andrea
> 

Best Regards,
Denis
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEOzEprx3d76WjfYGPCDGwvQPYsYIFAlzkLIgACgkQCDGwvQPY
sYIB+xAAls4wbblQwbsa25xbM8TfHbV+duTbdzFQA4IsBMuUJ8dAw2dohU+vRYQr
jjGEtWV/kVgjj/LEMbYO3o6NpUoIFbcMLhsGWXJxYwyfB/PedqkDXxU+aEzEoGTD
6C3wc0xcURoe6c2g4nBSrU1FT1bdKpTgZLyWOZBoUjDAw5kNpZMrGJcLnMPIPJlW
Cf2UudEIH1RHR5yHvwUq+ftUjt/tY/zPgZ7Kmyy891DklhCIx+k3D5sDbpwjkpMZ
q+IRJnrSmSKyxfCkVU/M3z6Rox3HDcb1PM+K7hiU1oV6cISbQsbuDtaw5oNwutfq
lGIDERam7Uxc/l4xexPbGvJ35E1FCSnvE/uG8t6EfPh6+UayUa/B56kvk3KKDu55
fFZMI3uONFVglxMitQKbEPnFaozi+8jHOh/wmx2fnnmGRWIZaRi5qx9dX5ICiVli
5vIu7pQustsWDOzFz4XBhORrFO5hrPkUmMYuMTgLDYFga/RZ4W/qgCDSYW6q7T9J
PWzunabVehA47ROn5DhToxXlIjTcKqTYrsiAhkOFDo2EWd6EAp4ky/bquOzfdmIZ
tAkj6ztBz9eh7G2jh9hhN+CHOsaMqlIX9QFNrbtKPNzyMdDInzUqBa2sOb3OSvKm
SoBZwobfj9fCQkwT6ww1hOeIsivhKRF9L1EMRGUmeetmRuqjlWg=
=DUe8
-----END PGP SIGNATURE-----