[gentoo-portage-dev] portage 9999 at commit 2d5e38b495776e5bb2266848a3365667f3ca7233 **SLOW**

[James Cloos]

My typical emerge -upvDN world went up from 10s of minutes to several
hours sometime between portage 37f33e9 and 2d5e38b.

I noticed by way of strace(8) that it access(2)es each ebuild in
/usr/portage on each configured overay 10 times.  Each.

It does so in order from the last overlay in PORTDIR_OVERLAY to the
first.  It is the whole cycle which repeats a total of 10 iterations.

Seems it would be simpler to do the python equiv of ls */*/*.ebuild
in each overlay's top dir, note what ebuilds exist in each overlay
in a data structure, and use that.  Portage shouldn't worry about
any changes which occur in the middle of any single run.  (Which
is not to claim that it currently does, lest that sentence be
misunderstood. :)

Each access(2) is averaging about 300 or so micro seconds.  So about 66
miliseconds per ebuild.  There are 33728 ebuild files in /usr/portage,
so that is about 2226 seconds.  Or nearly 40 minutes just wasting time.

I run it in script(1) these days; /usr/bin/time output for one run was:

4314.78user 305.06system 5:17:03elapsed 24%CPU (0avgtext+0avgdata 4977056maxresident)k
145208inputs+14296outputs (9major+34541240minor)pagefaults 0swaps

So that is on the order of 20 times as long as it used to take.

I looked at git log.  The depgraph commit (62dbcaa4d873784f1) seems to
be the only one in that range which could have an effect.  At least at
first glance.

After doing the 7420160 access(2) calls, it read in some from a file
(the descriptor was closed by the time a was able to run lsof(8) to see
what fd 4 was), seek(2)ing between reads, and then seems to have started
doing the 7420160 access(2) calls again. (!)  As if once wasn't enough. :^/

No wonder the first run took 5+ hours.

(I'm falling asleep at the kbd; I hope I didn't miss any needed edits above.)

-JimC
-- 
James Cloos <cloos@×××××××.com>         OpenPGP: 1024D/ED7DAEA6