hi,

unattended upgrades is regularly eating 100% CPU here, seems to be stuck
in a loop while trying to find non-existing file (yes, they can't exist
as puppet dropped some bad sources.list lines into my config, but that
shouldn't break u-a).

[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_binary-all_Packages.lzma", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_binary-all_Packages.gz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_binary-all_Packages.lz4", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_binary-all_Packages.zst", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_binary-all_Packages.uncompressed", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.xz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.bz2", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.lzma", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.gz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.lz4", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.zst", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_main_i18n_Translation-en.uncompressed", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.xz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.bz2", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.lzma", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.gz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.lz4", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.zst", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-amd64_Packages.uncompressed", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-i386_Packages", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-i386_Packages.xz", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[pid 1391788] newfstatat(AT_FDCWD, "/var/lib/apt/lists/deb.debian.org_debian_dists_sid-backports_contrib_binary-i386_Packages.bz2", 0x7ffdc3ac3ca0, 0) = -1 ENOENT (No such file or directory)
[..... and so on....]


100% CPU, needs to be killed as its stuck in a loop.

Thanks,

Bernd

I am seeing this problem for very long time with unattended-upgrades.
More than a year. It sometimes doesn't happen for weeks, but sometimes
happens soon after boot.

Not usable at the current state.

Attaching longer strace maybe it will help.

Hello, I experienced this bug (of which #1021042 might be a dup of BTW) for
the first time after having recently updated a bunch of packages (including
unattended-upgrades itself) from bullseye to bookworm.

I can only add that the infinite stat()ing does find files in /var/lib/apt/lists/
that do exist.

Attached:
 - about 0.6 seconds of strace. At ~28k lines/sec I didn't think a long
   trace was necessary or a good idea!
 - lsof output. I feel something is not quite right here! :P

Hello, I have also stumbled upon this bug. The strace is quite the same
as the original reporter mentions. Although without debugging symbols,
I got a backtrace with GDB:

    0x00007feac853a096 in debVersioningSystem::CheckDep(char const*, int, char const*) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    b(gdb) bt
    #0  0x00007feac853a096 in debVersioningSystem::CheckDep(char const*, int, char const*) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #1  0x00007feac85510e8 in pkgDepCache::CheckDep(pkgCache::DepIterator const&, int, pkgCache::PkgIterator&) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #2  0x00007feac85517c0 in pkgDepCache::DependencyState(pkgCache::DepIterator const&) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #3  0x00007feac8551bf4 in ?? () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #4  0x00007feac8558a95 in pkgDepCache::Update(OpProgress*) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #5  0x00007feac855907a in pkgDepCache::Init(OpProgress*) () from /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
    #6  0x00007feac87ace12 in ?? () from /usr/lib/python3/dist-packages/apt_pkg.cpython-311-x86_64-linux-gnu.so
    #7  0x00000000005206c8 in ?? ()
    #8  0x0000000000536950 in PyObject_Vectorcall ()
    #9  0x0000000000528559 in _PyEval_EvalFrameDefault ()
    #10 0x000000000057d132 in ?? ()
    #11 0x000000000057c9c4 in ?? ()
    #12 0x0000000000563868 in PyObject_Call ()
    #13 0x000000000052c731 in _PyEval_EvalFrameDefault ()
    #14 0x00000000006046ff in PyEval_EvalCode ()
    #15 0x000000000061e85b in ?? ()
    #16 0x000000000061af33 in ?? ()
    #17 0x000000000062d666 in ?? ()
    #18 0x000000000062d3d1 in _PyRun_SimpleFileObject ()
    #19 0x000000000062d1e8 in _PyRun_AnyFileObject ()
    #20 0x000000000062b6bb in Py_RunMain ()
    #21 0x00000000005f7cab in Py_BytesMain ()
    #22 0x00007feaca6326ca in __libc_start_call_main (main=main@entry=0x5f7c10, argc=argc@entry=3, argv=argv@entry=0x7ffd8ec55da8) at ../sysdeps/nptl/libc_start_call_main.h:58
    #23 0x00007feaca632785 in __libc_start_main_impl (main=0x5f7c10, argc=3, argv=0x7ffd8ec55da8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffd8ec55d98)
        at ../csu/libc-start.c:360
    #24 0x00000000005f7b41 in _start ()

So it seems that the problem is actually in the libapt-pkg6.0 package.
I have installed libapt-pkg6.0-dbgsym if this repeats again. The
untattended-upgrades.log contains this:

    2024-01-08 09:07:18,617 INFO Starting unattended upgrades script
    2024-01-08 09:07:18,624 INFO Allowed origins are: origin=Debian,codename=trixie,label=Debian, origin=Debian,codename=trixie,label=Debian-Security, origin=Debian,codename=trixie-security,label=Debian-Security
    2024-01-08 09:07:18,624 INFO Initial blacklist:
    2024-01-08 09:07:18,624 INFO Initial whitelist (not strict):
    2024-01-08 19:59:49,586 WARNING SIGTERM received, will stop

My /etc/apt/apt.conf.d/50unattended-upgrades contains this:

    Unattended-Upgrade::Origins-Pattern {
            "origin=Debian,codename=${distro_codename},label=Debian";
            "origin=Debian,codename=${distro_codename},label=Debian-Security";
            "origin=Debian,codename=${distro_codename}-security,label=Debian-Security";
    };
    Unattended-Upgrade::Package-Blacklist {
    };
    Unattended-Upgrade::Mail "root";
    Unattended-Upgrade::Remove-Unused-Dependencies "true";

I think this is all I can provide now.

Best wishes,
TomaS

Hi,

as this is regularly leaving systems unresponsible or at least in a
state where its basically making a hot air dryer out of servers, I'm
raising the severity. Its not an option to have a datacenter running
amok.

Bernd

I've started observing this again recently. Updating to 2.11 did not help.

Attached is stdout and stderr (containing a python traceback after I hit ^C
after about one minute) from me running:

    unattended-upgrade -v -d --download-only

for your consideration, which should at least narrow down the phase within which unattended-upgrades is getting bogged down.

I do see the unreasonable quantity of newfstatat() calls, mostly for APT
sources that (for the specific combination of suite/component/etc) are
empty, eg.

https://deb.debian.org/debian-security/dists/bookworm-security/non-free/binary-amd64/

has an empty Packages.xz. I notice APT doesn't bother to store empty files
in /var/lib/apt/lists/, so unattended-upgrades wastes a lot of time looking
for a Packages, Packages.xz, Packages.bz2, Packages.lzma, Packages.gz,
Packages.lz4, Packages.zst, and Packages.uncompressed (since when does that
dir contain compressed versions anyway?

Also, I reckon #1029941 is another dup of this bug.

HTH!

Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages unattended-upgrades depends on:
ii  debconf [debconf-2.0]      1.5.82
ii  lsb-base                   11.6
ii  lsb-release                12.0-1
ii  python3                    3.12.4-1
ii  python3-apt                2.9.0+b1
ii  python3-dbus               1.3.2-5+b3
ii  python3-distro-info        1.5+deb12u1
ii  sysvinit-utils [lsb-base]  3.09-2
ii  ucf                        3.0043+nmu1
ii  xz-utils                   5.4.1-0.2

Versions of packages unattended-upgrades recommends:
ii  anacron             2.3-36
ii  cron [cron-daemon]  3.0pl1-162
ii  systemd-sysv        256.4-2

Versions of packages unattended-upgrades suggests:
pn  bsd-mailx                                  <none>
ii  exim4-daemon-light [mail-transport-agent]  4.98-1
ii  needrestart                                3.6-4+deb12u1
ii  powermgmt-base                             1.37
ii  python3-gi                                 3.48.2-1+b1

found 2.13
thanks

strace -c output:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.64   11.034047           1   6867445   4194635 newfstatat
  0.33    0.036633          18      1996           read
  0.03    0.003487           1      1996           lseek
------ ----------- ----------- --------- --------- ----------------
100.00   11.074167           1   6871437   4194635 total

strace -c -p 28378  10.34s user 43.25s system 45% cpu 1:56.67 total

Snippet from regular strace output:

[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_source_Sources", {st_mode=S_IFREG|0644, st_size=5270421, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_source_Sources", {st_mode=S_IFREG|0644, st_size=33050, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free_source_Sources", {st_mode=S_IFREG|0644, st_size=3342, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free-firmware_source_Sources", {st_mode=S_IFREG|0644, st_size=18911, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=2463724, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=2463724, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=2066548, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=2066548, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.xz", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.bz2", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.lzma", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.gz", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.lz4", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.zst", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_binary-all_Packages.uncompressed", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_i18n_Translation-en", {st_mode=S_IFREG|0644, st_size=1668510, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_main_i18n_Translation-en", {st_mode=S_IFREG|0644, st_size=1668510, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=35708, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=35708, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=26846, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=26846, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.xz", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.bz2", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.lzma", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.gz", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.lz4", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.zst", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_binary-all_Packages.uncompressed", 0x7ffeddb5eec0, 0) = -1 ENOENT (No such file or directory)
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_i18n_Translation-en", {st_mode=S_IFREG|0644, st_size=26398, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_contrib_i18n_Translation-en", {st_mode=S_IFREG|0644, st_size=26398, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=44514, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free_binary-amd64_Packages", {st_mode=S_IFREG|0644, st_size=44514, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=27274, ...}, 0) = 0
[pid 28378] newfstatat(AT_FDCWD</var/backups>, "/var/lib/apt/lists/http.debian.net_debian_dists_stable-backports_non-free_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=27274, ...}, 0) = 0

Filtering out newfstatat() calls, we see

[pid 28444] ppoll([{fd=9<{eventfd-count=0, eventfd-id=239, eventfd-semaphore=0}>, events=POLLIN}], 1, NULL, NULL, 8 <unfinished ...>
[pid 28443] ppoll([{fd=6<{eventfd-count=0, eventfd-id=229, eventfd-semaphore=0}>, events=POLLIN}], 1, NULL, NULL, 8 <unfinished ...>
[pid 28442] futex(0x6da8f90, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28378] pselect6(145, [144<pipe:[8903427]>], NULL, NULL, {tv_sec=0, tv_nsec=3768247}, NULL) = 0 (Timeout)
[pid 28378] read(144<pipe:[8903427]>, 0xb80b200, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28378] wait4(43984, 0x7ffeddb5f67c, WNOHANG, NULL) = 0
[pid 28378] pselect6(145, [144<pipe:[8903427]>], NULL, NULL, {tv_sec=0, tv_nsec=100000000}, NULL) = 0 (Timeout)
[pid 28378] read(144<pipe:[8903427]>, 0xb80b200, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28378] wait4(43984, 0x7ffeddb5f67c, WNOHANG, NULL) = 0
[pid 28378] pselect6(145, [144<pipe:[8903427]>], NULL, NULL, {tv_sec=0, tv_nsec=100000000}, NULL) = 0 (Timeout)
[pid 28378] read(144<pipe:[8903427]>, 0xb80b200, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28378] wait4(43984, 0x7ffeddb5f67c, WNOHANG, NULL) = 0
[pid 28378] pselect6(145, [144<pipe:[8903427]>], NULL, NULL, {tv_sec=0, tv_nsec=100000000}, NULL) = 0 (Timeout)
[pid 28378] read(144<pipe:[8903427]>, 0xb80b200, 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28378] wait4(43984, 0x7ffeddb5f67c, WNOHANG, NULL) = 0
[pid 28378] pselect6(145, [144<pipe:[8903427]>], NULL, NULL, {tv_sec=0, tv_nsec=100000000}, NULL) = 0 (Timeout)

Process info:

PID    PPID   USER  NI	RES	USS	SWAP  SHR     S	 nTH  P	  %CPU	 %CUC	%MEM  TIME+	 WCHAN	COMMAND
28378  28342  root  0	328972	310920	0     211780  R	 4    22  100.1	 8.426	0.5   237:15.05	 -	/usr/bin/python3 /usr/bin/unattended-upgrade

The process tree looks like this (at 10:53 on 24 August):

root     28338  0.0  0.0   2692  1468 ?        Ss   Aug22   0:00  \_ /bin/sh /usr/lib/apt/apt.systemd.daily install
root     28342  0.0  0.0   2692  1612 ?        S    Aug22   0:00  |   \_ /bin/sh /usr/lib/apt/apt.systemd.daily lock_is_held install
root     28378  8.4  0.5 524748 345904 ?       Sl   Aug22 239:12  |       \_ /usr/bin/python3 /usr/bin/unattended-upgrade
root     43984  1.2  0.5 548916 344920 ?       S    10:51   0:01  |           \_ /usr/bin/python3 /usr/bin/unattended-upgrade
root     44048  0.0  0.0   2692  1460 ?        S    10:51   0:00  |               \_ /bin/sh -c /usr/bin/apt-listchanges --apt || test $? -lt 10
root     44049  2.7  0.0  71644 44380 ?        S    10:51   0:02  |                   \_ /usr/bin/python3 /usr/bin/apt-listchanges --apt
root     46909 46.6  0.3 256656 241956 ?       S    10:52   0:01  |                       \_ apt-get -qq changelog openjdk-17-jdk-headless=17.0.20.1+1-1
root     46922  0.0  0.0   5564  1452 ?        D    10:53   0:00  |                           \_ cat /tmp/apt-changelog-h6eEF2/openjdk-17.changelog

So it's not so much that unattended-upgrades as a whole is "stuck"; its
child 43984 is actually doing what it should. The problem is that the parent
process 28378 is in a busy loop for some reason, burning CPU cycles.

András

Hi,

I had an LLM write the attached tracer/profiler and ran unattended-upgrades with it. It took 11 hours to finish and produced copious logs, which I'm also attaching (~8MB, but they compress very well).

The trace output only shows function calls that took at least 1s.

This pattern repeats thousands of times:

The expensive operation seems to be apt.cache.get_changes(). It consistently took hundreds to low thousands of ms per invocation, while sanity_problem() itself had essentially no self time; for example:

sanity_problem() [total=1.141s self=0.005s]
  apt.cache.get_changes() [total=1.136s self=1.136s]

apt.cache.get_changes() seems to be implemented in Python by iterating over the APT cache and testing each package's marked state, with the actual package/dependency-cache operations performed through the APT bindings (making them invisible to the Python tracer).

I believe that's where all the observed newfstatat() calls are made (making them a symptom, not the actual problem).

unattended-upgrade calls get_changes() repeatedly (potentially tens of thousands of times) while evaluating and adjusting candidate changes, which contributed substantially to my observed 11-hour runtime.

The result of get_changes() reflects the current mutable marked state of the APT dependency cache, and unattended-upgrade modifies that state while considering candidates, so that the result of get_changes() can't be trivially cached; but maybe there are cases where it's called several times without intervening state changes, and those calls could be optimized out, at least.

(There is at least one redundant call in the sanity-check failure path: sanity_problem() obtains the change set, and check_changes_for_sanity() subsequently calls cache.get_changes() again to construct the debug message. However, this is only relevant to --debug runs.)

It seems to me the performance issue can only be fixed by refactoring unattended-upgrades and/or python3-apt so that get_changes() is called less often, or performs less work each time it's called.

András