[9fans] wait race?

[9fans] wait race?

[erik quanstrom]

this command frequently hangs on my terminal
	for(i in `{seq 1 $n}){echo fu>/dev/null&}

i've tried n=50 and n=150.  

acid says the shell is doing this

acid: lstk()
await()+0x7 /sys/src/libc/9syscall/await.s:5
wait()+0x1b /sys/src/libc/9sys/wait.c:13
	buf=0x36373031
	fld=0xdfffcc04
	l=0x35188
	w=0x35190
Waitfor(pid=0x2ae1)+0xb4 /usr/quanstro/src/rc/plan9.c:211
	w=0x35190
	p=0x36e70
	errbuf=0x353a4
Xbackq()+0x158 /usr/quanstro/src/rc/havefork.c:120
	wd=0x303531
	ewd=0xdfffeeef
	stop=0x1dd10
	pfd=0x5
	f=0x35190
	s=0xdfffceef
	v=0x36e70
	c=0xa
	pid=0x2ae1
main(argc=0x1,argv=0xdfffefb4)+0x327 /usr/quanstro/src/rc/exec.c:184
	rcmain=0x1642c
	num=0x35343031
	bootstrap=0x2
	i=0x0
_main+0x31 /sys/src/libc/386/main9.s:16

is this a race, or am i missing something?  (p9p rc does not
hang doing the same thing.)

- erik

Re: [9fans] wait race?

[matt]

>this command frequently hangs on my terminal
>
stop running it then :)

Re: [9fans] wait race?

[geoff]

The cited command doesn't hang my terminal (700MHz Pentium III).
You're not seeing "no procs" messages, are you?  What constitutes a
`hang', given that you can run acid?

The rc binary on sources is older than the sources, so I've pushed out
a current binary, though I don't expect it to fix this problem.

Re: [9fans] wait race?

[matt]

i tried n = 50, 150 & 500

50 & 150 worked fine

500 it stalled on first time so I killed it and re-ran and it was fine 
for 200, 300, 400, 500, 1500

my plan9 is quite old though, it's still kfs for instance

[9fans] ,m0

[Matt]

term% echo '1
    2
    3
    4
    5' > h
term% ed h
10
,m0
,
1
2
3
4
5
q
term % echo Hey Brucee time for more beer, 35 seems not to have been 
enough, that doesn't look reversed to me!

Re: [9fans] ,m0

[Rob Pike]

On 12/17/06, Matt <mattmobile@proweb.co.uk> wrote:
> term% echo '1
>     2
>     3
>     4
>     5' > h
> term% ed h
> 10
> ,m0
> ,
> 1
> 2
> 3
> 4
> 5
> q
> term % echo Hey Brucee time for more beer, 35 seems not to have been
> enough, that doesn't look reversed to me!
>
>
>
>

Re: [9fans] ,m0

[Rob Pike]

why would moving everything as a block reverse it?
try
   g/./m0

-rob

Re: [9fans] ,m0

[Matt]

See Rob, that's why we needed you in the pub, looks like Brucee owes 
Uriel a beer
> why would moving everything as a block reverse it?
> try
>   g/./m0
>
> -rob
>

Re: [9fans] ,m0

[Paul Lalonde]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

That doesn't match blank lines.
g/^/m0

On 17-Dec-06, at 8:41 AM, Rob Pike wrote:

> why would moving everything as a block reverse it?
> try
>   g/./m0
>
> -rob

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.5 (Darwin)

iD8DBQFFhXh/pJeHo/Fbu1wRArvKAKCOxUAoTSDSQk3LDsbJHsiVwbU7bACgo9Mv
p0RmeokFuPdTHaEpPzbmFtg=
=0E0e
-----END PGP SIGNATURE-----

Re: [9fans] ,m0

[Bruce Ellis]

it had the appropriate effect. confused everyone.
i did hesitate when i gave you the solution saying
that i couldn't remember if it was right. it took a
while to get the right wording out of uriel but he
did end up unwittingly saying some very funny things.

brucee

On 12/18/06, Paul Lalonde <plalonde@telus.net> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> That doesn't match blank lines.
> g/^/m0
>
> On 17-Dec-06, at 8:41 AM, Rob Pike wrote:
>
> > why would moving everything as a block reverse it?
> > try
> >   g/./m0
> >
> > -rob
>
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.5 (Darwin)
>
> iD8DBQFFhXh/pJeHo/Fbu1wRArvKAKCOxUAoTSDSQk3LDsbJHsiVwbU7bACgo9Mv
> p0RmeokFuPdTHaEpPzbmFtg=
> =0E0e
> -----END PGP SIGNATURE-----
>

Re: [9fans] wait race?

[Russ Cox]

> this command frequently hangs on my terminal
>         for(i in `{seq 1 $n}){echo fu>/dev/null&}

The back trace looks like rc is still trying to run seq
(it is in Xbackq, which is running the backquote expression)
and has not even gotten to the interesting part.

I might believe that if you ran two in a row:

          for(i in `{seq 1 $n}){echo fu>/dev/null&}
          for(i in `{seq 1 $n}){echo fu>/dev/null&}

then that would make it hanging like that much more likely.

But what it might have seen instead is a read returning -1
because it was interrupted by a sys: child note.  So seq might
not actually be done.  That being said, there would still have to
be a bug in the kernel (or seq), since rc has closed the pipe end
that it is reading at that point, so seq shouldn't be blocked trying
to write to it.

If you can reproduce the "hang", can you run ps and see if
the pid that rc is waiting for (it's in the argument to Waitfor
in the stack trace) is still running?  If so, what's that guy doing,
and is it sed or is it rc?

Russ

Re: [9fans] wait race?

[erik quanstrom]

russ,

you're spot-on, as per usual.  obvously, debugging when tired is
a dangerous thing for me.  i should have noticed the things you've 
pointed out right away.  the second or third cut-and-paste of that
command sequence usually does hang rc, which DEL fixes.

tomorrow, i will try to reproduce things.  (it was quite reliable.)
and see if i can get some more information.

the return value of write /sys/src/cmd/seq,c:84 & 92 is not checked,
but as you noted, that might not be the full story.

- erik

"Russ Cox" <rsc@swtch.com> writes

| 
| > this command frequently hangs on my terminal
| >         for(i in `{seq 1 $n}){echo fu>/dev/null&}
| 
| The back trace looks like rc is still trying to run seq
| (it is in Xbackq, which is running the backquote expression)
| and has not even gotten to the interesting part.
| 
| I might believe that if you ran two in a row:
| 
|           for(i in `{seq 1 $n}){echo fu>/dev/null&}
|           for(i in `{seq 1 $n}){echo fu>/dev/null&}
| 
| then that would make it hanging like that much more likely.
| 
| But what it might have seen instead is a read returning -1
| because it was interrupted by a sys: child note.  So seq might
| not actually be done.  That being said, there would still have to
| be a bug in the kernel (or seq), since rc has closed the pipe end
| that it is reading at that point, so seq shouldn't be blocked trying
| to write to it.
| 
| If you can reproduce the "hang", can you run ps and see if
| the pid that rc is waiting for (it's in the argument to Waitfor
| in the stack trace) is still running?  If so, what's that guy doing,
| and is it sed or is it rc?
| 
| Russ

Re: [9fans] wait race?

[Russ Cox]

I pushed a new /sys/src/9/port/proc.c
that fixes the underlying kernel bug (nothing to do with child notes)
as well as a new /sys/src/cmd/rc/havefork.c
that avoids tickling it.

Russ

Re: [9fans] wait race?

[Steve Simon]

>> for(i in `{seq 1 $n}){echo fu>/dev/null&}

> If you can reproduce the "hang", can you run ps and see if
> the pid that rc is waiting for.

I can reproduce this quite easily, with n=150,
one time in three the script hangs.

Waitfor seems to be waiting for a proc which has already exited.

felix% acid 63541
/proc/63541/text:386 plan 9 executable

/sys/lib/acid/port
/sys/lib/acid/386
acid: lstk()
await()+0x7 /sys/src/libc/9syscall/await.s:5
wait()+0x1b /sys/src/libc/9sys/wait.c:13
	buf=0x35323536
	fld=0xdfffcc04
	l=0x33930
	w=0x33938
Waitfor(pid=0xff7e)+0xb4 /sys/src/cmd/rc/plan9.c:210
	w=0x33938
	p=0x36538
	errbuf=0x33b4c
Xbackq()+0x158 /sys/src/cmd/rc/havefork.c:120
	wd=0x303531
	ewd=0xdfffeeef
	stop=0x1d958
	pfd=0x5
	f=0x33938
	s=0xdfffceef
	v=0x36538
	c=0xa
	pid=0xff7e
main(argc=0x1,argv=0xdfffefb4)+0x327 /sys/src/cmd/rc/exec.c:184
...

0xff7e == 65406

felix% ps
...
steve         63540    0:00   0:00      252K Await    rc
steve         63541    0:00   0:00      252K Await    rc
steve         63546    0:00   0:00      164K Pread    stats
steve         63547    0:00   0:00      168K Pread    stats
steve         63548    0:00   0:00      140K Pread    clock
steve         63549    0:00   0:00      140K Sleep    clock
steve         63550    0:00   0:00      376K Sleep    faces
steve         63551    0:00   0:00      376K Pread    faces
steve         63805    0:00   0:00     1116K Await    rio
steve         63806    0:00   0:00      252K Await    rc
steve         63807    0:00   0:00      124K Pread    nedmail
steve         63960    0:00   0:00     1116K Await    rio
steve         63961    0:00   0:00      252K Await    rc
steve         65153    0:00   0:00        8K Sleep    sleep
steve         65226    0:00   0:00     1116K Await    rio
steve         65227    0:00   0:00      252K Await    rc
steve         65228    0:00   0:00      228K Pread    sam
steve         65229    0:00   0:00      320K Rendez   samterm
steve         65230    0:00   0:00      320K Pread    samterm
steve         65231    0:00   0:00      320K Pread    samterm
steve         65232    0:00   0:00      320K Pread    samterm
steve         65233    0:00   0:00      320K Pread    samterm
steve         65251    0:00   0:00     1116K Await    rio
steve         65252    0:00   0:00      252K Await    rc
steve         65253    0:00   0:00      124K Pread    nedmail
steve         65419    0:00   0:00      200K Pread    ps
felix%