yum check takes two hours, 60% in 2 billion calls to str_eq()

[Lars Ellenberg]

On Mon, Jun 02, 2014 at 01:07:43PM -0400, James Antill wrote:
> On Sun, 2014-06-01 at 18:03 +0200, Lars Ellenberg wrote:
> > 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.
> 
>  Ok, please try the attached patch[1]. It directly asks the rpm indexes
> for an answer, and doesn't bother doing any of the yum side stuff as we
> already know the answer.
> 
> 
> [1] It's measurably faster here, for normal/sane pkgs. But then it's
> doing a lot less :).
> 

I added timing for individual "provides" in the inner loop
of check_provides(); second column is number of calls to str_eq
(which is 0 obviously for the "new" style),
third value is the time it took (seconds.fractions),
"speedup" is "T_new/T_old".

The "interesting" part of two runs of yum check provides,
interleaved,
both interrupted once they reached the "kernel" provides.

config(jpackage-utils)                        3   0.000266790 
config(jpackage-utils)                        0   0.000150919 1.77 x speedup
java-1.6.0-openjdk                          177   0.001138930 
java-1.6.0-openjdk                            0   0.000332117 3.43 x speedup
java-1.6.0-openjdk(x86-64)                  178   0.001145120 
java-1.6.0-openjdk(x86-64)                    0   0.000360966 3.17 x speedup
java_cup                                      7   0.000203848 
java_cup                                      0   0.000096083 2.12 x speedup
java_cup(x86-64)                              8   0.000218153 
java_cup(x86-64)                              0   0.000105858 2.06 x speedup
java_cup-0.10k.jar.so()(64bit)                4   0.000185966 
java_cup-0.10k.jar.so()(64bit)                0   0.000099897 1.86 x speedup
java_cup-runtime-0.10k.jar.so()(64bit)        4   0.000209808 
java_cup-runtime-0.10k.jar.so()(64bit)        0   0.000111103 1.89 x speedup
jline                                         2   0.000190973 
jline                                         0   0.000101089 1.89 x speedup
jpackage-utils                                4   0.000254869 
jpackage-utils                                0   0.000148058 1.72 x speedup
kbd                                           3   0.000252008 
kbd                                           0   0.000157118 1.60 x speedup
kbd(x86-64)                                   4   0.000255108 
kbd(x86-64)                                   0   0.000152111 1.68 x speedup
kbd-misc                                      2   0.000576973 
kbd-misc                                      0   0.000462055 1.25 x speedup
kernel                                    64770   1.586930000 
kernel                                        0   0.015713000 100.99 x speedup
kernel(DSA_verify)                        64806   0.392415000 
kernel(DSA_verify)                            0   0.014446000 27.16 x speedup
kernel(FsmChangeState)                    64812   0.389691000 
kernel(FsmChangeState)                        0   0.014361100 27.14 x speedup
kernel(FsmDelTimer)                       64818   0.385489000 
kernel(FsmDelTimer)                           0   0.014438200 26.70 x speedup
kernel(FsmEvent)                          64824   0.394106000 
kernel(FsmEvent)                              0   0.014229100 27.70 x speedup
kernel(FsmFree)                           64830   0.389760000 
kernel(FsmFree)                               0   0.014483000 26.91 x speedup
kernel-drm                                64779   0.390668000 
kernel-drm                                    0   0.014301100 27.32 x speedup
kernel-drm-nouveau                        64785   0.388427000 
kernel-drm-nouveau                            0   0.014469100 26.85 x speedup
kernel-modeset                            64791   0.387349000 
kernel-modeset                                0   0.014324900 27.04 x speedup
kernel-uname-r                            64797   0.385177000 
kernel-uname-r                                0   0.014467000 26.62 x speedup
kernel-x86_64                             64773   0.407443000 
kernel-x86_64                                 0   0.014701800 27.71 x speedup
kernel-xen                                32280   0.195229000 
kernel-xen                                    0   0.014184000 13.76 x speedup

So yes, that looks like a nice improvement even for packages with
a "short" provides list, and a big improvement for packages with
long provides lists.

If it's functional equivalent: please use!

I'll time a full "yum check" later,
and then an other with cProfile enabled, just for fun.

Thanks,
	Lars