UPDATING 20110730

[Andriy Gapon]

on 31/07/2011 22:14 Doug Barton said the following:
> Understood, but I'm not sure what I can do about it unless I can
> reproduce it.

I reproduced the problem by doing a similar kind of upgrade:
$ pkg_delete -f gtk-2.\*
$ portmaster -v atk-2.0.1 gio-fam-backend-2.28.8 glib-2.28.8
gobject-introspection-0.10.8 x11-toolkits/gtk20

Now I see some duality in the problem.

First, let's consider the portmaster side.
Suppose we have two ports A and B that both depend on both of two other ports C
and D.
When portmaster upgrades port C it updates dependency information in ports A and
B, and while doing that it also checks (and potentially updates) dependency
information for port D.
First of all, it's not clear if that check for port D is really required.
Second, I think that portmaster could cache the origin => pkg mapping that it
builds while working on port A, so that it can be readily re-used for port B.
That could also include "negative" mapping where there is no installed pkg for a
given origin.
Why this caching could be useful becomes more evident if there are hundreds of
ports in the A, B, ... class and hundreds of ports in the C, D, ... class.

As it stands now, the above invocation of portmaster searches for an installed
package with an origin of x11-toolkits/gtk20 for 714 times.  Each search
includes grepping */+CONTENTS in /var/db/pkg directory and also executing
pkg_info -q -O x11-toolkits/gtk20.  As far as I can see, each such pkg_info
invocation also performs something very similar to the grep action: it calls
getdirentries(2) on each port subdirectory and then reads +CONTENTS from it.

What I further observe is those pkg_info calls are sometimes quite fast,
sometimes slow and sometimes are very slow like couple dozen seconds.  Given
that there are ~700 pkg_info runs all those delays add up to quite a long period.

And now to my side of the problem.
While "profiling" pkg_info with ktrace I see getdirentries(2) calls sometimes
take quite a while.  And since I have > 1000 ports all those calls do add up.
DTrace shows that the calls are quite fast (~0.3 ms) when there is no actual
disk access, but if it occurs then it introduces a delay on the orders of 1 -
100 milliseconds.
I am really in doubts about what is happening here.  It seems that all the
directory data isn't kept in ZFS ARC for long enough or is squeezed out of it by
some other data (without additional pressure it should easily fit into the ARC).
  And also that somehow disk accesses have quite large latency.  Although svc_t
according to iostat is smaller (5 - 10 ms).  DTrace shows that the thread spends
the time in cv_wait.  So it's possible that the scheduler is also involved here
as its decisions also may add a delay to when the thread becomes runnable again.

-- 
Andriy Gapon