Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1227014
| Summary: | dnf makecache is extremely slow | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Adam Miller <admiller> |
| Component: | libsolv | Assignee: | Packaging Maintenance Team <packaging-team-maint> |
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 23 | CC: | bill-bugzilla.redhat.com, dustymabe, franciscossouza, ignatenko, james.findley, jperrin, jsilhan, marcos.souza.org, marmarek, mattdm, mhroncok, mluscon, packaging-team-maint, pbrobinson, pnemade, rdieter, rholy, rwahl, tla, vmukhame, yaroslav.sapozhnik |
| Target Milestone: | --- | Keywords: | Reopened |
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | libsolv-0.6.19-2.fc23 | Doc Type: | Bug Fix |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2016-03-13 23:55:23 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
|
Description
Adam Miller
2015-06-01 16:56:19 UTC
Similar results here. [root@thinkpad ~]# dnf clean metadata Cleaning repos: rawhide 6 metadata files removed 4 dbcache files removed [root@thinkpad ~]# time dnf makecache Fedora - Rawhide - Developmental packages for the next Fedora release 3.2 MB/s | 42 MB 00:13 Metadata cache created. real 6m34.876s user 0m14.563s sys 0m10.044s [root@thinkpad ~]# yum-deprecated clean metadata Yum command has been deprecated, use dnf instead. See 'man dnf' and 'man yum2dnf' for more information. Cleaning repos: rawhide 0 metadata files removed 0 sqlite files removed 0 metadata files removed [root@thinkpad ~]# time yum-deprecated makecache Yum command has been deprecated, use dnf instead. See 'man dnf' and 'man yum2dnf' for more information. rawhide/x86_64/metalink | 9.5 kB 00:00:00 rawhide | 4.2 kB 00:00:00 (1/5): rawhide/x86_64/group_gz | 230 kB 00:00:00 (2/5): rawhide/x86_64/prestodelta | 171 kB 00:00:00 (3/5): rawhide/x86_64/primary_db | 18 MB 00:00:02 (4/5): rawhide/x86_64/other_db | 8.2 MB 00:00:03 (5/5): rawhide/x86_64/filelists_db | 27 MB 00:00:09 Metadata Cache Created real 0m16.961s user 0m7.061s sys 0m2.933s This bug appears to have been reported against 'rawhide' during the Fedora 23 development cycle. Changing version to '23'. (As we did not run this process for some time, it could affect also pre-Fedora 23 development cycle bugs. We are very sorry. It will help us with cleanup during Fedora 23 End Of Life. Thank you.) More information and reason for this action is here: https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora23 I see two two improvements that could be made: * don't download filelists (bug 968006) * download metadata in parallel (bug 1172752) Marking as a duplicate of parallel metadata download if you don't mind. *** This bug has been marked as a duplicate of bug 1172752 *** I'm not entirely sure that this a duplicate, whatever dnf is doing is extremely cpu-bound. I can see a core of my cpu pegged out to 100% in htop for the entire duration of the 'dnf makecache'. Exactly, this doesn't seems to be a duplicate at all.
dnf indeed downloads a lot of metadata, but on fast connection this isn't an issue. The whole download process takes only few seconds (one repository at a time), then after downloading each repository metadata, dnf sits a lot of time consuming 100% CPU. According to strace there is a lot of `mremap` calls and gdb says it's all inside of `repodata_internalize` from libsolv.
I guess dnf (libsolv) uses that time to convert xml.gz input files to some internal format.
And when I say "a lot of time", I mean calling `dnf check-update` after `dnf clean all` requires 12 minutes of dnf using 100% of CPU. Horrible for usability, battery life, system temperature and probably more. On the same system, calling `yum-deprecated check-update` after `yum-deprecated clean all` requires only 14 sec.
Some more data:
-------
[user@f22test ~]$ time sudo dnf clean all
Cleaning repos: fedora test updates qubes-vm-r3.0-current-testing
: qubes-vm-r3.0-current
Cleaning up Everything
real 0m0.510s
user 0m0.329s
sys 0m0.159s
[user@f22test ~]$ time sudo dnf check-update
Fedora 22 - x86_64 10 MB/s | 41 MB 00:04
######### (here it takes over 10 minutes) #######
Test 1.2 MB/s | 10 kB 00:00
Fedora 22 - x86_64 - Updates 8.8 MB/s | 19 MB 00:02
Qubes OS Repository for VM (updates-testing) 3.8 kB/s | 257 B 00:00
Qubes OS Repository for VM (updates) 3.6 kB/s | 257 B 00:00
Last metadata expiration check performed 0:00:00 ago on Fri Oct 30 15:33:52 2015.
real 12m43.331s
user 0m46.187s
sys 11m35.080s
-------
(gdb) bt
#0 0x00007fb18612034a in mremap () from /lib64/libc.so.6
#1 0x00007fb18609a8a4 in mremap_chunk () from /lib64/libc.so.6
#2 0x00007fb1860a1848 in realloc () from /lib64/libc.so.6
#3 0x00007fb17347ac0e in solv_realloc () from /lib64/libsolv.so.0
#4 0x00007fb17346d1d9 in repodata_serialize_key.isra ()
from /lib64/libsolv.so.0
#5 0x00007fb1734780f4 in repodata_internalize () from /lib64/libsolv.so.0
#6 0x00007fb17321efd1 in repo_add_rpmmd () from /lib64/libsolvext.so.0
#7 0x00007fb1736cd0d5 in load_filelists_cb () from /lib64/libhawkey.so.2
#8 0x00007fb1736ce7d5 in load_ext () from /lib64/libhawkey.so.2
#9 0x00007fb1736ceef1 in hy_sack_load_repo () from /lib64/libhawkey.so.2
#10 0x00007fb1738e6021 in load_repo ()
from /usr/lib64/python2.7/site-packages/hawkey/_hawkeymodule.so
#11 0x00007fb186dea572 in PyEval_EvalFrameEx () from /lib64/libpython2.7.so.1.0
#12 0x00007fb186deb6b4 in PyEval_EvalCodeEx () from /lib64/libpython2.7.so.1.0
#13 0x00007fb186dea5c6 in PyEval_EvalFrameEx () from /lib64/libpython2.7.so.1.0
#14 0x00007fb186deb6b4 in PyEval_EvalCodeEx () from /lib64/libpython2.7.so.1.0
#15 0x00007fb186dea5c6 in PyEval_EvalFrameEx () from /lib64/libpython2.7.so.1.0
#16 0x00007fb186deb6b4 in PyEval_EvalCodeEx () from /lib64/libpython2.7.so.1.0
#17 0x00007fb186dea5c6 in PyEval_EvalFrameEx () from /lib64/libpython2.7.so.1.0
#18 0x00007fb186deb6b4 in PyEval_EvalCodeEx () from /lib64/libpython2.7.so.1.0
#19 0x00007fb186dea5c6 in PyEval_EvalFrameEx () from /lib64/libpython2.7.so.1.0
#20 0x00007fb186deb6b4 in PyEval_EvalCodeEx () from /lib64/libpython2.7.so.1.0
---Type <return> to continue, or q <return> to quit---q
--------- strace:
read(7, "\25W\206]Y\311\346\340\325sU\3529\223M\336\315du\257\322\330M\273g\344\364F\17\30\23\377"..., 8192) = 8192
mremap(0x7fb16133d000, 46936064, 46940160, MREMAP_MAYMOVE) = 0x7fb15933c000
mremap(0x7fb15933c000, 46940160, 46944256, MREMAP_MAYMOVE) = 0x7fb16133b000
mremap(0x7fb16133b000, 46944256, 46948352, MREMAP_MAYMOVE) = 0x7fb15933a000
mremap(0x7fb15933a000, 46948352, 46952448, MREMAP_MAYMOVE) = 0x7fb161339000
mremap(0x7fb161339000, 46952448, 46956544, MREMAP_MAYMOVE) = 0x7fb159338000
mremap(0x7fb159338000, 46956544, 46960640, MREMAP_MAYMOVE) = 0x7fb161337000
mremap(0x7fb161337000, 46960640, 46964736, MREMAP_MAYMOVE) = 0x7fb159336000
mremap(0x7fb159336000, 46964736, 46968832, MREMAP_MAYMOVE) = 0x7fb161335000
mremap(0x7fb161335000, 46968832, 46972928, MREMAP_MAYMOVE) = 0x7fb159334000
mremap(0x7fb159334000, 46972928, 46977024, MREMAP_MAYMOVE) = 0x7fb161333000
mremap(0x7fb161333000, 46977024, 46981120, MREMAP_MAYMOVE) = 0x7fb159332000
mremap(0x7fb159332000, 46981120, 46985216, MREMAP_MAYMOVE) = 0x7fb161331000
mremap(0x7fb161331000, 46985216, 46989312, MREMAP_MAYMOVE) = 0x7fb159330000
read(7, "H\360\276\"&\t\267A\220\330\244\264\365\307\23Q\333BAr\320'x\v\4\211Q\335\254m\22\244"..., 8192) = 8192
mremap(0x7fb159330000, 46989312, 46993408, MREMAP_MAYMOVE) = 0x7fb16132f000
mremap(0x7fb16132f000, 46993408, 46997504, MREMAP_MAYMOVE) = 0x7fb15932e000
mremap(0x7fb15932e000, 46997504, 47001600, MREMAP_MAYMOVE) = 0x7fb16132d000
mremap(0x7fb16132d000, 47001600, 47005696, MREMAP_MAYMOVE) = 0x7fb15932c000
mremap(0x7fb15932c000, 47005696, 47009792, MREMAP_MAYMOVE) = 0x7fb16132b000
mremap(0x7fb16132b000, 47009792, 47013888, MREMAP_MAYMOVE) = 0x7fb15932a000
mremap(0x7fb15932a000, 47013888, 47017984, MREMAP_MAYMOVE) = 0x7fb161329000
mremap(0x7fb161329000, 47017984, 47022080, MREMAP_MAYMOVE) = 0x7fb159328000
mremap(0x7fb159328000, 47022080, 47026176, MREMAP_MAYMOVE) = 0x7fb161327000
mremap(0x7fb161327000, 47026176, 47030272, MREMAP_MAYMOVE) = 0x7fb159326000
mremap(0x7fb159326000, 47030272, 47034368, MREMAP_MAYMOVE) = 0x7fb161325000
mremap(0x7fb161325000, 47034368, 47038464, MREMAP_MAYMOVE) = 0x7fb159324000
mremap(0x7fb159324000, 47038464, 47042560, MREMAP_MAYMOVE) = 0x7fb161323000
read(7, "\240\306\23\\P\273\224A\304Y\32>f\206\253Vn,,}a\317\36\203M\255\33\vK\243\252\264"..., 8192) = 8192
mremap(0x7fb161323000, 47042560, 47046656, MREMAP_MAYMOVE) = 0x7fb159322000
mremap(0x7fb159322000, 47046656, 47050752, MREMAP_MAYMOVE) = 0x7fb161321000
mremap(0x7fb161321000, 47050752, 47054848, MREMAP_MAYMOVE) = 0x7fb159320000
mremap(0x7fb159320000, 47054848, 47058944, MREMAP_MAYMOVE) = 0x7fb16131f000
mremap(0x7fb16131f000, 47058944, 47063040, MREMAP_MAYMOVE) = 0x7fb15931e000
mremap(0x7fb15931e000, 47063040, 47067136, MREMAP_MAYMOVE^CProcess 1878 detached
<detached ...>
------
Interesting is that, the most of the time is spent in `mremap` calls (at least I guess so based on `sys 11m35.080s`). Only a small fraction of that is used for actual data processing (user 0m46.187s). Maybe memory allocation in libsolv can be improved? Is there any simple way to isolate the sole metadata processing call and try to fiddle with some parameters (if there are any)? But fist of all, please reopen this bug, or tell me I should create a new one. I'd suggest a new/specific bug Reopened as new. Hi, just in case it might not be obvious, this bug makes fedora virtually useless as a container base. Docker builds need to be fast, and a 15+ minute wait for dnf to set up a cache (that in many cases won't ever be used more than once) means that in my organisation, we've had to specifically prohibit fedora inside containers. It'd be great if this could be fixed. (In reply to Marek Marczykowski from comment #5) > dnf indeed downloads a lot of metadata, but on fast connection this isn't an > issue. The whole download process takes only few seconds (one repository at > a time), then after downloading each repository metadata, dnf sits a lot of > time consuming 100% CPU. According to strace there is a lot of `mremap` > calls and gdb says it's all inside of `repodata_internalize` from libsolv. > > I guess dnf (libsolv) uses that time to convert xml.gz input files to some > internal format. That's the creation of the .solv files in the cache - it should take <4 sec for fedora repo (see below). IMO the bottle neck is the downloading of large files in the sequence. We'll investigate more. * loading of local .solv (no download nor creation .solv file) # time sudo dnf check-update -C --disablerepo=\* --enablerepo=fedora ... Last metadata expiration check performed 4 days, 21:34:37 ago on Wed Oct 28 15:57:09 2015. ... real 0m0.487s user 0m0.377s sys 0m0.077s * creation of .solv file + loading (no download) # sudo rm /var/cache/dnf/fedora.solv # time sudo dnf check-update -C --disablerepo=\* --enablerepo=fedora Last metadata expiration check performed 4 days, 21:35:25 ago on Wed Oct 28 15:57:09 2015. ... real 0m4.289s user 0m3.738s sys 0m0.187s * downloading of xml file + creation of .solv file + loading # time sudo dnf check-update --disablerepo=\* --enablerepo=fedora --refresh Fedora 21 - x86_64 23 MB/s | 39 MB 00:01 Last metadata expiration check performed 0:00:13 ago on Mon Nov 2 13:36:18 2015. ... real 0m25.422s user 0m15.955s sys 0m1.356s According to hawkey.log, it's all about loading/parsing filelist.xml.gz. If I remove just fedora.solv, its regeneration is fast. But if I remove fedora-filenames.solv, I need to wait several minutes. Just opened upstream bug: https://github.com/openSUSE/libsolv/issues/111 There is also more general discussion about repo metadata: https://bugzilla.redhat.com/show_bug.cgi?id=850896 But it's a long way until something meaningful would come up, and dnf is unusable just now. The upstream bug is fixed (see above link for details), so now it's only a matter of getting it packaged for Fedora. Can we please take that commit and apply it as a patch in Fedora? specifically: https://github.com/openSUSE/libsolv/commit/a8220fe1d69f96825a912df96d1a2212f5c61b85 I wound up here via strace on fedup on an F21 Xen Dom0 machine. It would be super if we could push this back as far as possible to help more people stay current. I figured fedup was broken as it just sat "doing nothing" for 20 minutes. They've just released libsolv 0.6.15, so it's just a matter of upgrading the libsolv package to this version. libsolv-0.6.15-1.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2015-778555cbc2 libsolv-0.6.15-1.fc22 has been submitted as an update to Fedora 22. https://bodhi.fedoraproject.org/updates/FEDORA-2015-7705ba2ba0 This problem still happens on my Fedora 23. I'm waiting for more than 5 minutes to have a command like check-update to finish. Update mentioned above was suspended. Can anyone push it back (probably also fixing the reason why it was suspended)? dnf-1.1.7-2.fc23 dnf-plugins-core-0.1.17-1.fc23 libsolv-0.6.19-2.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-0123ce82c1 dnf-1.1.7-2.fc23 dnf-plugins-core-0.1.17-1.fc23 libsolv-0.6.19-2.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-0123ce82c1 dnf-1.1.7-2.fc22 dnf-plugins-core-0.1.17-1.fc22 libsolv-0.6.19-2.fc22 has been submitted as an update to Fedora 22. https://bodhi.fedoraproject.org/updates/FEDORA-2016-f673381075 dnf-1.1.7-2.fc22 dnf-plugins-core-0.1.17-1.fc22 libsolv-0.6.19-2.fc22 has been submitted as an update to Fedora 22. https://bodhi.fedoraproject.org/updates/FEDORA-2016-f673381075 dnf-1.1.7-2.fc22, dnf-plugins-core-0.1.17-1.fc22, libsolv-0.6.19-2.fc22 has been pushed to the Fedora 22 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-f673381075 dnf-1.1.7-2.fc23, dnf-plugins-core-0.1.17-1.fc23, libsolv-0.6.19-2.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-0123ce82c1 dnf-1.1.7-2.fc23, dnf-plugins-core-0.1.17-1.fc23, libsolv-0.6.19-2.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report. It's better with the update, but still 2 times slower than yum-deprecated. |