Stage "searching for obsolete software" takes a very long time (30 minutes)

Bug #1874272 reported by Jean-Baptiste Lallement
76
This bug affects 16 people
Affects Status Importance Assigned to Milestone
ubuntu-release-upgrader (Ubuntu)
High
Unassigned
Focal
High
Unassigned

Bug Description

Test Case:
1. Fresh Bionic installation from 18.04.4 + all updates applied
2. Run: update-manager -d
3. Proceed with the upgrade.

Actual Result:
Everything goes well but the stage "Searching for obsolete software" takes a very long time.

ProblemType: Bug
DistroRelease: Ubuntu 20.04
Package: ubuntu-release-upgrader-core 1:20.04.18
ProcVersionSignature: Ubuntu 5.4.0-26.30-generic 5.4.30
Uname: Linux 5.4.0-26-generic x86_64
ApportVersion: 2.20.11-0ubuntu27
Architecture: amd64
CasperMD5CheckResult: skip
CrashDB: ubuntu
CurrentDesktop: ubuntu:GNOME
Date: Wed Apr 22 10:34:19 2020
InstallationDate: Installed on 2020-04-20 (2 days ago)
InstallationMedia: Ubuntu 18.04.4 LTS "Bionic Beaver" - Release amd64 (20200203.1)
PackageArchitecture: all
ProcEnviron:
 TERM=xterm-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: ubuntu-release-upgrader
Symptom: ubuntu-release-upgrader
UpgradeStatus: Upgraded to focal on 2020-04-22 (0 days ago)
VarLogDistupgradeTermlog:

Revision history for this message
Jean-Baptiste Lallement (jibel) wrote :
Revision history for this message
Brian Murray (brian-murray) wrote :

I restored this apt-clone file to an Ubuntu 18.04 LTS system and then upgraded to Ubuntu 20.04 LTS. The search for obsolete software only took a minute.

bdmurray@clean-bionic-amd64:~$ grep "obsolete pkgs" /var/log/dist-upgrade/main.log
2020-04-22 14:04:41,576 DEBUG Start checking for obsolete pkgs
2020-04-22 14:05:27,656 DEBUG Finish checking for obsolete pkgs

It's not immediately clear to me what is going on. This other cache operation of yours also took a long time.

2020-04-22 09:17:49,110 INFO cache.commit()
2020-04-22 09:42:51,188 DEBUG cache.commit() returned None
2020-04-22 09:42:51,332 DEBUG openCache()
2020-04-22 09:42:54,210 DEBUG /openCache(), new cache size 65224

Revision history for this message
Brian Murray (brian-murray) wrote :

I also did a spot check of open bugs in Launchpad for Mainlog.txt files with an extremely long times between starting and finishing the check for obsolete packages and I found none. Although, maybe I should check closed bugs too.

Revision history for this message
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in ubuntu-release-upgrader (Ubuntu):
status: New → Confirmed
Revision history for this message
Fabricio G. Scaglioni (fgscaglioni) wrote :

I was upgrading from version 18.04 to 20.04 when this bug has appeared.

2020-04-25 11:47:59,154 DEBUG Start checking for obsolete pkgs
2020-04-25 12:37:11,877 DEBUG Finish checking for obsolete pkgs

Revision history for this message
RarSa (rarsa) wrote :

I can confirm the problem. Including the delay in the cache.commit():

2020-04-26 13:05:59,023 INFO cache.commit()
2020-04-26 14:24:25,464 DEBUG cache.commit() returned None

For the obsolete packages
2020-04-26 14:32:27,989 DEBUG Start checking for obsolete pkgs
2020-04-26 14:53:12,608 DEBUG Finish checking for obsolete pkgs

Most of the packages report a "DEBUG package '<package name' produces an unwanted removal'gnome-software-plugin-snap', skipping

tags: added: rls-ff-incoming
Revision history for this message
Johannes (piktogrammdd+ubuntu) wrote :

Sorry, I can't add much, but the process on my machine (2Core 4T Intel Haswell, 16GB Ram, Samsung 860Evo SSD) took over 6 hours. Update was from 19.10 to 20.04.

$ grep "obsolete pkgs" /var/log/dist-upgrade/main.log
2020-04-30 20:17:50,550 DEBUG Start checking for obsolete pkgs
2020-05-01 02:39:51,833 DEBUG Finish checking for obsolete pkgs

Changed in ubuntu-release-upgrader (Ubuntu):
importance: Undecided → High
Revision history for this message
Dimitri John Ledkov (xnox) wrote :

I wonder if something stray is holding locks or doing things, and thus we are waiting on locks to expire.

