yum check takes two hours, 60% in 2 billion calls to str_eq()
Lars Ellenberg
lars.ellenberg at linbit.com
Sun Jun 1 16:03:00 UTC 2014
On Fri, May 30, 2014 at 05:18:19PM -0400, James Antill wrote:
> On Fri, 2014-05-30 at 16:46 +0200, Lars Ellenberg wrote:
> > Hi there.
> > (Cc me, I'm not subscribed)
> >
> > I've got a "yum check" taking two hours.
> > (really single core CPU time, actually, not much IO going on there, afaics)
>
> That is not normal. Whenever I've seen this kind of problem it's always
> been a problem in the rpm indexes, rpm --rebuilddb might help.
Did that.
Does not help.
> > I cProfiled it.
> >
> > 60% of the time it seems to spend in i18n.str_eq
> >
> > I pastied an SVG (gprof2dot) here: http://paste.fedoraproject.org/105517/raw
> >
> > It does 2001811124 calls to i18n.str_eq
> > Yes, that's 2 billion.
> > ... seems excessive ...
>
> Indeed.
>
> > rpm -qa | wc -l : 716
> > rpm -qa --provides | wc -l : 71774
> > yum-3.2.29-40.el6.centos.noarch
>
> That doesn't seem super excessive.
>
> > Seems like you have some O(2) or worse behaviour below check_provides(),
>
> You can see the code easily enough, it's generic and could be micro
> optimised but it's basically:
>
> for each package pkg:
> for each provide in pkg prov:
> lookup prov in rpmdb and make sure pkg is in the results
Yes.
And somewhere *below* that there seem to be additional
loops, where I don't really understand what is supposed to be happening
there, or what exactly they are looping over,
but it seems to be some linear search?
checkPrco
for (n, f, (e, v, r)) in self.returnPrco(prcotype):
if i18n.str_eq(reqn, n):
return 1
matchingPrcos
for (n, f, (e, v, r)) in self.returnPrco(prcotype):
if not i18n.str_eq(reqn, n):
continue
> ...so it's roughly:
>
> (provide lookup in rpmdb) * (provides in rpmdb)
>
> ...or in your case:
>
> (time rpm -q --whatprovides blah) * 72000
~6900 seconds / 72000 "provides"
that would mean 95 ms lookup time on average.
# time rpm -q --whatprovides does-not-exist --stats
no package provides does-not-exist
total: 1 0.000000 MB 0.002827 secs
digest: 4 0.016060 MB 0.000018 secs
dbget: 6 0.016092 MB 0.000450 secs
real 0m0.025s user 0m0.015s sys 0m0.009s
# time rpm -q --whatprovides bash --stats
bash-4.1.2-15.el6_4.x86_64
total: 1 0.000000 MB 0.004547 secs
digest: 5 0.063624 MB 0.001372 secs
dbget: 7 0.063664 MB 0.000817 secs
real 0m0.027s user 0m0.017s sys 0m0.009s
# time rpm -q --whatprovides kernel --stats
kernel-2.6.32-279.14.1.el6.x86_64
kernel-2.6.32-279.14.1.el6.x86_64
kernel-2.6.32-431.1.2.el6.x86_64
kernel-2.6.32-431.1.2.el6.x86_64
kernel-debug-2.6.32-279.14.1.el6.x86_64
kernel-debug-2.6.32-431.1.2.el6.x86_64
kernel-2.6.32-358.18.1.el6.x86_64
kernel-2.6.32-358.18.1.el6.x86_64
kernel-debug-2.6.32-358.18.1.el6.x86_64
total: 1 0.000000 MB 0.197096 secs
digest: 10 14.959840 MB 0.090771 secs
dbget: 12 14.959944 MB 0.045128 secs
real 0m0.220s user 0m0.173s sys 0m0.046s
Same, adding --nodigest --nosignature
total: 1 0.000000 MB 0.113099 secs
digest: 10 14.959840 MB 0.000140 secs
dbget: 12 14.959944 MB 0.045224 secs
real 0m0.137s user 0m0.087s sys 0m0.049s
Note the factor of >50 in dbget (bash vs kernel)
>
> ...if the rebuild doesn't fix it, I'd try putting print statements in
> rpmsack:check_provides ... to see which package/provide is causing the
> problem.
Ok. So I added a call counter to i18n.str_eq,
and reset that for each "provides" to be checked,
and print processed name and calls_to_str_eq
(and a similar "import mystats; ++calls" to i18n.str_eq):
def check_provides(self):
""" For each package, check that a provides search for it's name (and
everything it provides) finds it. """
problems = []
for pkg in sorted(self.returnPackages()):
for provtup in pkg.provides:
import mystats
mystats.calls_to_str_eq = 0
name, flags, version = provtup
if pkg not in self.getProvides(name, flags, version):
problems.append(RPMDBProblemProvides(pkg, provide=provtup))
break
try:
print "%s %d" % (name, mystats.calls_to_str_eq)
except:
print "??? %d" % (mystats.calls_to_str_eq)
return problems
There are many that seem to hit some cache,
and have a zero call count.
Then there are some small, a few in the 100 or 800 range.
Once it starts to check "kernel" provides, its above 64000:
...
config(glibc) 564
config(ipa-gothic-fonts) 98
font(:lang=aa) 0
libzip.so()(64bit) 89
libzip.so(SUNWprivate_1.1)(64bit) 89
java-1.6.0-openjdk 177
java-1.6.0-openjdk(x86-64) 178
java_cup-0.10k.jar.so()(64bit) 4
jline 2
config(jpackage-utils) 3
jpackage-utils 4
kbd 3
kbd(x86-64) 4
kbd-misc 2
...
kernel 64770
kernel-x86_64 64773
kernel-xen 32280
kernel(FsmChangeState) 64812
kernel(FsmDelTimer) 64818
...
So for each "provides" line of the kernel package
and there are >= ten thousand such provides per kernel package,
it needs to do >= 64 thousand str_eq?
What's happening there?
Lars
More information about the Yum-devel
mailing list