Some notes on speeding up do_package_write_rpm

Some notes on speeding up do_package_write_rpm

[Richard Purdie]

I had a look at why do_package_write_rpm seems slow. It's clear most of
the time is being spent in rpmbuild. Taking the BUILDSPEC script, it was
interesting to run it standalone with "strace -f". The result with
libxfont was a 13.5MB log file showing lots of execs of grep, wc, cut
and other shell utils.

This confirmed suspicion I had that the X.provides and X.requires
scripts that are written out and called by rpmbuild were causing some
performance issues since those scripts are where the grep/wc/cut calls
are coming from.

Rewriting dump_filterdeps() in package_rpm.bbclass to write out a python
script instead of a shell script (doing the same work), resulted in an
strace logfile of 1.5MB, much smaller. The big win is that python has
internal functions for these things so we don't have all the exec()
overhead and don't hit the kernel anywhere near as much.

This showed small improvements in times for some simple package writing
tasks. I then ran "time bitbake eglibc-locale -c package_write_rpm -f"
which I've noticed is one of the last tasks to complete on my standard
build time benchmark atm. The results with shell script (i.e. before):

real	7m15.207s
user	2m31.320s
sys	0m27.720s

and after, with the python script:

real	5m23.727s
user	3m25.540s
sys	1m4.530s

So in real terms its much faster but it claims to be using more user and
sys resources. So it looks to be a performance speedup (and everything
I've done would agree with that) but those user/sys numbers don't make
sense.

I find the first set of numbers odd anyway as how can something spending
2.5 minutes in user and 0.5 minutes in sys making a total of 3 minutes,
take 7.25 minutes to run on a multicore system that is otherwise idle. I
suspect somewhere, the accounting in the kernel is screwing up maybe in
the handling of the many short lived processes we were triggering. The
real numbers correspond with my stopwatch so I'm happy to proceed with
changes in this direction but if anyone does understand why those
numbers would differ like that, I'd be interested to know about it.

Tests to see how much overall this helps our build time are still in
progress.

Cheers,

Richard

Re: Some notes on speeding up do_package_write_rpm

[Khem Raj]

On Wed, Feb 8, 2012 at 6:54 AM, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
> real    7m15.207s
> user    2m31.320s
> sys     0m27.720s
>
> and after, with the python script:
>
> real    5m23.727s
> user    3m25.540s
> sys     1m4.530s
>
> So in real terms its much faster but it claims to be using more user and
> sys resources. So it looks to be a performance speedup (and everything
> I've done would agree with that) but those user/sys numbers don't make
> sense.
>
> I find the first set of numbers odd anyway as how can something spending
> 2.5 minutes in user and 0.5 minutes in sys making a total of 3 minutes,
> take 7.25 minutes to run on a multicore system that is otherwise idle. I
> suspect somewhere, the accounting in the kernel is screwing up maybe in
> the handling of the many short lived processes we were triggering.

yeah could be its so small that it gets rounded off.

The
> real numbers correspond with my stopwatch so I'm happy to proceed with
> changes in this direction but if anyone does understand why those
> numbers would differ like that, I'd be interested to know about it.

I think it could be that there is more parallel threads now. since user+sys
is across all cpus so you see more user+sys but overall real time
is improved so its good.