Do we like stop unatanded upgrades / apt-daily timer units when we start the ugprade? Cause they may have "cought" the lock between us finish update, and starting to check for obsolete pkgs.

I have managed to catch lock "half-way in between doing things" before.

Changed in ubuntu-release-upgrader (Ubuntu Focal):
status: New → Confirmed
importance: Undecided → High
tags: removed: rls-ff-incoming
tags: added: id-5eb44cb5b465575ffac8f476
Revision history for this message
Lincoln Phipps (lincoln-phipps) wrote :

I've got this right now and if I tail the /var/log/dist-upgrade/main.log I have...

DEBUG package 'foo' produces an unwanted removal 'libomp5-10', skipping
DEBUG 'foo' scheduled for removal but not safe to remove, skipping

Where 'foo' changes and takes solid core 100% 20 seconds cpu to move to next package. The libomp5-10 stays the same.

Upgrade is 19.10 to 20.04 using do-release-upgrade in a console.

Revision history for this message
Steve Langasek (vorlon) wrote :

Marking this incomplete since we don't have a reliable reproducer for it. If someone experiencing this problem can check for other processes holding a lock (Dimitri's question), that would be helpful.

Changed in ubuntu-release-upgrader (Ubuntu Focal):
status: Confirmed → Incomplete
Changed in ubuntu-release-upgrader (Ubuntu):
status: Confirmed → Incomplete
Revision history for this message
David Jung (djung) wrote :

Same occurrence here form GUI 'updater'. Not a clean install - I upgraded from 17 first, then 18 LTS -> 20.04. See the same pattern in /var/log/dist-upgrade/main.log as seen by @Lincoln above. Timestamps span ~20mins.

Revision history for this message
Jani Uusitalo (uusijani) wrote :

Currently experiencing this. `lsof /var/lib/dpkg/lock` shows only "focal" as holding the lock. The same "focal" process is also eating up all of the CPU. No dpkg or apt processes are listed by `ps` either.

Revision history for this message
John Rose (johnaaronrose) wrote :

Same problem. What would happen if I stopped the upgrade (e.g. by cutting power on my Intel Barebones PC)?

Revision history for this message
bsy (bennet-yee) wrote :

37 minutes so far. Top shows final using 100% of a core. Top -H shows only one thread. Main.log shows the skipping messages.

Revision history for this message
bsy (bennet-yee) wrote :

Upgrading a second system. 47 minutes of CPU time burned so far.

Revision history for this message
paul fox (pgf-launchpad) wrote :

I've upgraded 4 systems from 18.04 to 20.04, and only one has shown this behavior. Will attach an strace of the focal process. I ran the strace for approximately 30 seconds.

tags: added: rls-ff-incoming
Revision history for this message
Noam Mor (noam-mor) wrote :

Upgraded with do-release-upgrade, "searching for obsolete software" took about 50 minutes. Attaching upgrade log (partial, upgrade has not finished yet).

tags: added: fr-328
tags: removed: rls-ff-incoming
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for ubuntu-release-upgrader (Ubuntu Focal) because there has been no activity for 60 days.]

Changed in ubuntu-release-upgrader (Ubuntu Focal):
status: Incomplete → Expired
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for ubuntu-release-upgrader (Ubuntu) because there has been no activity for 60 days.]

Changed in ubuntu-release-upgrader (Ubuntu):
status: Incomplete → Expired
Changed in ubuntu-release-upgrader (Ubuntu):
status: Expired → Confirmed
Changed in ubuntu-release-upgrader (Ubuntu Focal):
status: Expired → Confirmed
Revision history for this message
Conrad Knight (iestynapmwg) wrote :

A google search brought me here... Was this ever solved? I'm currently having the same problem, upgrading from 20.10 to 21.04. "Searching for obsolete software" was displayed about an hour and a half ago, and the line below says " eading state information... 52%" (I assume there's a display bug in the output of that last line and there should be a leading 'R').

One cpu is pegged at 100%, running the upgrade process. /var/log/dist-upgrade/apt.log is full of lines like:

Starting pkgProblemResolver with broken count: 1
Starting 2 pkgProblemResolver with broken count: 1
Investigating (0) fonts-gujr:amd64 < 2:1.4 @ii K Ib >
Broken fonts-gujr:amd64 Depends on fonts-kalapi:amd64 < 1.0-4 @ii pR >
  Considering fonts-kalapi:amd64 10001 as a solution to fonts-gujr:amd64 0
  Removing fonts-gujr:amd64 rather than change fonts-kalapi:amd64
  MarkDelete fonts-gujr:amd64 < 2:1.4 @ii K Ib > FU=0
