Discussion:
Bug#935653: [unattended-upgrades] /usr/bin/unattended-upgrade hogging cpu
Add Reply
Riccardo Magliocchetti
2019-08-24 21:30:02 UTC
Reply
Permalink
Package: unattended-upgrades
Version: 1.14
Severity: normal

--- Please enter the report below this line. ---

Hello,

I have /usr/bin/python3 /usr/bin/unattended-upgrade using 100% of a core calling
stat in a very tight loop for no apparent good reason. It does so by holding the
/var/lib/dpkg/lock-frontend lock.

Even after a kill -9, a new process shows the same behaviour.

Stracing it looks like it's in a loop calling stat for files that does not exists:

sudo strace -c -p 6778
strace: Process 6778 attached
strace: [ Process PID=6778 runs in x32 mode. ]
strace: [ Process PID=6778 runs in 64 bit mode. ]
^Cstrace: Process 6778 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100,00 0,147692 1 77789 57944 stat
------ ----------- ----------- --------- --------- ----------------
100.00 0,147692 77789 57944 total

Excerpt on actual calls:

stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-en",
{st_mode=S_IFREG|0644, st_size=208649, ...}) = 0
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.xz",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.bz2",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.lzma",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.gz",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.lz4",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
stat("/var/lib/apt/lists/ftp.de.debian.org_debian_dists_sid_contrib_i18n_Translation-it.zst",
0x7ffd7bd40c80) = -1 ENOENT (File o directory non esistente)
...


Thanks
--
Riccardo Magliocchetti
@rmistaken

http://menodizero.it
Pascal Giard
2019-10-10 02:20:01 UTC
Reply
Permalink
Dear maintainer,

Recently unattended-upgrades started to consume a LOT more CPU time than
before.

Similarly to the original report, I looked at what strace gets in terms of
statistics, here it is:
strace: Process 5193 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100,00 4,762247 2 2288315 1703451 stat
0,00 0,000051 0 100 read
0,00 0,000015 0 20 openat
0,00 0,000008 0 20 close
0,00 0,000005 0 20 fstat
0,00 0,000005 0 20 fcntl
------ ----------- ----------- --------- --------- ----------------
100.00 4,762331 2288495 1703451 total

Looks odd, no?

It is so bothering that for now I've disabled unattended-upgrades on all 3
laptops. Manual update + upgrade requires a fraction of the resources
currently required by unattended-upgrades.

I hope this issue gets sorted out. Please let me know if there's something
else I can do to provide useful information.

Thanks,

-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Bálint Réczey
2019-10-10 12:50:01 UTC
Reply
Permalink
Control -1 moreinfo

Hi Pascal,

I tried to reproduce the issue in an lxc container, but did not
observe a lot of stat calls:

***@sid-uu:~# dpkg -i hello_2.10-1+deb9u1_amd64.deb
dpkg: warning: downgrading hello from 2.10-2 to 2.10-1+deb9u1
(Reading database ... 15204 files and directories currently installed.)
Preparing to unpack hello_2.10-1+deb9u1_amd64.deb ...
Unpacking hello (2.10-1+deb9u1) over (2.10-2) ...
Setting up hello (2.10-1+deb9u1) ...
***@sid-uu:~# time strace -f -c unattended-upgrade --debug --verbose
strace: Process 7208 attached
...
All upgrades installed
InstCount=0 DelCount=0 BrokenCount=0
Extracting content from
/var/log/unattended-upgrades/unattended-upgrades-dpkg.log since
2019-10-10 12:32:00
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
66.25 0.877182 2587 339 1 wait4
12.31 0.162923 2201 74 24 poll
3.54 0.046883 919 51 link
3.15 0.041677 11 3506 240 read
2.91 0.038556 488 79 fsync
...

Could you please add some more detailed reproduction steps?
What release do you use, for example?

