[Bug 1096803] New: zypper "Reading installed packages" takes long time
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 Bug ID: 1096803 Summary: zypper "Reading installed packages" takes long time Classification: openSUSE Product: openSUSE Tumbleweed Version: Current Hardware: x86-64 OS: openSUSE Factory Status: NEW Severity: Normal Priority: P5 - None Component: libzypp Assignee: zypp-maintainers@forge.provo.novell.com Reporter: harish2704@gmail.com QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- zypper command is takes long time to complete most of the operations It is found that, most of the delay is happening after the message "Reading installed packages..." Details of time consumed by command "time zypper --no-refresh up zypper" on my system ( 2.7GHz x 4, 8GB RAM, SSD ) is given below " Nothing to do. real 1m34.984s user 1m33.487s sys 0m0.444s " -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c1 --- Comment #1 from Michael Andres <ma@suse.com> --- Please attach the zypper logfile /var/log/zypper.log (or an older and compressed /var/log/zypper.log-YYYYMMDD.xz) that shows the reported behavior. To see the execution dates and zypper commands included in a logfile you can install the zypper-log package (available since zypper-1.6.11) and execute: zypper-log To extract the log of a specific command use zypper-log pid See the manual page zypper-log(8) for details on how to read older (rotated) zypper-log files. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 Michael Andres <ma@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |harish2704@gmail.com Flags| |needinfo?(harish2704@gmail. | |com) -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c2 --- Comment #2 from Harish Karumuthil <harish2704@gmail.com> --- Created attachment 773477 --> http://bugzilla.opensuse.org/attachment.cgi?id=773477&action=edit Logs produced by "zypper up zypper" command. This 8MB logs were produced by just one time execution of command "zypper up zypper" The attached file was generated using the command "tailf /var/log/zypper.log > zypper.log" and running "zypper up zypper" as a different process -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c3 --- Comment #3 from Harish Karumuthil <harish2704@gmail.com> --- This issue is somewhat solved now even-though the root cause is still unknown. The problem was solved when I removed my "/etc/zypp/locks" file and reapplied my locks using command line. Please attached file zypper-locks.tar.gz which contains both versions for locks file. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c4 --- Comment #4 from Harish Karumuthil <harish2704@gmail.com> --- Created attachment 773481 --> http://bugzilla.opensuse.org/attachment.cgi?id=773481&action=edit Zypper lock file which caused issue -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c5 Michael Andres <ma@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Priority|P5 - None |P3 - Medium Status|NEW |CONFIRMED Flags|needinfo?(harish2704@gmail. | |com) | Severity|Normal |Enhancement --- Comment #5 from Michael Andres <ma@suse.com> --- Your 'texlive*' lock matches ~7000 packages in a single query. We can't see when it happened, but one or few of these packages were explicitly unlocked. Maybe in YASTs software selection, maybe as resolution to a solver conflict (suggesting to unlock a specific package). Anyhow, 'texlive*' can no longer be used, so it is replaced by ~7000 simple locks matching the individual 'texlive*' packages which are still locked. Now startup has to process ~7000 queries which causes the bad performance. We'll review the code.... -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c6 --- Comment #6 from Harish Karumuthil <harish2704@gmail.com> --- Thanks Michael Andres, Your explanation is really helpful and I can understand root cause of the problem now. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c7 --- Comment #7 from Harish Karumuthil <harish2704@gmail.com> --- I can confirm that, installing any software using yast2 GUI ( Which is the default action for "single click installation" on software.opensuse.com ) will convert a single rule written in "/etc/zypp/lock" to into multiple rules as Michael Andres mentioned in previous message -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c8 Michael Andres <ma@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|zypp-maintainers@forge.prov |lslezak@suse.com |o.novell.com | --- Comment #8 from Michael Andres <ma@suse.com> --- @Ladislav: I'm assigning it to you as the log reveals some potential flaws in the ONECLICK workflow (empty commit) and also in yast2-pkg-bindings (explicit locks file load/store). Now as I know what ONECLICK is doing, I'm able to prevent the lock expansion reported here in libzypp. Nevertheless the workflow looks dubious and you may want to review it (or reassign it). In short: ONECLICK initially triggers a commit without having loaded target data into the pool. This would cause the locks to be cleared, if YAST would not unconditionally load/store the locks on top of libzypps handling. YAST however causes to write the locks expanded (~7000 single package locks rather than one globbing expression). If ONECLICK actually must perform an empty commit before installing the package, then it should at least lod the current target, so no setting get lost. More detailed: Y2log abstract from a one-click install (plus some extra '[zypp]' debug lines you usually don't see). [grep -i 'locks.cc\|HardLocksFile\|targetimpl.cc\|\[pkg\]' y2log] ONECLICK calls 'TargetInitialize /' (which does not yet load the Target into the pool!):
[Pkg] modules/OneClickInstallWorkerFunctions.rb:58 Pkg Builtin called: TargetInitialize [Pkg] PkgFunctions.cc(zypp_ptr):100 Initializing Zypp library... [zypp] HardLocksFile.h(HardLocksFile):50 /etc/zypp/locks [zypp] HardLocksFile.h(HardLocksFile):51 0 -- 0 [zypp] TargetImpl.cc(TargetImpl):695 Initialized target on / [zypp] TargetImpl.cc(buildCache):850 Read cookie: /var/cache/zypp/solv/@System/cookie{- 0644 0/0 size 52} [zypp] TargetImpl.cc(buildCache):857 Read cookie: /var/cache/zypp/solv/@System/cookie says: uptodate [Pkg] modules/OneClickInstallWorkerFunctions.rb:60 Pkg Builtin called: SourceStartCache [Pkg] PkgFunctions.cc(CreateRepoManager):225 Path to repository files: /etc/zypp/repos.d
Now the following looks fishy to me: ONECLICK calls 'commit' without having loaded any repos or the target. This commits the active locks, language etc. settings, which are empty (unless YAST would explicitly provide values):
[Pkg] modules/PackageInstallation.rb:144 Pkg Builtin called: Commit [Pkg] Package.cc(Commit):2384 Restricting commit only to medium number: 0 [zypp] TargetImpl.cc(commit):1119 TargetImpl::commit(<pool>, CommitPolicy( DownloadInHeaps syncPoolAfterCommit )) [zypp] TargetImpl.cc(commit):1145 Todo: CommitResult (total 0, done 0, error 0, skipped 0, updateMessages 0) [zypp] HardLocksFile.h(setData):81 0 -- 0 [zypp++] TargetImpl.cc(commit):1237 commit log file is set to: /var/log/zypp/history [zypp] TargetImpl.cc(commit):1371 TargetImpl::commit(<list>CommitPolicy( DownloadInHeaps syncPoolAfterCommit ))0 [zypp] TargetImpl.cc(buildCache):850 Read cookie: /var/cache/zypp/solv/@System/cookie{- 0644 0/0 size 52} [zypp] TargetImpl.cc(buildCache):857 Read cookie: /var/cache/zypp/solv/@System/cookie says: uptodate [zypp] TargetImpl.cc(commit):1342 TargetImpl::commit(<pool>, CommitPolicy( DownloadInHeaps syncPoolAfterCommit )) returns: CommitResu [zypp] TargetImpl.cc(buildCache):850 Read cookie: /var/cache/zypp/solv/@System/cookie{- 0644 0/0 size 52} [zypp] TargetImpl.cc(buildCache):857 Read cookie: /var/cache/zypp/solv/@System/cookie says: uptodate [zypp] TargetImpl.cc(load):992 New cache built: false, force loading: true
Reloading the target after commit:
[zypp] TargetImpl.cc(load):998 adding /var/cache/zy
-- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c9 --- Comment #9 from Michael Andres <ma@suse.com> --- [continue - cut'n'paste lost some lines] Reloading the target after commit:
[zypp] TargetImpl.cc(load):998 adding /var/cache/zypp/solv/@System/solv to pool(@System) [zypp] TargetImpl.cc(load):1022 adding /var/cache/zypp/solv/@System/solv to system [zypp] TargetImpl.cc(load):1074 ZConfig::instance().apply_locks_file = 1 [zypp] TargetImpl.cc(load):1075 ZConfig::instance() locksfile = /etc/zypp/locks [zypp] HardLocksFile.h(data):64 0xb997820 -- 1 [zypp] TargetImpl.cc(load):1079 0 [zypp] TargetImpl.cc(load):1084 ZConfig::instance().apply_locks_file DONE
So this empty commit actually resets the locks in the pool to be empty (the `0` in the one but last line `TargetImpl.cc(load):1079`). Now the workflow continues and actually loads target and repos:
[Pkg] modules/OneClickInstallWorkerFunctions.rb:196 Pkg Builtin called: ResolvableInstallRepo [Pkg] modules/OneClickInstallWorkerFunctions.rb:220 Pkg Builtin called: TargetInit [zypp] TargetImpl.cc(buildCache):850 Read cookie: /var/cache/zypp/solv/@System/cookie{- 0644 0/0 size 52} [zypp] TargetImpl.cc(buildCache):857 Read cookie: /var/cache/zypp/solv/@System/cookie says: uptodate [zypp] TargetImpl.cc(load):992 New cache built: false, force loading: true [zypp] TargetImpl.cc(load):998 adding /var/cache/zypp/solv/@System/solv to pool(@System) [zypp] TargetImpl.cc(load):1022 adding /var/cache/zypp/solv/@System/solv to system [zypp] TargetImpl.cc(load):1074 ZConfig::instance().apply_locks_file = 1 [zypp] TargetImpl.cc(load):1075 ZConfig::instance() locksfile = /etc/zypp/locks [zypp] HardLocksFile.h(data):64 0xb997820 -- 1 [zypp] TargetImpl.cc(load):1079 0 [zypp] TargetImpl.cc(load):1084 ZConfig::instance().apply_locks_file DONE [zypp] TargetImpl.cc(updateFileContent):724 updating '/var/lib/zypp/LastDistributionFlavor' content. [zypp] TargetImpl.cc(load):1090 Target loaded: 4007 resolvables
The locks however stay empty due to the commit before. The reason why people don't lose their locks, but get complex locks exapanded, is in yast2-pkg-bindings: https://github.com/yast/yast-pkg-bindings/blob/master/src/Target_Load.cc#L10...
[Pkg] Target_Load.cc(TargetInitInternal):100 Reading locks from /etc/zypp/locks [locks] Locks.cc(readAndApply):105 read and apply locks from /etc/zypp/locks
I'm not sure why YAST on it's own explicitly loads /etc/zypp/locks? A few lines above (L85) the target is loaded, and this also loads the locks into the pool. In 'ordinary' workflows the action here is superfluous, as you load the locks a 2nd time. In ONECLICK however this is why we don't lose the locks after the empty commit, BUT the old '[locks]' API adds locks expanded (which does not matter if the tagret alredy saw the original locks). Then ONECLICK commits the package install, which writes back the (expanded) locks file:
[Pkg] modules/PackageSlideShow.rb:404 Pkg Builtin called: SourceGeneralData [Pkg] modules/OneClickInstallWorkerFunctions.rb:226 Pkg Builtin called: PkgCommit [zypp] TargetImpl.cc(commit):1119 TargetImpl::commit(<pool>, CommitPolicy( DownloadInHeaps syncPoolAfterCommit )) [zypp] TargetImpl.cc(commit):1145 Todo: CommitResult (total 1, done 0, error 0, skipped 1, updateMessages 0) [zypp] HardLocksFile.h(setData):81 0xb997820 -- 1 [zypp] HardLocksFile.cc(store):59 Wrote /etc/zypp/locks{- 0644 0/0 size 615293}
And similar to TargetInitInternal, TargetFinish would write back the locks file a second time here: https://github.com/yast/yast-pkg-bindings/blob/master/src/Target_Load.cc#L23.... Not sure how YAST can be sure that the pool does not contain any rejected changes, which should not be synced back to the system. Called after a successful commit however it's just overhead, as commit already did the same. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c10 --- Comment #10 from Michael Andres <ma@suse.com> --- JFYI: The issue should be mitigated with TUMBLEWEED libzypp 17. 5. 0 Code-15 libzypp 17. 5. 0 Code-42_3 libzypp 16.17.14 Code-42_2 libzypp 16.17.14 Code-42_1 libzypp 15.25.12 -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1096803 http://bugzilla.opensuse.org/show_bug.cgi?id=1096803#c26 Felipe Abroas <felipesabrahao@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |felipesabrahao@gmail.com OS|openSUSE Factory |All --- Comment #26 from Felipe Abroas <felipesabrahao@gmail.com> --- Bug confirmed here on Tumbleweed 20201002. -- Reproducible: Always. Also, the larger the number of packages that you lock, the longer the hanging. Workaround: Delete all the package locks on Yast2. -- You are receiving this mail because: You are on the CC list for the bug.
participants (2)
-
bugzilla_noreply＠novell.com -
bugzilla_noreply＠suse.com