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

Il giorno sab, 18/05/2019 alle 12.23 +0200, Denis Corbin ha scritto:
> On 16/05/2019 13:00, Andrea Vai wrote:
> > I haven't checked the RAM yet, but going to do it in the next    
> > night. (I think it's the only test I still have to do, see below).
> 
> this is not likely to be the cause of the problem...

indeed it isn't, as the RAM check gave no errors in many running hours

> [...]
> 
> 
> 
> if you have the opportunity to test the behavior of dar 2.5.x for
> curiosity 

well, I may be missing something but actually I made all tests using
dar 2.5.3, as you can see from the output of "dar -V" in my first
message, which I replicate here:

 dar version 2.5.3, Copyright (C) 2002-2052 Denis Corbin
   Long options support       : YES

 Using libdar 5.7.3 built with compilation time options:
   Libz compression (gzip)      : NO
   Libbz2 compression (bzip2)   : NO
   Liblzo2 compression (lzo)    : NO
   Liblzma compression (xz)     : NO
   Strong encryption (libgcrypt): NO
   Public key ciphers (gpgme)   : NO
   Extended Attributes support  : NO
   Large files support (> 2GB)  : YES
   ext2fs NODUMP flag support   : NO
   Special allocation scheme    : YES
   Integer size used            : 64 bits
   Thread safe support          : YES
   Furtive read mode support    : YES
   Linux ext2/3/4 FSA support   : NO
   Mac OS X HFS+ FSA support    : NO
   Detected system/CPU endian   : little
   Posix fadvise support        : YES
   Large dir. speed optimi.     : YES
   Timestamp read accuracy      : 1 microsecond
   Timestamp write accuracy     : 1 microsecond
   Restores dates of symlinks   : YES

 compiled the Apr 27 2016 with GNUC version 5.3.1 20160406 (Red Hat
5.3.1-6)
 dar is part of the Disk ARchive suite (Release 2.5.3)
 dar comes with ABSOLUTELY NO WARRANTY; for details
 type `dar -W'. This is free software, and you are welcome
 to redistribute it under certain conditions; type `dar -L | more'
 for details.



> > [...]
> > 
> > When process is in D state, I see (iotop) some increased I/O 
> > operation, which stops when the process terminates.
> 
> strace with dar 2.6.3 provides the following information about the
> system calls issued by dar/libdar after the "Final memory
> cleanup..."
> 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

---------------COMPLETE OUTPUT BEGIN------------------
Arguments read from /usr/local/etc/darrc :

Furtive read mode has been disabled as dar has not the FOWNER
capability nor is running as root
Creating low layer: Writing archive into a plain file object...
Writing down the archive header...
Adding a new layer on top: Caching layer for better performances...
Adding a new layer on top: Escape layer to allow sequential reading...
All layers have been created successfully
Building the catalog object...
Processing files for backup...
Adding file to archive: /NoBackup/buttare/ubuntu-14.04.5-desktop-
i386.iso
Writing down archive contents...
Closing the escape layer...
Writing down the first archive terminator...
Writing down archive trailer...
Writing down the second archive terminator...
Closing archive low layer...
Archive is closed.


 --------------------------------------------
 1 inode(s) saved
   including 0 hard link(s) treated
 0 inode(s) changed at the moment of the backup and could not be saved
properly
 0 byte(s) have been wasted in the archive to resave changing files
 0 inode(s) not saved (no inode/file change)
 0 inode(s) failed to be saved (filesystem error)
 0 inode(s) ignored (excluded by filters)
 0 inode(s) recorded as deleted from reference backup
 --------------------------------------------
 Total number of inode(s) considered: 1
 FSA saved for 0 inode(s)
 --------------------------------------------
Making room in memory (releasing memory used by archive of
reference)...
Final memory cleanup...
---------------COMPLETE OUTPUT END--------------------

can be split in two parts: a first part, which shows more or less
immediately

---------------FIRST PART BEGIN-------------------------
Arguments read from /usr/local/etc/darrc :

Furtive read mode has been disabled as dar has not the FOWNER
capability nor is running as root
Creating low layer: Writing archive into a plain file object...
Writing down the archive header...
Adding a new layer on top: Caching layer for better performances...
Adding a new layer on top: Escape layer to allow sequential reading...
All layers have been created successfully
Building the catalog object...
Processing files for backup...
Adding file to archive: /NoBackup/buttare/ubuntu-14.04.5-desktop-
i386.iso
Writing down archive contents...
Closing the escape layer...
Writing down the first archive terminator...
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.


 --------------------------------------------
 1 inode(s) saved
   including 0 hard link(s) treated
 0 inode(s) changed at the moment of the backup and could not be saved
properly
 0 byte(s) have been wasted in the archive to resave changing files
 0 inode(s) not saved (no inode/file change)
 0 inode(s) failed to be saved (filesystem error)
 0 inode(s) ignored (excluded by filters)
 0 inode(s) recorded as deleted from reference backup
 --------------------------------------------
 Total number of inode(s) considered: 1
 FSA saved for 0 inode(s)
 --------------------------------------------
Making room in memory (releasing memory used by archive of
reference)...
Final memory cleanup...
---------------SECOND PART END-------------------------

...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).



> 
> [...]
> 
> 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

> 
> > 
> > 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/1518

> 
> > 
> > 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).

Thank you, and bye
Andrea