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

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

On 16/05/2019 13:00, Andrea Vai wrote:
> Il giorno gio, 09/05/2019 alle 11.23 +0200, Denis Corbin ha
> scritto:
>> 
>> [...]
>> 
>> Hello Andrea,
> 
> Hi Neil, Denis and all, first of all, thank you for your detailed
> explanations help.
> 
>> 

[...]

> 
> I haven't check 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...

> 
>> 

[...]

> 
> I re-created the swap, and the problem still happens. I also tried
> to connect the pendrive directly to a USB port connected directly
> to the mainboard, and the problem still happens.

OK

> 
> Then I installed and tested many kernels and found that problem 
> doesn't happen with kernel 4.20, and happens with kernel 5.01 (the 
> next one, as I can understand) and newer (tested 5.0.7, 5.0.9,
> 5.0.10, 5.0.13, 5.0.14, 5.0.16).
> 
> With the "faulty" kernels, dar takes roughly 10-20 times to
> complete (I usually made the tests with a 1.1 GB only file to
> backup, but also with other backup size), say 10-20 minutes instead
> of 1-2 minutes.

if you have the opportunity to test the behavior of dar 2.5.x for
curiosity as it has a longer history and is deployed much wider than
2.6.x (Stable Debian and derived distros still rely on it, for
example), the only difference related to the process ending is that in
2.6.x the C++ objects are pointed to by std::shared_ptr<> pointers
rather than using C classical pointers. std::shared_ptr<> pointed to
memory release time is really compiler dependent.

if you see a difference of behavior between 2.5.x and 2.6.x check
whether the binary have been compiled with the same compiler version
(dar -V will tell you)

> 
> 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?

**** start of strace log extract ****

open("/dev/tty", O_RDONLY)              = 3

[...]

write(1, "Final memory cleanup...\n", 24) = 24
munmap(0x7f0200902000, 262144)          = 0
ioctl(3, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or TCSETS, {B38400 opost isig icanon echo
...}) = 0
ioctl(3, TCGETS, {B38400 opost isig icanon echo ...}) = 0
close(3)                                = 0
exit_group(5)                           = ?

**** end of strace log *****

in substance, libdar puts back the properties the terminal had before
dar modified it, then it closes the file descriptor 3 (opened for
"/dev/tty")

I can't imagine this being to source of the problem as the same system
call are run at the beginning of execution and any time dar asks for
user interaction... dar 2.5.x ends the same way (it closes two file
descriptors in fact)

remains the munmap call that could be buggy effectively, but this one
is added by the compiler so I cannot influence its presence or absence
so I cannot test its impact.

seen that, the raise in IO you observed is not issued by dar/libdar
itself, but seems to be a consequence of the process termination
inside the kernel of a consequence of the munmap system call(?).

Just a question, when dar is running, do you see it making the system
swapping? (you check that using "vmstat 60" for example).

> 
> 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?

> 
> 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, correc
t?

> An odd thing (maybe perfectly normal, but I've not enough skills to
> understand it) is that the time needed to copy a file is sometimes
> substantially different (15 seconds instead of 1 minute...)(I
> usually did some 5-10 identical tries for each test). I thought it
> could be related to some low level caching, but curiously it
> happens on the first copy and not on the next ones. Btw, I have
> also discovered that this seems to happen using the faulty kernel
> only.

this really points to a kernel issue...

> 
>> 
>> 
>> Anyway, whatever is asked to the kernel (by mean of system call)
>> if it is "bad", it should fail immediately, dar would report an
>> error, or would be crashed by the system (core dump), or would do
>> ugly things looping and consuming a lot of CPU in vain, ... but
>> it would not be waiting for the kernel to answer the request it
>> made (which is such D state)
> so, if I understand correctly, the D state is not compatible with 
> kernel problems, but I'm not sure to have understood :-)

this is the opposite, when a process is put in D state by the kernel
this is because the kernel is processing/waiting for all the necessary
stuff (from hardware mainly) to perform the action asked by a process
through a system call ...or is doing silly things that the process has
in any case no view nor power on.


> 
> Thanks, and bye, Andrea
> 

Ciao,
Denis

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEOzEprx3d76WjfYGPCDGwvQPYsYIFAlzf3P8ACgkQCDGwvQPY
sYK6Cw//aePjYxwhU8SZpmpPJwEHEcVgmMv9dqJX3nci5cRM9bYCilV2bpu0TyUi
21xsgR8bPoUhjWFtQe7gO3P/yBG3huS6b55x2gbupNsYqmwfmW7q+aDMeQrsb/s8
g84UwBArfhQNnx99tdQx2Ah8zd67HPATrqEUVpryvss2vfbSEZkSeVZC4d83dZMF
YR+9Fwo1bSNOVSjQpy6X1yq17AapyNBxxzsotavLxScV9jHEC4sNiPeWVtljf8/O
KgWcjgGuWYw9qjnYpJ5viI6520AMKGIItxYDKm3sJdVrMiOpZUaS9OLVWi0BTlFH
T//HL8GB8AqdrRorQ7XF0rLqJKxeZmZi7/OnUfiTNnD864I//EDs+2Aqtyqe+GvQ
ABtkUlwQI0pVnLNYdb8gZtvTtIG8fqFPXL6tbE8wch+O/CYVzlHRU60jPXUeFPjY
8RB/vgZu872NHM1LFEgIyMQoe762f/ZqdjvXZQlAIuuQbslHtql3yda8XBCLbAkb
NIxy7e61hbNyW5iLxXpFsV8kbTp2kkEjV8Q93Hs7N5O2OsLirSUuE59F+2ChFrBG
eQJRnXsk/CB0PaheVxVhwQa4hS34w16x2HaeMmK2TWtbjpWk00Ruj7gjjqzlkXJb
x9e4WpKLNHSjVxWcFYzeiZaKKcbkVGve/SIgODoLDjrN/C8EKCQ=
=oIha
-----END PGP SIGNATURE-----