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.