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 575878
| Summary: | Checking dependencies takes over 20 minutes | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Orion Poplawski <orion> |
| Component: | yum | Assignee: | Seth Vidal <skvidal> |
| Status: | CLOSED UPSTREAM | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | medium | Docs Contact: | |
| Priority: | low | ||
| Version: | 13 | CC: | adam, dcantrell, ffesti, james.antill, jlaska, jonathan, maxamillion, pmatilai, rvykydal, tim.lauridsen, vanmeeuwen+fedora |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2010-04-12 13:56:37 UTC | Type: | --- |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
| Bug Depends On: | |||
| Bug Blocks: | 507681 | ||
|
Description
Orion Poplawski
2010-03-22 15:53:00 UTC
The more repos you add and the more metadata they pull in, the slower dependency checking is going to be. I don't see that there's a bug in anaconda here, except that the progress bar should update. We'll I regularly have more repos and more dependencies and this stage only will take a minute or two, so I think this configuration tickles something. Perhaps the large number of excluded packages? Any way to turn on some more debugging to see where it is taking so much time? /tmp/yum.log should be a pretty verbose record of everything yum did during installation. It's pretty silent on the period in question: [2010-03-18 08:54:21,341] DEBUG : No package named mcelog available to be installed [2010-03-18 09:19:16,583] DEBUG : TSINFO: Marking libacl-2.2.49-4.fc13.i686 as install for acl-2.2.49-4.fc13.i686 Can you run iftop or something to see if it's trying to download filelists? Otherwise it'd be really nice to know what yum/anaconda is doing here, is there a way to bump the verbosity? Having a quick look at anaconda, deselectPackage() is pretty horrible and could be faster ... we should probably just move it into yum in some way. But I doubt it eats 20 minutes. It's not downloading anything during that time. It does eventually download filelists at the end of it, but that's not the big time suck. strace shows lots of groups of mmap2() calls followed by munmap(). Anaconda is also consuming 100% cpu during this. sample strace snippet: 497 mmap2(NULL, 3149824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb2b4e000 497 brk(0xc086000) = 0xc086000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3955000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb38d3000 497 brk(0xc0a7000) = 0xc0a7000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3892000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3851000 497 munmap(0xb2b4e000, 3149824) = 0 497 munmap(0xb3851000, 266240) = 0 497 munmap(0xb3955000, 266240) = 0 497 munmap(0xb3892000, 266240) = 0 497 mmap2(NULL, 1576960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3467000 497 mmap2(NULL, 3149824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb2b4e000 497 munmap(0xb3467000, 1576960) = 0 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3955000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3892000 497 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb3851000 497 munmap(0xb2b4e000, 3149824) = 0 497 munmap(0xb3851000, 266240) = 0 497 munmap(0xb3955000, 266240) = 0 497 brk(0xbf8c000) = 0xbf8c000 497 brk(0xbf4c000) = 0xbf4c000 497 munmap(0xb3892000, 266240) = 0 that's just saying "allocating data, freeing data" ... which doesn't tell us much. Could still be rpm/python/sqlite/whatever. Does mean it isn't downloading though ... which sucks. the repos you've made there? Did you make the repos using the -d option to createrepo? Can you provide us with a filelist of all of the 'repodata' subdirs referenced in the baseurls above? I have a theory as to what it is doing above: I think it is building the sqlite files and maybe is doing so w/o the benefit of y-m-p. (In reply to comment #5) > Can you run iftop or something to see if it's trying to download filelists? > > Otherwise it'd be really nice to know what yum/anaconda is doing here, is there > a way to bump the verbosity? Using updates image you can raise the verbosity by patching yuminstall.py:AnacondaYum.doLoggingSetup on line logger.setLevel(yum.logginglevels.INFO_2) I'd recommend using yum.logginglevels.DEBUG_2. (In reply to comment #10) > (In reply to comment #5) > > logger.setLevel(yum.logginglevels.INFO_2) > Ah, sorry, the line relevant for /tmp/yum.log is this one: verbose.setLevel(logging.DEBUG) here is updates image for anaconda 13.35 setting it to yum.logginglevels.DEBUG_2: http://rvykydal.fedorapeople.org/updates.yumdbg.img (In reply to comment #9) > the repos you've made there? Did you make the repos using the -d option to > createrepo? Can you provide us with a filelist of all of the 'repodata' subdirs > referenced in the baseurls above? > I have a theory as to what it is doing above: I think it is building the sqlite > files and maybe is doing so w/o the benefit of y-m-p. Well, the CoRA repo is the only repo I make, and I was not using the -d option. I've added that now. The others are mirrors and all but adobe-linux provide sqlite files. But I use these repos in installs that run fast. With the update image, yum.log now contains lots of: [2010-03-23 11:43:23,807] DEBUG_1 : Package: 1:grub-0.97-64.fc13.i686 - already in transaction set [2010-03-23 11:43:24,965] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:26,512] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:28,852] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:29,994] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:31,525] DEBUG_1 : Package: lvm2-2.02.61-1.fc13.i686 - already in transaction set [2010-03-23 11:43:32,697] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:33,847] DEBUG_1 : Package: mdadm-3.0.3-3.fc13.i686 - already in transaction set [2010-03-23 11:43:34,984] DEBUG_1 : Package: lvm2-2.02.61-1.fc13.i686 - already in transaction set [2010-03-23 11:43:36,503] DEBUG_1 : Package: e2fsprogs-1.41.10-6.fc13.i686 - already in transaction set .... which keeps repeating in random order. Orion, how many duplicates are there in your repos of each other? (In reply to comment #13) > how many duplicates are there in your repos of each other? Not quite sure what you mean. But: # yum list --showduplicates --disablerepo=updates-testing | awk '$1 == lastpkg { print last "\n" $0 }; {lastpkg = $1; last = $0}' akmod-VirtualBox-OSE.i686 3.0.10-1.fc12.4 rpmfusion-free-rawhide akmod-VirtualBox-OSE.i686 3.1.0-0.1.beta2.fc13 rpmfusion-free-rawhide akmod-VirtualBox-OSE.i686 3.1.0-0.1.beta2.fc13 rpmfusion-free-rawhide akmod-VirtualBox-OSE.i686 3.1.0-1.fc13 rpmfusion-free-rawhide akmod-VirtualBox-OSE.i686 3.1.0-1.fc13 rpmfusion-free-rawhide akmod-VirtualBox-OSE.i686 3.1.2-1.fc13 rpmfusion-free-rawhide akmod-em8300.i686 0.17.4-1.fc13.2 rpmfusion-free-rawhide akmod-em8300.i686 0.18.0-1.fc13 rpmfusion-free-rawhide akmod-kqemu.i686 1.4.0-0.2.pre1.fc12.15 rpmfusion-free-rawhide akmod-kqemu.i686 1.4.0-0.2.pre1.fc13.16 rpmfusion-free-rawhide akmod-ndiswrapper.i686 1.54-4.fc12.14 rpmfusion-free-rawhide akmod-ndiswrapper.i686 1.54-4.fc13.15 rpmfusion-free-rawhide akmod-nvidia.i686 190.42-1.fc13.5 rpmfusion-nonfree-rawhide akmod-nvidia.i686 190.53-1.fc13 rpmfusion-nonfree-rawhide akmod-open-vm-tools.i686 0.0.0.201664-1.fc12.6 rpmfusion-free-rawhide akmod-open-vm-tools.i686 0.0.0.226760-1.fc13 rpmfusion-free-rawhide akmod-rt2860.i686 2.1.2.0-3.fc12.6 rpmfusion-free-rawhide akmod-rt2860.i686 2.1.2.0-3.fc13.7 rpmfusion-free-rawhide akmod-rt2870.i686 2.1.2.0-3.fc12.6 rpmfusion-free-rawhide akmod-rt2870.i686 2.1.2.0-5.fc13 rpmfusion-free-rawhide akmod-rt2870.i686 2.1.2.0-5.fc13 rpmfusion-free-rawhide akmod-rt2870.i686 2.1.2.0-6.fc13 rpmfusion-free-rawhide akmod-rt3070.i686 2.1.1.0-3.fc12.6 rpmfusion-free-rawhide akmod-rt3070.i686 2.1.1.0-3.fc13.7 rpmfusion-free-rawhide akmod-wl.i686 5.10.91.9.3-3.fc12.6 rpmfusion-nonfree-rawhide akmod-wl.i686 5.10.91.9.3-4.fc13 rpmfusion-nonfree-rawhide akmod-wl.i686 5.10.91.9.3-4.fc13 rpmfusion-nonfree-rawhide akmod-wl.i686 5.60.48.36-1.fc13 rpmfusion-nonfree-rawhide bsnes.i686 0.051-1.fc12 rpmfusion-nonfree-rawhide bsnes.i686 0.060-1.fc14 rpmfusion-free-rawhide flexlm.i386 11.4.100.0-1.cora CoRA flexlm.i386 11.4.100.0-2.cora CoRA flexlm-idl.i386 11.4.100.0-1.cora CoRA flexlm-idl.i386 11.4.100.0-2.cora CoRA idl.i386 7.1-1 CoRA idl.i386 7.1.1-1 CoRA idl-base.noarch 7.1-1 CoRA idl-base.noarch 7.1.1-1 CoRA idl-common.noarch 7.1-1 CoRA idl-common.noarch 7.1.1-1 CoRA idl-devel.noarch 7.1-1 CoRA idl-devel.noarch 7.1.1-1 CoRA idl-workbench.i386 7.1-1 CoRA idl-workbench.i386 7.1.1-1 CoRA java3d.i386 1.3.1-0.cte.2 CoRA java3d.i386 1.3.2-1jpp CoRA kmod-VirtualBox-OSE.i686 3.1.0-0.1.beta2.fc13 rpmfusion-free-rawhide kmod-VirtualBox-OSE.i686 3.1.0-1.fc13 rpmfusion-free-rawhide kmod-VirtualBox-OSE.i686 3.1.0-1.fc13 rpmfusion-free-rawhide kmod-VirtualBox-OSE.i686 3.1.2-1.fc13 rpmfusion-free-rawhide kmod-em8300.i686 0.17.4-1.fc13.2 rpmfusion-free-rawhide kmod-em8300.i686 0.18.0-1.fc13 rpmfusion-free-rawhide kmod-em8300-PAE.i686 0.17.4-1.fc13.2 rpmfusion-free-rawhide kmod-em8300-PAE.i686 0.18.0-1.fc13 rpmfusion-free-rawhide kmod-kqemu-PAE.i686 1.4.0-0.2.pre1.fc12.15 rpmfusion-free-rawhide kmod-kqemu-PAE.i686 1.4.0-0.2.pre1.fc13.16 rpmfusion-free-rawhide kmod-ndiswrapper-PAE.i686 1.54-4.fc12.14 rpmfusion-free-rawhide kmod-ndiswrapper-PAE.i686 1.54-4.fc13.15 rpmfusion-free-rawhide kmod-nvidia.i686 190.42-1.fc13.5 rpmfusion-nonfree-rawhide kmod-nvidia.i686 190.53-1.fc13 rpmfusion-nonfree-rawhide kmod-nvidia-PAE.i686 190.42-1.fc13.5 rpmfusion-nonfree-rawhide kmod-nvidia-PAE.i686 190.53-1.fc13 rpmfusion-nonfree-rawhide kmod-open-vm-tools-PAE.i686 0.0.0.201664-1.fc12.6 rpmfusion-free-rawhide kmod-open-vm-tools-PAE.i686 0.0.0.226760-1.fc13 rpmfusion-free-rawhide kmod-rt2860-PAE.i686 2.1.2.0-3.fc12.6 rpmfusion-free-rawhide kmod-rt2860-PAE.i686 2.1.2.0-3.fc13.7 rpmfusion-free-rawhide kmod-rt2870-PAE.i686 2.1.2.0-3.fc12.6 rpmfusion-free-rawhide kmod-rt2870-PAE.i686 2.1.2.0-5.fc13 rpmfusion-free-rawhide kmod-rt2870-PAE.i686 2.1.2.0-5.fc13 rpmfusion-free-rawhide kmod-rt2870-PAE.i686 2.1.2.0-6.fc13 rpmfusion-free-rawhide kmod-rt3070-PAE.i686 2.1.1.0-3.fc12.6 rpmfusion-free-rawhide kmod-rt3070-PAE.i686 2.1.1.0-3.fc13.7 rpmfusion-free-rawhide kmod-staging-PAE.i686 2.6.31.5-2.fc12.3 rpmfusion-free-rawhide kmod-staging-PAE.i686 2.6.32-0.1.rc8.fc13 rpmfusion-free-rawhide kmod-wl.i686 5.10.91.9.3-4.fc13 rpmfusion-nonfree-rawhide kmod-wl.i686 5.60.48.36-1.fc13 rpmfusion-nonfree-rawhide kmod-wl-PAE.i686 5.10.91.9.3-3.fc12.6 rpmfusion-nonfree-rawhide kmod-wl-PAE.i686 5.10.91.9.3-4.fc13 rpmfusion-nonfree-rawhide kmod-wl-PAE.i686 5.10.91.9.3-4.fc13 rpmfusion-nonfree-rawhide kmod-wl-PAE.i686 5.60.48.36-1.fc13 rpmfusion-nonfree-rawhide lekhonee-gnome.noarch 0.7-2.fc12 fedora lekhonee-gnome.noarch 0.8-2.fc13 fedora mozilla-flash.i386 7.0.25-1.cora CoRA mozilla-flash.i386 7.0.63.0-1.cora CoRA perl-DateTime.i686 0.1901-1 CoRA perl-DateTime.i686 1:0.5300-2.fc13 fedora skype.i586 2.0.0.72-fc5 CoRA skype.i586 2.1.0.47-fc10 CoRA yum-cron.noarch 0.1-1 CoRA yum-cron.noarch 0.9.2-1.fc13 fedora So CoRA (and rpmfusion) repos have multiple versions of some packages, and CoRA has some different versions of packages in fedora (some that I can see I can clean up now). Just started another install with the same repos but a different set of packages and the depedencies stage only took 1 minute (on slower hardware). Other differences:
< slow > fast
< skipx
< clearpart --all --drives=sda,sdb --initlabel
< part raid.100000 --size=128 --ondisk=sda
< part raid.100003 --size=128 --ondisk=sdb
< part raid.100001 --size=10000 --grow --ondisk=sda
< part raid.100004 --size=10000 --grow --ondisk=sdb
< raid /boot --level=RAID1 --device=md0 raid.100000 raid.100003
< raid pv.1 --level=RAID1 --device=md1 raid.100001 raid.100004
< volgroup vg_root pv.1
< logvol / --vgname=vg_root --size=512 --name=root
< logvol swap --fstype=swap --vgname=vg_root --size=2048 --name=swap
< logvol /usr --vgname=vg_root --size=2048 --name=usr
< logvol /var --vgname=vg_root --size=4096 --name=var
< logvol /export --vgname=vg_root --size=1 --name=export --grow
---
> xconfig --startxonboot --defaultdesktop=KDE
> clearpart --linux
> part /boot --size=100
> part / --size=12000
> part swap --recommended
> part /export --size=100 --grow
Perhaps anaconda is doing something silly to make user raid (mdadm) and lvm (lvm2) support is added to the package set?
can you use the same disk config but different pkgs and see if it is fast or slow? and then put back the other pkg selections and see if it is fast or slow? normally, changing one thing at a time makes it easiest to test. Anaconda will make sure packages are added to handle certain device types. For device packages we have:
def selectFSPackages(self, storage):
for device in storage.fsset.devices:
# this takes care of device and filesystem packages
map(self.selectPackage, device.packages)
and
def selectPackage(self, pkg, *args):
try:
mbrs = self.ayum.install(pattern=pkg)
return len(mbrs)
Does this somehow end up with duplicates or get evaluated too many times by yum in the transaction?
Well anaconda forces the installation of various packages required to support whatever filesystems and storage technologies you use during install. For instance: formats/mdraid.py: _packages = ["mdadm"] formats/lvmpv.py: _packages = ["lvm2"] formats/fs.py: _packages = ["e2fsprogs"] However, we don't do anything particularly fancy - just selectPackage on them. Perhaps one of the packages getting pulled in has an inordinate number of file deps that's slowing everything down? I bet it's the number of devices. This slow install is on a box with 10 drives, 2 raid sets, and multiple logical volumes. That loop over all devices looks like you could end up with duplicates.
I change the device section to be just:
clearpart --all --initlabel
part /boot --size=100
part / --size=12000
part swap --recommended
part /export --size=100 --grow
Now I get:
[2010-03-23 15:26:57,502] DEBUG_2 : Adding package pam_passwdqc from group base
[2010-03-23 15:27:53,675] DEBUG_1 : Package: 1:grub-0.97-64.fc13.i686 - already in transaction set
[2010-03-23 15:27:54,798] DEBUG_1 : Package: e2fsprogs-1.41.10-6.fc13.i686 - already in transaction set
[2010-03-23 15:27:55,900] DEBUG_1 : Package: e2fsprogs-1.41.10-6.fc13.i686 - already in transaction set
.....
[2010-03-23 15:28:42,000] DEBUG_1 : Package: e2fsprogs-1.41.10-6.fc13.i686 - already in transaction set
[2010-03-23 15:28:43,116] DEBUG_1 : Package: authconfig-6.0.2-1.fc13.i686 - already in transaction set
[2010-03-23 15:28:45,686] DEBUG_2 : Checking deps for CoRA.noarch 0:1.0-1 - u
[2010-03-23 15:28:45,687] DEBUG_2 : looking for ('config(CoRA)', 'EQ', ('0', '1.0', '1')) as a requirement of CoRA.noarch 0:1.0-1 - u
So much faster, though still lots of duplicated e2fsprogs lines:
grep -F 'DEBUG_1 : Package: e2fsprogs-1.41.10-6.fc13.i686 - already in transaction set' /tmp/yum.log | wc -l
40
Is it possible for you to tweak the anaconda image to change selectPackage to:
def selectPackage(self, pkg, *args):
if self.ayum.tsInfo.matchNaevr(name=pkg):
return 0
try:
mbrs = self.ayum.install(pattern=pkg)
return len(mbrs)
except yum.Errors.InstallError:
log.debug("no package matching %s" %(pkg,))
return 0
...ie. just add the two lines at the top?
Sure. Now with full raid/lvm config I get: [2010-03-29 10:18:20,446] DEBUG_2 : Adding package pam_passwdqc from group base [2010-03-29 10:19:19,701] DEBUG_2 : Checking deps for CoRA.noarch 0:1.0-1 - u 10:18:14,752 INFO anaconda: moving (1) to step basepkgsel 10:18:14,753 DEBUG anaconda: basepkgsel is a direct step 10:18:27,370 DEBUG anaconda: no such package java-1.6.0-sun to remove 10:18:32,307 DEBUG anaconda: no such package hotplug to remove 10:18:36,118 DEBUG anaconda: no such package java-1.6.0-sun-devel to remove 10:18:44,793 DEBUG anaconda: no such package firstboot-tui to remove 10:18:53,467 DEBUG anaconda: no such package system-config-mouse to remove 10:19:02,227 DEBUG anaconda: no such package bluez-utils to remove 10:19:14,661 INFO anaconda: leaving (1) step basepkgsel 10:19:14,662 INFO anaconda: moving (1) to step postselection 10:19:14,662 DEBUG anaconda: postselection is a direct step 10:19:14,686 INFO anaconda: selected kernel-PAE package for kernel 10:19:46,237 INFO anaconda: leaving (1) step postselection so postselection takes 32 seconds, *much* better! So, given that I see 3 possible approaches: 1. Make .install() do the above check ... I can go either way on this, add more junk to .install() doesn't fill me with joy but it maybe makes some good for weird "yum shell usecases too". Any opinions Seth? 2. Move selectPackage into yum, and add this check there? Certainly, longer term., I think we want to get rid of deselectPackage from anaconda ... or at least make it much smaller. So having both is one way to go. 3. Just add the two lines to anaconda's selectPackage and live with it all for a bit longer, opinions Chris? > 1. Make .install() do the above check ... I can go either way on this, add more > junk to .install() doesn't fill me with joy but it maybe makes some good for > weird "yum shell usecases too". Any opinions Seth? > > 2. Move selectPackage into yum, and add this check there? Certainly, longer > term., I think we want to get rid of deselectPackage from anaconda ... or at > least make it much smaller. So having both is one way to go. Long term, I'd love to get rid of selectPackage and deselectPackage in anaconda. We should sit down one day and see what our differences are. It also seems to me that if adding duplicates makes dependency resolution so slow, you'll want to add a check to yum. > 3. Just add the two lines to anaconda's selectPackage and live with it all for > a bit longer, opinions Chris? I'm fine with adding these two lines to anaconda for now while we work on getting rid of those functions or adding checks into yum. If we want this to be in F13, we're going to have to get people to agree this is a blocker, though. I'll send a patch to a-m-l right now to get this moving. Add the check into install() it doesn't seem like a terribly expensive check and we'll really only ever hit it if someone is calling the same thing over and over and over again. Upstream/rawhide has a fix for this on the yum side, so that repeated .install()/.update() calls should be fast. Adding it to the blocker list to get review. This could cause some pretty significant delays on large disk systems. adding the patch from upstream is completely trivial. A 2 line fix, but boy does that make me nervous (http://git.fedorahosted.org/git/?p=anaconda.git;a=commit;h=ee601630b1b7f72d6728e704a8332e98084236fe) What level of confidence is there in the changes against F-13? If you guys feel good about this, let's pull it into F13. If you think it needs more bake time (which we're in short supply of for F13), can we instead provide this as an updates.img and document affected systems? I'm very confident about the anaconda change ... the yum change to do the same thing is significantly bigger, but even that doesn't worry me too much as it's had a few weeks in rawhide and is less likely to have weird corner cases. |