Done
  MarkDelete pmidi:amd64 < 1.7.1-1 @ii K > FU=1
  MarkDelete librsvg2-common:i386 < 2.50.3+dfsg-1 @ii K > FU=1
  MarkDelete fonts-navilu:amd64 < 1.2-3 @ii K > FU=1
Starting pkgProblemResolver with broken count: 1
Starting 2 pkgProblemResolver with broken count: 1
Investigating (0) fonts-knda:amd64 < 2:1.3 @ii K Ib >
Broken fonts-knda:amd64 Depends on fonts-navilu:amd64 < 1.2-3 @ii pR >
  Considering fonts-navilu:amd64 10001 as a solution to fonts-knda:amd64 0
  Removing fonts-knda:amd64 rather than change fonts-navilu:amd64
  MarkDelete fonts-knda:amd64 < 2:1.3 @ii K Ib > FU=0
Done

main.log is filling with:

2021-04-24 01:44:16,280 DEBUG package 'python3.9-examples' produces an unwanted removal 'libsnack-alsa', skipping
2021-04-24 01:44:52,824 DEBUG 'python3.9-examples' scheduled for remove but not safe to remove, skipping
2021-04-24 01:44:52,969 DEBUG package 'firebird3.0-common-doc' produces an unwanted removal 'libsnack-alsa', skipping
2021-04-24 01:45:28,698 DEBUG 'firebird3.0-common-doc' scheduled for remove but not safe to remove, skipping
2021-04-24 01:45:29,665 DEBUG package 'libvdpau1:i386' produces an unwanted removal 'libsnack-alsa', skipping
2021-04-24 01:46:05,161 DEBUG 'libvdpau1:i386' scheduled for remove but not safe to remove, skipping
2021-04-24 01:46:05,313 DEBUG package 'python3-sss' produces an unwanted removal 'libsnack-alsa', skipping
2021-04-24 01:46:43,381 DEBUG 'python3-sss' scheduled for remove but not safe to remove, skipping
2021-04-24 01:46:43,517 DEBUG package 'libvo-amrwbenc0:i386' produces an unwanted removal 'libsnack-alsa', skipping
2021-04-24 01:47:19,690 DEBUG 'libvo-amrwbenc0:i386' scheduled for remove but not safe to remove, skipping
2021-04-24 01:47:19,830 DEBUG package 'ruby-svn' produces an unwanted removal 'libsnack-alsa', skipping

Revision history for this message
Cruz Fernandez (cruz-fernandez) wrote :

Similar to what @iestynapmwg said, while upgrading from Ubuntu 20.10 to 21.04 experiencing this slowness on step "searching for obsolete software". Mine took 36 minutes (in my Dell XPS 15 9550 that's not so old).

2021-05-14 08:17:28,617 DEBUG Start checking for obsolete pkgs
2021-05-14 08:41:34,610 DEBUG Finish checking for obsolete pkgs

Main difference is that my main culprit seems always package 'libqt5gui5'

2021-05-14 08:37:08,688 DEBUG 'libparams-validationcompiler-perl' scheduled for remove but not safe to remove, skipping
2021-05-14 08:37:08,776 DEBUG package 'libqt5concurrent5' produces an unwanted removal 'libqt5gui5', skipping

and lsof command returned "hirsute"

sudo lsof /var/lib/dpkg/lock
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1002/gvfs
      Output information may be incomplete.
lsof: WARNING: can't stat() fuse.portal file system /run/user/1002/doc
      Output information may be incomplete.
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
hirsute 15215 root 16uW REG 259,5 0 1966936 /var/lib/dpkg/lock

Revision history for this message
Gregory P Smith (gpshead) wrote :

Judging by the 100% cpu utilization and entries in /var/log/dist-upgrade/apt.log... as an outside observer black box guess: is this thing loading the parsing the entire package dependency graph repeatedly once per potential package?

88% complete after 30 minutes of CPU time...

Revision history for this message
Seán Ó Séaghdha (seanos) wrote :

Happened for me on 2 machines today upgrading 18.04 -> 20.04.

Revision history for this message
Shaya Potter (sjpotter) wrote :

I don't understand how there can be a comment that its not reproducible. I upgraded from 18.04->20.04 today and hit it and then upgraded to 21.04 and hit it again harder.

i have no idea what its trying to do to remove obsolete software, but perhaps it has to be rethought or even made into an option if it can't be done efficiently (I have 129 obsoleete packages installed at the moment, can probably prune it down, but i'd rather do it by hand then have it burn a cpu for an hour+)

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers