Re: [9fans] env walk

Re: [9fans] env walk

[presotto]

The n**2 comes from the ls M* walking each entry in the environment
with envwalk walking from the first to that entry every time.  All the 
time is spent in the devdir+convM2D in procgen.  The 

	for(e = eg->entries; e && s; e = e->link)
		s--;

is pretty much fleeting even for 1000 entries.  Otherwise the algorithm for
your example would be n**3.

for example:

#include <u.h>
#include <libc.h>

struct X
{
	struct X *next;
};

struct X x[1000];

void
main(void)
{
	struct X *p;
	int i, j;
	
	for(i = 0; i < nelem(x)-1; i++)
		x[i].next = &x[i+1];

	for(i = 0; i < nelem(x); i++)
		for(j = 0, p = x; j < i && p != nil; p = p->next, j++)
			;

}

takes .01 seconds on my crufty old machine.
The advantage to your loop is that you take all the useless stuff
that devdir does out of the inner loop, not too mention the call
itself.

Re: [9fans] env walk

[Sam]

schweet

John had looked at it on Monday and it said Showers Sat-Mon...guess the storm 
got pushed back.

... ok, I'm getting a little excited now.

:)

On Wednesday 09 May 2001 12:58, you wrote:
> The n**2 comes from the ls M* walking each entry in the environment
> with envwalk walking from the first to that entry every time.  All the
> time is spent in the devdir+convM2D in procgen.  The
>
> 	for(e = eg->entries; e && s; e = e->link)
> 		s--;
>
> is pretty much fleeting even for 1000 entries.  Otherwise the algorithm for
> your example would be n**3.
>
> for example:
>
> #include <u.h>
> #include <libc.h>
>
> struct X
> {
> 	struct X *next;
> };
>
> struct X x[1000];
>
> void
> main(void)
> {
> 	struct X *p;
> 	int i, j;
>
> 	for(i = 0; i < nelem(x)-1; i++)
> 		x[i].next = &x[i+1];
>
> 	for(i = 0; i < nelem(x); i++)
> 		for(j = 0, p = x; j < i && p != nil; p = p->next, j++)
> 			;
>
> }
>
> takes .01 seconds on my crufty old machine.
> The advantage to your loop is that you take all the useless stuff
> that devdir does out of the inner loop, not too mention the call
> itself.

-- 


Sam Hopkins
------------------------------------------------
QOTD:
"Design top down, implement bottom up."

Re: [9fans] env walk

[Sam]

ugh...'scuse the flub.

On Wednesday 09 May 2001 13:34, you wrote:
> schweet
>
> John had looked at it on Monday and it said Showers Sat-Mon...guess the
> storm got pushed back.
>
> ... ok, I'm getting a little excited now.
>
> :)
>
> On Wednesday 09 May 2001 12:58, you wrote:
> > The n**2 comes from the ls M* walking each entry in the environment
> > with envwalk walking from the first to that entry every time.  All the
> > time is spent in the devdir+convM2D in procgen.  The
> >
> > 	for(e = eg->entries; e && s; e = e->link)
> > 		s--;
> >
> > is pretty much fleeting even for 1000 entries.  Otherwise the algorithm
> > for your example would be n**3.
> >
> > for example:
> >
> > #include <u.h>
> > #include <libc.h>
> >
> > struct X
> > {
> > 	struct X *next;
> > };
> >
> > struct X x[1000];
> >
> > void
> > main(void)
> > {
> > 	struct X *p;
> > 	int i, j;
> >
> > 	for(i = 0; i < nelem(x)-1; i++)
> > 		x[i].next = &x[i+1];
> >
> > 	for(i = 0; i < nelem(x); i++)
> > 		for(j = 0, p = x; j < i && p != nil; p = p->next, j++)
> > 			;
> >
> > }
> >
> > takes .01 seconds on my crufty old machine.
> > The advantage to your loop is that you take all the useless stuff
> > that devdir does out of the inner loop, not too mention the call
> > itself.

-- 


Sam Hopkins
------------------------------------------------
QOTD:
"Design top down, implement bottom up."

Re: [9fans] env walk

[Peter Schay]

Thanks for looking into this!  Sorry for beating it to death, but...
I still think more time is spent in envgen, because, as you said,
the algorithm is O(n**3).
Also devdir and all the extra qlocking contribute as well.
(see the kprof results below).

I changed your example to be triply nested,
	int i, j, k;
        
	for(i = 0; i < nelem(x)-1; i++)
		x[i].next = &x[i+1];

	for(i = 0; i < nelem(x); i++)
		for(j = 0; j < nelem(x); j++)
			for(k = 0, p = x; k < j && p != nil; p = p->next, k++)
				;

and it took around 11 seconds instead of .01.  This is a good
example of what happens with the triply nested loops of
rc, devwalk, and envgen.

Sorry, the original example I gave was misleading for two reasons.
First, you are right and it does walk to all the /env entries
of course so I should have said this was O(n**3).
I was talking about the time to walk to a *single* entry
being O(n**2).  Indeed the time to walk to all the entries is
O(n**3) which is why it really starts to get slow.

My example was also misleading because the time taken is
not because of ls /env.  You can get a similar delay from forking
any process because rc walks to all the /env entries.  (I think).
The following example is also slow because of the O(n**3) effect,
and it doesn't use ls /env.  

	term% echo startclr > /dev/kpctl
	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 400})^('=1')
	echo `{echo x | wc -c}
	.
	2
	0.14u 3.14s 3.68r 	 /fd/0
	term% echo stop > /dev/kpctl
	term% kprof /n/9fat/9pcdisk /dev/kpdata | sed 12q
	total: 3684	in kernel text: 3528	outside kernel text: 156
	KTZERO 80100000
	ms	  %	sym
	732	 20.7	envgen
	540	 15.3	i8259isr
	348	  9.8	sched
	348	  9.8	runproc
	216	  6.1	lock
	132	  3.7	devdir
	132	  3.7	cycletimer
	132	  3.7	memmove
	96	  2.7	qunlock
	term% 

-Pete

presotto@plan9.bell-labs.com wrote:
> 
> The n**2 comes from the ls M* walking each entry in the environment
> with envwalk walking from the first to that entry every time.  All the
> time is spent in the devdir+convM2D in procgen.  The
> 
>         for(e = eg->entries; e && s; e = e->link)
>                 s--;
> 
> is pretty much fleeting even for 1000 entries.  Otherwise the algorithm for
> your example would be n**3.
> 
> for example:
> 
> #include <u.h>
> #include <libc.h>
> 
> struct X
> {
>         struct X *next;
> };
> 
> struct X x[1000];
> 
> void
> main(void)
> {
>         struct X *p;
>         int i, j;
> 
>         for(i = 0; i < nelem(x)-1; i++)
>                 x[i].next = &x[i+1];
> 
>         for(i = 0; i < nelem(x); i++)
>                 for(j = 0, p = x; j < i && p != nil; p = p->next, j++)
>                         ;
> 
> }
> 
> takes .01 seconds on my crufty old machine.
> The advantage to your loop is that you take all the useless stuff
> that devdir does out of the inner loop, not too mention the call
> itself.

Re: [9fans] env walk

[rog]

i was checking that i wasn't being entirely stupid, and
got a bit confused, because
 a) running rc when it's named 8.out results in a "broken!" prompt
	(slightly bizarre test in /rc/lib/rcmain)
 b) iostats binds #e itself (presumably so you don't see all the crud)

anyway, the results are as follows:

% eval X^(`{seq 400})^('=1')
% iostats rc
% ^D
read      193464 bytes, 1038.069 Kb/sec
write     919 bytes, 896.5644 Kb/sec
protocol  291613 bytes, 70.31562 Kb/sec
rpc       3851 count

Message    Count   Low  High  Time Averg          in      out
clone        497     0     1    11     0 ms     3479     2485 bytes
walk         960     0    15  2437     2 ms    31680    12467 bytes
open         476     0     8  1396     2 ms     2856     6188 bytes
read        1404     0     2   182     0 ms    21060   204696 bytes
write         14     0     1     1     0 ms     1143       98 bytes
clunk        497     0     1    21     0 ms     2485     2485 bytes
stat           2     0     1     1     0 ms       10      242 bytes
attach         1     1     1     1     1 ms      146       26 bytes

Opens    Reads  (bytes)   Writes  (bytes) File
    1        1        2        0        0 /env/X99
    1        1        2        0        0 /env/X89
....

Re: [9fans] env walk

[presotto]

[-- Attachment #1: Type: text/plain, Size: 886 bytes --]

You're right, it's spurious, it does use #e, but this is getting tedious.
I bugged rc.  It really doesn't reread the env's when it starts a new command,
only when rc itself is started.  The time in his example was completely accounted for
by setting the variables, not by forking rc as he claimed.

This isn't to say that if you create a new a few hundred variables and
then restart rc you won't get the variables reread, but that's not
what the example was doing.

I'm not saying that this isn't a problem.  I did two kernel mk's in
a row, one with only the usual dozen or so env's and one with 400+ env's.
The latter was interminable since rc is getting exec'd for every rule.
The ratio of times was about 7 to 1.  With the fix it goes down to
1.75 to 1.  It's the result of the n**3 going to n**2.  Not perfect
but, given that we rarely have that many env's, livable.

[-- Attachment #2: Type: message/rfc822, Size: 1616 bytes --]

From: rog@vitanuova.com
To: 9fans@cse.psu.edu
Subject: Re: [9fans] env walk
Date: Thu, 10 May 2001 14:39:40 +0100
Message-ID: <20010510133208.2132F199E7@mail.cse.psu.edu>

> By the way, it's setting all the env's in your example that takes the
> time, not forking in rc.  Rc doesn't reread the /env's.  If you
> do an iostats on the example you'll see no opens of /env after
> setting the vars:

that's a bit spurious, i'm afraid, because rc opens #e directly so
iostats can't see those accesses.

given that rc does read all the environment variables when it starts
up, i think it's quite likely it's spending a fair amount of time doing
so...

  rog.

Re: [9fans] env walk

[rob pike]

I did some kprofing while running big mks, and the environment
costs almost nothing even before presotto's changes.  For typical
uses around here, the environment isn't big enough to be a problem.
Of course, it's easy to build counterexamples.

/proc was a different matter, but presotto fixed that too.

-rob

Re: [9fans] env walk

[rog]

> By the way, it's setting all the env's in your example that takes the
> time, not forking in rc.  Rc doesn't reread the /env's.  If you
> do an iostats on the example you'll see no opens of /env after
> setting the vars:

that's a bit spurious, i'm afraid, because rc opens #e directly so
iostats can't see those accesses.

given that rc does read all the environment variables when it starts
up, i think it's quite likely it's spending a fair amount of time doing
so...

  rog.

Re: [9fans] env walk

[presotto]

...and before you ask, yes execing a new rc does cause the
env values to be reread.

Re: [9fans] env walk

[presotto]

[-- Attachment #1: Type: text/plain, Size: 2141 bytes --]

We stuck your change into devenv.c.  devproc.c was pretty bad too, since our
cpu servers often have upwards of 300 procs.  It was n**2 for ps which got
unwieldy for a tool rob is building, so we added a hash table to proc.c
to map pid to proctab slot.  Time for ps of our cpu servers goes from
4 seconds to milliseconds.  We'll include both changes in the next update
wrap.

We should probably rethink xxxgen, but for now we'll just speed up the
high runners; even the proc.c hash was only a few lines of code.

By the way, it's setting all the env's in your example that takes the
time, not forking in rc.  Rc doesn't reread the /env's.  If you
do an iostats on the example you'll see no opens of /env after
setting the vars:

% eval X^(`{seq 400})^('=1')
% echo /env/*|wc
      1     448    4443
% iostats rc
% rfork e
% time echo `{echo x | wc -c}
2
0.00u 0.00s 0.17r 	 echo 2
% ^D
read      157530 bytes, 9.022221 Kb/sec
write     95 bytes, 1.325316 Kb/sec
protocol  161425 bytes, 8.131304 Kb/sec
rpc       128 count

Message    Count   Low  High  Time Averg          in      out
clone         17     0     0     0     0 ms      119       85 bytes
walk          30     0   297  1092    36 ms      990      338 bytes
open           9    32   469  1142   126 ms       54      117 bytes
read          50     0 13593 17051   341 ms      750   157930 bytes
write          5     1    62    70    14 ms      175       35 bytes
clunk         14     0    16    31     2 ms       70       70 bytes
stat           2     0     1     1     0 ms       10      242 bytes
attach         1     0     0     0     0 ms      146       26 bytes

Opens    Reads  (bytes)   Writes  (bytes) File
    2        9    28100        0        0 /bin/echo
    1        3       36        0        0 (stdin)
    1        0        0        1        2 (stdout)
    1        0        0        4       93 (stderr)
    1        2      579        0        0 /rc/lib/rcmain
    1       23    87864        0        0 /bin/rc
    1        6    18680        0        0 /bin/time
    1        7    22271        0        0 /bin/wc
% 

[-- Attachment #2: Type: message/rfc822, Size: 4405 bytes --]

From: Peter Schay <pschay@pobox.com>
To: 9fans@cse.psu.edu
Subject: Re: [9fans] env walk
Date: Thu, 10 May 2001 08:33:48 GMT
Message-ID: <3AF9CB94.C507F463@pobox.com>

Thanks for looking into this!  Sorry for beating it to death, but...
I still think more time is spent in envgen, because, as you said,
the algorithm is O(n**3).
Also devdir and all the extra qlocking contribute as well.
(see the kprof results below).

I changed your example to be triply nested,
	int i, j, k;
        
	for(i = 0; i < nelem(x)-1; i++)
		x[i].next = &x[i+1];

	for(i = 0; i < nelem(x); i++)
		for(j = 0; j < nelem(x); j++)
			for(k = 0, p = x; k < j && p != nil; p = p->next, k++)
				;

and it took around 11 seconds instead of .01.  This is a good
example of what happens with the triply nested loops of
rc, devwalk, and envgen.

Sorry, the original example I gave was misleading for two reasons.
First, you are right and it does walk to all the /env entries
of course so I should have said this was O(n**3).
I was talking about the time to walk to a *single* entry
being O(n**2).  Indeed the time to walk to all the entries is
O(n**3) which is why it really starts to get slow.

My example was also misleading because the time taken is
not because of ls /env.  You can get a similar delay from forking
any process because rc walks to all the /env entries.  (I think).
The following example is also slow because of the O(n**3) effect,
and it doesn't use ls /env.  

	term% echo startclr > /dev/kpctl
	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 400})^('=1')
	echo `{echo x | wc -c}
	.
	2
	0.14u 3.14s 3.68r 	 /fd/0
	term% echo stop > /dev/kpctl
	term% kprof /n/9fat/9pcdisk /dev/kpdata | sed 12q
	total: 3684	in kernel text: 3528	outside kernel text: 156
	KTZERO 80100000
	ms	  %	sym
	732	 20.7	envgen
	540	 15.3	i8259isr
	348	  9.8	sched
	348	  9.8	runproc
	216	  6.1	lock
	132	  3.7	devdir
	132	  3.7	cycletimer
	132	  3.7	memmove
	96	  2.7	qunlock
	term% 

-Pete

presotto@plan9.bell-labs.com wrote:
> 
> The n**2 comes from the ls M* walking each entry in the environment
> with envwalk walking from the first to that entry every time.  All the
> time is spent in the devdir+convM2D in procgen.  The
> 
>         for(e = eg->entries; e && s; e = e->link)
>                 s--;
> 
> is pretty much fleeting even for 1000 entries.  Otherwise the algorithm for
> your example would be n**3.
> 
> for example:
> 
> #include <u.h>
> #include <libc.h>
> 
> struct X
> {
>         struct X *next;
> };
> 
> struct X x[1000];
> 
> void
> main(void)
> {
>         struct X *p;
>         int i, j;
> 
>         for(i = 0; i < nelem(x)-1; i++)
>                 x[i].next = &x[i+1];
> 
>         for(i = 0; i < nelem(x); i++)
>                 for(j = 0, p = x; j < i && p != nil; p = p->next, j++)
>                         ;
> 
> }
> 
> takes .01 seconds on my crufty old machine.
> The advantage to your loop is that you take all the useless stuff
> that devdir does out of the inner loop, not too mention the call
> itself.

Re: [9fans] env walk

[Peter Schay]

As far as I can tell, the loop I proposed in envwalk() is a
linear search to walk to an environment variable.

The devwalk+envgen algorithm is n squared because the loop in envgen
is nested within the loop in devwalk.  It's amazing how that tiny
little loop in envgen can eat up time!

Pete


presotto@plan9.bell-labs.com wrote:
> 
> All the devices that use devwalk have n squared behavior.  It wasn't
> supposed to be a problem because n isn't supposed to be large for them.
> I agree that it's short sighted for something with potentially many files
> like #e.  Your solution is also O(n**2), though the constant
> is much smaller (no devdir inside the loop).  I'll replace the devwalk
> with your search and put it on the next update wrap.
> 
> Also, on network performance, we played a bunch with TCP speed after
> Dong Lin showed us how slow we were.  Last we tested our TCP stack,
> we came out somewhere between Linux and FreeBSD in speed between 2
> 500 MHZ Pentiums on a 100meg ether.  That's partially why loopbackmedium
> appeared, to see how much was stack and how much driver.  I'll run
> a new set of tests in a few weeks and post when I'm done.
> Since both all 3 OS's are moving targets, the validity
> of the tests is transient.  Sic transit perfunctio.

Re: [9fans] env walk

[presotto]

[-- Attachment #1: Type: text/plain, Size: 925 bytes --]

All the devices that use devwalk have n squared behavior.  It wasn't
supposed to be a problem because n isn't supposed to be large for them.
I agree that it's short sighted for something with potentially many files
like #e.  Your solution is also O(n**2), though the constant
is much smaller (no devdir inside the loop).  I'll replace the devwalk
with your search and put it on the next update wrap.

Also, on network performance, we played a bunch with TCP speed after
Dong Lin showed us how slow we were.  Last we tested our TCP stack,
we came out somewhere between Linux and FreeBSD in speed between 2
500 MHZ Pentiums on a 100meg ether.  That's partially why loopbackmedium
appeared, to see how much was stack and how much driver.  I'll run
a new set of tests in a few weeks and post when I'm done.
Since both all 3 OS's are moving targets, the validity
of the tests is transient.  Sic transit perfunctio.

[-- Attachment #2: Type: message/rfc822, Size: 3358 bytes --]

From: Peter Schay <pschay@pobox.com>
To: 9fans@cse.psu.edu
Subject: [9fans] env walk
Date: Wed, 9 May 2001 11:54:30 GMT
Message-ID: <3AF92776.18AE2A42@pobox.com>

This posting got truncated at the ".".  2nd attempt:

Here's more on the performance subject; I hope the
following optimization is useful and not too inelegant.

The algorithm for walking in #e seems to be O(n*n).
I think it's pretty easy to make it O(n).

For example, on my system the following script takes no
time with 42 environment variables takes 4 seconds with
441 vars:

	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 1})^('=1')
	echo nvars `{ls /env | wc -l}
	.
	nvars 42
	0.01u 0.02s 0.06r        /fd/0

	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 400})^('=1')
	echo nvars `{ls /env | wc -l}
	.
	nvars 441
	0.14u 3.59s 4.14r        /fd/0

(OK, this was an abusive script.  But the effect can be
noticable for non-abusers too.)

Usually you really only lose time when rc forks, I think,
and even then not always.  I'm not exactly sure.

Changing envwalk() has a big impact on large (ok, bloated)
make projects.  Even on the small job of compiling the
Plan 9 kernel you save a few per cent of system time.  And I'm
sure there are many truly abusive projects out there that
could build much faster.

IMHO, rc and mk are masterpieces and it's a shame
to limit them by wasting time on walks in #e.

So here's a proposed optimization of envwalk(), to avoid
spending too much time in envgen():

term% diff /sys/src/9/port/devenv.c .
60c60,78
<       return devwalk(c, name, 0, 0, envgen);
---
>       Evalue *e;
>       Egrp *eg = up->egrp;
> 
>       isdir(c);
>       if(name[0]=='.' && name[1]==0)
>               return 1;
> 
>       qlock(eg);
>       for(e = eg->entries; e; e = e->link)
>               if(!strcmp(e->name, name))
>                       break;
>       if(e) {
>               c->qid = e->qid;
>               qunlock(eg);
>               return 1;
>       }
>       qunlock(eg);
>       strncpy(up->error, Enonexist, NAMELEN);
>       return 0;
\x01\x01\x01\x01

[9fans] env walk

[Peter Schay]

This posting got truncated at the ".".  2nd attempt:

Here's more on the performance subject; I hope the
following optimization is useful and not too inelegant.

The algorithm for walking in #e seems to be O(n*n).
I think it's pretty easy to make it O(n).

For example, on my system the following script takes no
time with 42 environment variables takes 4 seconds with
441 vars:

	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 1})^('=1')
	echo nvars `{ls /env | wc -l}
	.
	nvars 42
	0.01u 0.02s 0.06r        /fd/0

	term% time /fd/0 <<.
	#!/bin/rc
	rfork e
	eval X^(`{seq 400})^('=1')
	echo nvars `{ls /env | wc -l}
	.
	nvars 441
	0.14u 3.59s 4.14r        /fd/0

(OK, this was an abusive script.  But the effect can be
noticable for non-abusers too.)

Usually you really only lose time when rc forks, I think,
and even then not always.  I'm not exactly sure.

Changing envwalk() has a big impact on large (ok, bloated)
make projects.  Even on the small job of compiling the
Plan 9 kernel you save a few per cent of system time.  And I'm
sure there are many truly abusive projects out there that
could build much faster.

IMHO, rc and mk are masterpieces and it's a shame
to limit them by wasting time on walks in #e.

So here's a proposed optimization of envwalk(), to avoid
spending too much time in envgen():

term% diff /sys/src/9/port/devenv.c .
60c60,78
<       return devwalk(c, name, 0, 0, envgen);
---
>       Evalue *e;
>       Egrp *eg = up->egrp;
> 
>       isdir(c);
>       if(name[0]=='.' && name[1]==0)
>               return 1;
> 
>       qlock(eg);
>       for(e = eg->entries; e; e = e->link)
>               if(!strcmp(e->name, name))
>                       break;
>       if(e) {
>               c->qid = e->qid;
>               qunlock(eg);
>               return 1;
>       }
>       qunlock(eg);
>       strncpy(up->error, Enonexist, NAMELEN);
>       return 0;
\x01\x01\x01\x01