Cheers,
Balint
Post by Pascal Giard
Dear maintainer,
Recently unattended-upgrades started to consume a LOT more CPU time than before.
strace: Process 5193 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100,00 4,762247 2 2288315 1703451 stat
0,00 0,000051 0 100 read
0,00 0,000015 0 20 openat
0,00 0,000008 0 20 close
0,00 0,000005 0 20 fstat
0,00 0,000005 0 20 fcntl
------ ----------- ----------- --------- --------- ----------------
100.00 4,762331 2288495 1703451 total
Looks odd, no?
It is so bothering that for now I've disabled unattended-upgrades on all 3 laptops. Manual update + upgrade requires a fraction of the resources currently required by unattended-upgrades.
I hope this issue gets sorted out. Please let me know if there's something else I can do to provide useful information.
Thanks,
-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Pascal Giard
2019-10-11 03:10:02 UTC
Reply
Permalink
Hi Balint,

Thank you for looking into this.

Running "time strace -f -c unattended-upgrade --debug --verbose" it became
obvious that unattended-upgrade was going through ALL the experimental
packages in order to, in the end, ignore them (priority), causing a
significant delay.

Disabling experimental from my sources:
I don't have the time to let it go all the way through yet, but the number
of stat calls and errors is still significant.
And a lot of time appears to be spent "recursively adjusting dependencies",
e.g.,
falling back to adjusting asymptote's dependencies recursively
falling back to adjusting asymptote-doc's dependencies recursively
falling back to adjusting binutils's dependencies recursively
falling back to adjusting binutils-common's dependencies recursively
falling back to adjusting binutils-x86-64-linux-gnu's dependencies
recursively
falling back to adjusting cpp-9's dependencies recursively
etc.

Note this may very well be expected behavior. That I can't tell.

Best regards,
-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Post by Bálint Réczey
Control -1 moreinfo
Hi Pascal,
I tried to reproduce the issue in an lxc container, but did not
dpkg: warning: downgrading hello from 2.10-2 to 2.10-1+deb9u1
(Reading database ... 15204 files and directories currently installed.)
Preparing to unpack hello_2.10-1+deb9u1_amd64.deb ...
Unpacking hello (2.10-1+deb9u1) over (2.10-2) ...
Setting up hello (2.10-1+deb9u1) ...
strace: Process 7208 attached
...
All upgrades installed
InstCount=0 DelCount=0 BrokenCount=0
Extracting content from
/var/log/unattended-upgrades/unattended-upgrades-dpkg.log since
2019-10-10 12:32:00
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
66.25 0.877182 2587 339 1 wait4
12.31 0.162923 2201 74 24 poll
3.54 0.046883 919 51 link
3.15 0.041677 11 3506 240 read
2.91 0.038556 488 79 fsync
...
Could you please add some more detailed reproduction steps?
What release do you use, for example?
Cheers,
Balint
Post by Pascal Giard
Dear maintainer,
Recently unattended-upgrades started to consume a LOT more CPU time than
before.
Post by Pascal Giard
Similarly to the original report, I looked at what strace gets in terms
strace: Process 5193 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100,00 4,762247 2 2288315 1703451 stat
0,00 0,000051 0 100 read
0,00 0,000015 0 20 openat
0,00 0,000008 0 20 close
0,00 0,000005 0 20 fstat
0,00 0,000005 0 20 fcntl
------ ----------- ----------- --------- --------- ----------------
100.00 4,762331 2288495 1703451 total
Looks odd, no?
It is so bothering that for now I've disabled unattended-upgrades on all
3 laptops. Manual update + upgrade requires a fraction of the resources
currently required by unattended-upgrades.
Post by Pascal Giard
I hope this issue gets sorted out. Please let me know if there's
something else I can do to provide useful information.
Post by Pascal Giard
Thanks,
-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Pascal Giard
2019-10-11 22:10:01 UTC
Reply
Permalink
Dear Balint,

I confirm that, like Thibaut Girka, I actually get tons of "sanity check
failed" which actually trigger those numerous "falling back to adjusting
<some package>'s dependencies recursively".

Best regards,

-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Bálint Réczey
2019-10-15 19:00:01 UTC
Reply
Permalink
Control: forwarded -1 https://github.com/mvo5/unattended-upgrades/pull/231

Hi Pascal,

The PR above should address most of the issue.

Cheers,
Balint
Post by Pascal Giard
Dear Balint,
I confirm that, like Thibaut Girka, I actually get tons of "sanity check failed" which actually trigger those numerous "falling back to adjusting <some package>'s dependencies recursively".
Best regards,
-Pascal
--
Homepage (http://pascal.giard.info)
École de technologie supérieure (http://etsmtl.ca)
Loading...