test: timeout on Plan 9

[0intro]

What steps will reproduce the problem?

The Go builder on Plan 9 is regularly timing out
while running "go run run.go" in the test directory.

See http://build.golang.org/log/fb585389f807e12ef8c6982c245a073e037b10df

What is the expected output? What do you see instead?

djc             295    0:00   0:00      244K Await    gobuilder /bin/gobuilder
djc             342    0:01   0:05   796404K Pread    builder -cmdTimeout=30m0s
plan9-386-cnielsen
djc             343    0:00   0:00   796404K Semacqui builder
djc             344    0:00   0:00   796404K Semacqui builder
djc             345    0:02   0:21   796404K Await    builder
djc             349    0:01   0:08   796404K Pread    builder
djc             353    0:01   0:13   796404K Pread    builder
djc             355    0:01   0:07   796404K Await    builder
djc             356    0:01   0:08   796404K Tsemacqu builder
djc             367    0:01   0:10   796404K Pread    builder
djc            3729    0:01   0:04   796404K Tsemacqu builder
bootes       125923    0:00   0:00   575196K Rendez   venti ?
djc          137032    0:00   0:00      240K Await    all.rc -e
/tmp/gobuilder/plan9-386-cnielsen-a3b2bc0b515e/go/src/all.rc
djc          137898    0:00   0:00      240K Await    run.rc -e ./run.rc --no-rebuild
djc          140340    0:00   0:00      240K Await    run.rc
djc          140343    0:00   0:00       48K Await    time go run run.go
djc          140344    0:00   0:00   795388K Await    go run run.go
djc          140345    0:00   0:00   795388K Semacqui go
djc          140346    0:00   0:00   795388K Tsemacqu go
djc          140347    0:00   0:00   795388K Semacqui go
djc          140349    0:00   0:00   795388K Semacqui go
djc          140351    0:00   0:00   792124K Pread   
/tmp/go-build107725360/command-line-arguments/_obj/exe/run
djc          140352    0:00   0:00   792124K Semacqui run
djc          140353    0:00   0:00   792124K Tsemacqu run
djc          140354    0:00   0:00   792124K Await    run
djc          140359    0:00   0:00   792124K Semacqui run
djc          140464    0:00   0:00   795460K Await    go run bom.go
djc          140465    0:00   0:00   795460K Semacqui go
djc          140466    0:00   0:00   795460K Tsemacqu go
djc          140467    0:00   0:00   795460K Semacqui go
djc          140470    0:00   0:00   795460K Semacqui go
djc          140471    0:00   0:00   790860K Semacqui
/tmp/go-build095028545/command-line-arguments/_obj/exe/bom

cpu% acid 140351
/proc/140351/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: asm(*PC)
syscall.Syscall6+0x1a 0x000ca47a    MOVL    AX,0x20(SP)
syscall.Syscall6+0x1e 0x000ca47e    MOVL    $0x0,0x24(SP)
syscall.Syscall6+0x26 0x000ca486    CMPL    AX,$0xffffffff
syscall.Syscall6+0x29 0x000ca489    JNE syscall.Syscall6+0x45(SB)
syscall.Syscall6+0x2b 0x000ca48b    SUBL    $0x8,SP
syscall.Syscall6+0x2e 0x000ca48e    CALL    runtime.errstr(SB)
syscall.Syscall6+0x33 0x000ca493    MOVL    SP,SI
syscall.Syscall6+0x35 0x000ca495    ADDL    $0x8,SP
syscall.Syscall6+0x38 0x000ca498    LEAL    0x28(SP),DI
syscall.Syscall6+0x3c 0x000ca49c    CLD
syscall.Syscall6+0x3d 0x000ca49d    MOVSL   (SI),(DI)
syscall.Syscall6+0x3e 0x000ca49e    MOVSL   (SI),(DI)
syscall.Syscall6+0x3f 0x000ca49f    CALL    runtime.exitsyscall(SB)
syscall.Syscall6+0x44 0x000ca4a4    RET
syscall.Syscall6+0x45 0x000ca4a5    LEAL    runtime.emptystring(SB),SI
syscall.Syscall6+0x4b 0x000ca4ab    JMP syscall.Syscall6+0x38(SB)
syscall.Syscall6+0x4d 0x000ca4ad    ADDB    AL,0x0(AX)
syscall.Syscall6+0x4f 0x000ca4af    ADDB    CL,0x8d042444(BX)
acid: regs()
PC  0x000ca47a syscall.Syscall6+0x1a  ?file?:0
SP  0x304687d0 ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0xf010001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000032 BX   0x1036c008 CX   0x002443ec DX   0xffffffff
DI  0x304687ec SI   0x304687f0 BP   0x104d02a0
acid: �
echo kill > /proc/140351/ctl

cpu% acid 140471
/proc/140471/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: asm(*PC)
runtime.plan9_semacquire+0x7 0x00021407 RET
runtime.plan9_semacquire+0x8 0x00021408 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0002140a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0002140c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0002140e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x00021410    MOVL    $0x34,AX
acid: regs()
PC  0x00021407 runtime.plan9_semacquire+0x7  ?file?:0
SP  0xdfffee78 ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0xf010001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000025 BX   0x0012c874 CX   0x00000001 DX   0x00000001
DI  0x00010e50 SI   0x0012c180 BP   0x0012c000
acid: �
echo kill > /proc/140471/ctl

[ality]

Comment 1:

This should be fixed by my signal handling CL: https://golang.org/cl/9796043/

Status changed to Started.

[0intro]

Comment 2:

With the current Go (08dcdcdb757b), it's still hanging on:
djc           15008    0:00   0:00   792860K Pread   
/tmp/go-build677230928/command-line-arguments/_obj/exe/run
djc           15855    0:00   0:00   790844K Semacqui
/tmp/go-build151474037/command-line-arguments/_obj/exe/initialize
cpu% acid 15008
/proc/15008/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: stk()
syscall.Syscall6()+0x1a ?file?:0
syscall.Pread(syscall.err=0x0,syscall.n=0x1017c1,syscall.offset=0xffffffff,syscall.p=0x103d4e00,syscall.fd=0x5)+0x99
?file?:0
syscall.Read(syscall.err=0x0,syscall.n=0x200,syscall.p=0x103d4e00,syscall.fd=0x5)+0x72
?file?:0
os.(*File).read(os.err=0x0,os.n=0x0,os.b=0x103d4e00,os.f=0x10578770)+0x67 ?file?:0
os.(*File).Read(os.err=0x0,os.n=0x27dfb,os.b=0x103d4e00,os.f=0x10578770)+0x95 ?file?:0
bytes.(*Buffer).ReadFrom(bytes.err=0x0,bytes.n=0x0,bytes.r=0x30379410,bytes.b=0x104fc0c0)+0x1e3
?file?:0
io.Copy(io.err=0x0,io.written=0x0,io.src=0x30379410,io.dst=0x30379428)+0x125 ?file?:0
os/exec.func·003(os/exec.~r0=0x0)+0x72 ?file?:0
os/exec.func·004(os/exec.fn=0x1062ed80)+0x3a ?file?:0
runtime.goexit()+0x0 ?file?:0
0x1062ed80 ?file?:0
acid: asm(*PC)
syscall.Syscall6+0x1a 0x000cc0da    MOVL    AX,0x20(FP)
syscall.Syscall6+0x1e 0x000cc0de    MOVL    $0x0,0x24(FP)
syscall.Syscall6+0x26 0x000cc0e6    CMPL    AX,$0xffffffff
syscall.Syscall6+0x29 0x000cc0e9    JNE syscall.Syscall6+0x45(SB)
syscall.Syscall6+0x2b 0x000cc0eb    SUBL    $0x8,SP
syscall.Syscall6+0x2e 0x000cc0ee    CALL    runtime.errstr(SB)
syscall.Syscall6+0x33 0x000cc0f3    MOVL    SP,SI
syscall.Syscall6+0x35 0x000cc0f5    ADDL    $0x8,SP
syscall.Syscall6+0x38 0x000cc0f8    LEAL    0x28(FP),DI
syscall.Syscall6+0x3c 0x000cc0fc    CLD
syscall.Syscall6+0x3d 0x000cc0fd    MOVSL   (SI),(DI)
syscall.Syscall6+0x3e 0x000cc0fe    MOVSL   (SI),(DI)
syscall.Syscall6+0x3f 0x000cc0ff    CALL    runtime.exitsyscall(SB)
syscall.Syscall6+0x44 0x000cc104    RET
syscall.Syscall6+0x45 0x000cc105    LEAL    runtime.emptystring(SB),SI
syscall.Syscall6+0x4b 0x000cc10b    JMP syscall.Syscall6+0x38(SB)
syscall.Syscall6+0x4d 0x000cc10d    ADDB    AL,0x0(AX)
syscall.Syscall6+0x4f 0x000cc10f    ADDB    CL,0x8d042444(BX)
acid: regs()
PC  0x000cc0da syscall.Syscall6+0x1a  ?file?:0
SP  0x3047fdd4 ECODE 0xf010083e EFLAG 0x00000202
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000032 BX   0x10380008 CX   0x0025286c DX   0xffffffff
DI  0x3047fdf0 SI   0x3047fdf4 BP   0x1062ed20
acid: �
echo kill > /proc/15008/ctl
cpu% acid 15855
/proc/15855/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: stk()
runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x37 ?file?:0
runtime.notesleep()+0xd0 ?file?:0
stopm()+0xcd ?file?:0
exitsyscall0()+0xbe ?file?:0
runtime.mcall()+0x36 ?file?:0
0x10230280 ?file?:0
acid: asm(*PC)
runtime.plan9_semacquire+0x7 0x00022647 RET
runtime.plan9_semacquire+0x8 0x00022648 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0002264a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0002264c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0002264e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x00022650    MOVL    $0x34,AX
acid: regs()
PC  0x00022647 runtime.plan9_semacquire+0x7  ?file?:0
SP  0xdfffee78 ECODE 0xf010083e EFLAG 0x00000202
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000025 BX   0x0011b254 CX   0x00000001 DX   0x00000001
DI  0x00011e70 SI   0x0011ab60 BP   0x0011a9e0
acid: �
echo kill > /proc/15855/ctl

[ality]

Comment 3:

I can't seem to reproduce this anymore. Were those the only two procs left running?

[0intro]

Comment 4:

Here is a shorter way to reproduce this issue:
% cd test
% for(i in `{seq 1 400})
      go run run.go -- fixedbugs/bug056.go

[0intro]

Comment 5:

Here are all the remaining processes when the issue happens on the builder.
djc         1352344    0:00   0:00      240K Await    all.rc -e
/tmp/gobuilder/plan9-386-cnielsen-4450c84265f0/go/src/all.rc
djc         1353199    0:00   0:00      240K Await    run.rc -e ./run.rc --no-rebuild
djc         1355818    0:00   0:00      240K Await    run.rc
djc         1355821    0:00   0:00       48K Await    time go run run.go
djc         1355822    0:00   0:00   795648K Await    go run run.go
djc         1355823    0:00   0:00   795648K Semacqui go
djc         1355824    0:00   0:00   795648K Semacqui go
djc         1355825    0:00   0:00   795648K Tsemacqu go
djc         1355827    0:00   0:00   795648K Semacqui go
djc         1355831    0:01   0:07   792872K Pread   
/tmp/go-build525020060/command-line-arguments/_obj/exe/run
djc         1355832    0:00   0:00   792872K Semacqui run
djc         1355833    0:01   0:04   792872K Tsemacqu run
djc         1355834    0:01   0:01   792872K Semacqui run
djc         1355839    0:00   0:00   792872K Semacqui run
djc         1360254    0:22   0:54   788976K Sleep    bug327
djc         1371668    0:12   1:11   796976K Await    builder
djc         1381927    0:04   0:26   796976K Await    builder
/proc/1353199/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: await()+0x7 /sys/src/libc/9syscall/await.s:5
wait()+0x1b /sys/src/libc/9sys/wait.c:13
Waitfor(pid=0x14b02a)+0x28 /sys/src/cmd/rc/plan9.c:224
Xsubshell()+0x33 /sys/src/cmd/rc/havefork.c:205
main(argc=0x3,argv=0xdfffef84)+0x34e /sys/src/cmd/rc/exec.c:185
_main+0x31 /sys/src/libc/386/main9.s:16
acid: await+0x7 0x00013ff7  RET
_mulv 0x00013ff8    MOVL    r+0x0(FP),CX
acid: PC    0x00013ff7 await+0x7  /sys/src/libc/9syscall/await.s:5
SP  0xdfffebf0 ECODE 0xf010083e EFLAG 0x00000292
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x0000002f BX   0x00000000 CX   0x000001ff DX   0x0014b02a
DI  0x00000001 SI   0x0001b178 BP   0x0014b02a
acid: 
echo kill > /proc/1353199/ctl
/proc/1355818/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: await()+0x7 /sys/src/libc/9syscall/await.s:5
wait()+0x1b /sys/src/libc/9sys/wait.c:13
Waitfor(pid=0x14b02d)+0x28 /sys/src/cmd/rc/plan9.c:224
Xsimple()+0x1a4 /sys/src/cmd/rc/simple.c:70
main(argc=0x3,argv=0xdfffef84)+0x34e /sys/src/cmd/rc/exec.c:185
_main+0x31 /sys/src/libc/386/main9.s:16
acid: await+0x7 0x00013ff7  RET
_mulv 0x00013ff8    MOVL    r+0x0(FP),CX
acid: PC    0x00013ff7 await+0x7  /sys/src/libc/9syscall/await.s:5
SP  0xdfffebe0 ECODE 0xf010083e EFLAG 0x00000296
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x0000002f BX   0x00000000 CX   0x000001ff DX   0x0014b02d
DI  0x00000001 SI   0x0001b178 BP   0x0014b02d
acid: 
echo kill > /proc/1355818/ctl
/proc/1355821/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: await()+0x7 /sys/src/libc/9syscall/await.s:5
wait()+0x1b /sys/src/libc/9sys/wait.c:13
main(argc=0x4,argv=0xdfffef8c)+0x5c /sys/src/cmd/time.c:39
_main+0x31 /sys/src/libc/386/main9.s:16
acid: await+0x7 0x00005938  RET
write 0x00005939    SUBL    $0x14,SP
acid: PC    0x00005938 await+0x7  /sys/src/libc/9syscall/await.s:5
SP  0xdfffec64 ECODE 0xf010083e EFLAG 0x00000292
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x0000002f BX   0x00000001 CX   0x000001ff DX   0x0001af58
DI  0xdfffea06 SI   0x0001e3dd BP   0x0001da18
acid: 
echo kill > /proc/1355821/ctl
/proc/1355831/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: syscall.Syscall6()+0x1a ?file?:0
syscall.Pread(syscall.err=0x0,syscall.n=0x1040a1,syscall.offset=0xffffffff,syscall.p=0x1716be00,syscall.fd=0x5)+0x9a
?file?:0
syscall.Read(syscall.err=0x0,syscall.n=0x200,syscall.p=0x1716be00,syscall.fd=0x5)+0x72
?file?:0
os.(*File).read(os.err=0x0,os.n=0x0,os.b=0x1716be00,os.f=0x103817d8)+0x67 ?file?:0
os.(*File).Read(os.err=0x0,os.n=0x281cb,os.b=0x1716be00,os.f=0x103817d8)+0xa2 ?file?:0
bytes.(*Buffer).ReadFrom(bytes.err=0x0,bytes.n=0x0,bytes.r=0x3037c3a0,bytes.b=0x103c0fc0)+0x208
?file?:0
io.Copy(io.err=0x0,io.written=0x0,io.src=0x3037c3a0,io.dst=0x3037c3b8)+0x146 ?file?:0
os/exec.func·003(os/exec.~r0=0x0)+0x73 ?file?:0
os/exec.func·004(os/exec.fn=0x10ad8950)+0x3b ?file?:0
runtime.goexit()+0x0 ?file?:0
0x10ad8950 ?file?:0
acid: syscall.Syscall6+0x1a 0x000ce36a  MOVL    AX,0x20(FP)
syscall.Syscall6+0x1e 0x000ce36e    MOVL    $0x0,0x24(FP)
syscall.Syscall6+0x26 0x000ce376    CMPL    AX,$0xffffffff
syscall.Syscall6+0x29 0x000ce379    JNE syscall.Syscall6+0x45(SB)
syscall.Syscall6+0x2b 0x000ce37b    SUBL    $0x8,SP
syscall.Syscall6+0x2e 0x000ce37e    CALL    runtime.errstr(SB)
syscall.Syscall6+0x33 0x000ce383    MOVL    SP,SI
syscall.Syscall6+0x35 0x000ce385    ADDL    $0x8,SP
syscall.Syscall6+0x38 0x000ce388    LEAL    0x28(FP),DI
syscall.Syscall6+0x3c 0x000ce38c    CLD
syscall.Syscall6+0x3d 0x000ce38d    MOVSL   (SI),(DI)
syscall.Syscall6+0x3e 0x000ce38e    MOVSL   (SI),(DI)
syscall.Syscall6+0x3f 0x000ce38f    CALL    runtime.exitsyscall(SB)
syscall.Syscall6+0x44 0x000ce394    RET
syscall.Syscall6+0x45 0x000ce395    LEAL    runtime.emptystring(SB),SI
syscall.Syscall6+0x4b 0x000ce39b    JMP syscall.Syscall6+0x38(SB)
syscall.Syscall6+0x4d 0x000ce39d    ADDB    AL,0x0(AX)
syscall.Syscall6+0x4f 0x000ce39f    ADDB    CL,0x8d042444(BX)
acid: PC    0x000ce36a syscall.Syscall6+0x1a  ?file?:0
SP  0x305a8dd4 ECODE 0xf010083e EFLAG 0x00000202
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000032 BX   0x10384008 CX   0x0025584c DX   0xffffffff
DI  0x305a8df0 SI   0x305a8df4 BP   0x10ad8920
acid: 
echo kill > /proc/1355831/ctl
/proc/1355832/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x37 ?file?:0
runtime.notesleep()+0xd0 ?file?:0
sysmon()+0x29b ?file?:0
runtime.mstart()+0xc1 ?file?:0
runtime.rfork+0x43 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x0002f227   RET
runtime.plan9_semacquire+0x8 0x0002f228 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0002f22a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0002f22c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0002f22e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x0002f230    MOVL    $0x34,AX
acid: PC    0x0002f227 runtime.plan9_semacquire+0x7  ?file?:0
SP  0x1039ff5c ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000025 BX   0x00255850 CX   0x00000001 DX   0x00000001
DI  0x103ba000 SI   0x0001c290 BP   0x00255800
acid: 
echo kill > /proc/1355832/ctl
/proc/1355833/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x37 ?file?:0
runtime.notesleep()+0xd0 ?file?:0
stopm()+0xcd ?file?:0
findrunnable()+0x2eb ?file?:0
schedule()+0xeb ?file?:0
park0()+0xe8 ?file?:0
runtime.mcall()+0x36 ?file?:0
0x1036c320 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x0002f227   RET
runtime.plan9_semacquire+0x8 0x0002f228 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0002f22a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0002f22c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0002f22e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x0002f230    MOVL    $0x34,AX
acid: PC    0x0002f227 runtime.plan9_semacquire+0x7  ?file?:0
SP  0x103b5f3c ECODE 0xf010083e EFLAG 0x00000202
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000025 BX   0x10388354 CX   0x00000001 DX   0x00000001
DI  0x000835cf SI   0x00000000 BP   0x00255800
acid: 
echo kill > /proc/1355833/ctl
/proc/1355834/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_tsemacquire()+0x7 ?file?:0
runtime.semasleep()+0x86 ?file?:0
notetsleep()+0xda ?file?:0
runtime.notetsleepg()+0xa4 ?file?:0
runtime.MHeap_Scavenger()+0xc2 ?file?:0
runtime.goexit ?file?:0
acid: runtime.plan9_tsemacquire+0x7 0x0002f237  RET
runtime.plan9_tsemacquire+0x8 0x0002f238    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xa 0x0002f23a    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xc 0x0002f23c    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xe 0x0002f23e    ADDB    AL,0x0(AX)
runtime.notify 0x0002f240   MOVL    $0x1c,AX
acid: PC    0x0002f237 runtime.plan9_tsemacquire+0x7  ?file?:0
SP  0x3048af34 ECODE 0xf010083e EFLAG 0x00000202
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000034 BX   0xffffffff CX   0x0000ea60 DX   0x0000ea60
DI  0x000f4240 SI   0x00000000 BP   0x0000ea60
acid: 
echo kill > /proc/1355834/ctl
/proc/1355839/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x37 ?file?:0
runtime.notesleep()+0xd0 ?file?:0
stopm()+0xcd ?file?:0
findrunnable()+0x2eb ?file?:0
schedule()+0xeb ?file?:0
park0()+0xe8 ?file?:0
runtime.mcall()+0x36 ?file?:0
0x1036c320 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x0002f227   RET
runtime.plan9_semacquire+0x8 0x0002f228 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0002f22a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0002f22c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0002f22e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x0002f230    MOVL    $0x34,AX
acid: PC    0x0002f227 runtime.plan9_semacquire+0x7  ?file?:0
SP  0x103b9f3c ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0xf010001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x00000025 BX   0x103888d4 CX   0x00000001 DX   0x00000001
DI  0x0000488d SI   0x00000000 BP   0x00255800
acid: 
echo kill > /proc/1355839/ctl
/proc/1371668/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: syscall.Syscall()+0x17 ?file?:0
syscall.await(syscall.err=0x0,syscall.n=0x10713412,syscall.s=0x111e3d18)+0x7d ?file?:0
syscall.Await(syscall.err=0x0,syscall.w=0x10927520)+0xc4 ?file?:0
syscall.func·001()+0x187 ?file?:0
runtime.goexit ?file?:0
acid: syscall.Syscall+0x17 0x00106e57   MOVL    AX,0x14(FP)
syscall.Syscall+0x1b 0x00106e5b MOVL    $0x0,0x18(FP)
syscall.Syscall+0x23 0x00106e63 CMPL    AX,$0xffffffff
syscall.Syscall+0x26 0x00106e66 JNE syscall.Syscall+0x42(SB)
syscall.Syscall+0x28 0x00106e68 SUBL    $0x8,SP
syscall.Syscall+0x2b 0x00106e6b CALL    runtime.errstr(SB)
syscall.Syscall+0x30 0x00106e70 MOVL    SP,SI
syscall.Syscall+0x32 0x00106e72 ADDL    $0x8,SP
syscall.Syscall+0x35 0x00106e75 LEAL    0x1c(FP),DI
syscall.Syscall+0x39 0x00106e79 CLD
syscall.Syscall+0x3a 0x00106e7a MOVSL   (SI),(DI)
syscall.Syscall+0x3b 0x00106e7b MOVSL   (SI),(DI)
syscall.Syscall+0x3c 0x00106e7c CALL    runtime.exitsyscall(SB)
syscall.Syscall+0x41 0x00106e81 RET
syscall.Syscall+0x42 0x00106e82 LEAL    runtime.emptystring(SB),SI
syscall.Syscall+0x48 0x00106e88 JMP syscall.Syscall+0x35(SB)
syscall.Syscall+0x4a 0x00106e8a ADDB    AL,0x0(AX)
syscall.Syscall+0x4c 0x00106e8c ADDB    AL,0x0(AX)
syscall.Syscall+0x4e 0x00106e8e ADDB    AL,0x0(AX)
syscall.Syscall6 0x00106e90 CALL    runtime.entersyscall(SB)
acid: PC    0x00106e57 syscall.Syscall+0x17  ?file?:0
SP  0x111e3ca0 ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0xf010001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x0000002f BX   0x10566008 CX   0x00435bcc DX   0x00000000
DI  0x111e3cb0 SI   0x111e3cb4 BP   0x00000000
acid: 
echo kill > /proc/1371668/ctl
/proc/1381927/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: syscall.Syscall()+0x17 ?file?:0
syscall.await(syscall.err=0x0,syscall.n=0x109224c2,syscall.s=0x10a05d18)+0x7d ?file?:0
syscall.Await(syscall.err=0x0,syscall.w=0x10842000)+0xc4 ?file?:0
syscall.func·001()+0x187 ?file?:0
runtime.goexit ?file?:0
acid: syscall.Syscall+0x17 0x00106e57   MOVL    AX,0x14(FP)
syscall.Syscall+0x1b 0x00106e5b MOVL    $0x0,0x18(FP)
syscall.Syscall+0x23 0x00106e63 CMPL    AX,$0xffffffff
syscall.Syscall+0x26 0x00106e66 JNE syscall.Syscall+0x42(SB)
syscall.Syscall+0x28 0x00106e68 SUBL    $0x8,SP
syscall.Syscall+0x2b 0x00106e6b CALL    runtime.errstr(SB)
syscall.Syscall+0x30 0x00106e70 MOVL    SP,SI
syscall.Syscall+0x32 0x00106e72 ADDL    $0x8,SP
syscall.Syscall+0x35 0x00106e75 LEAL    0x1c(FP),DI
syscall.Syscall+0x39 0x00106e79 CLD
syscall.Syscall+0x3a 0x00106e7a MOVSL   (SI),(DI)
syscall.Syscall+0x3b 0x00106e7b MOVSL   (SI),(DI)
syscall.Syscall+0x3c 0x00106e7c CALL    runtime.exitsyscall(SB)
syscall.Syscall+0x41 0x00106e81 RET
syscall.Syscall+0x42 0x00106e82 LEAL    runtime.emptystring(SB),SI
syscall.Syscall+0x48 0x00106e88 JMP syscall.Syscall+0x35(SB)
syscall.Syscall+0x4a 0x00106e8a ADDB    AL,0x0(AX)
syscall.Syscall+0x4c 0x00106e8c ADDB    AL,0x0(AX)
syscall.Syscall+0x4e 0x00106e8e ADDB    AL,0x0(AX)
syscall.Syscall6 0x00106e90 CALL    runtime.entersyscall(SB)
acid: PC    0x00106e57 syscall.Syscall+0x17  ?file?:0
SP  0x10a05ca0 ECODE 0xf010083e EFLAG 0x00000206
CS  0x00000023 DS    0x0000001b SS  0x0000001b
GS  0x0000001b FS    0x0000001b ES  0x0000001b
TRAP    0x00000040 system call
AX  0x0000002f BX   0x10566008 CX   0x00435bcc DX   0x00000000
DI  0x10a05cb0 SI   0x10a05cb4 BP   0x00000000
acid: 
echo kill > /proc/1381927/ctl

[rsc]

Comment 6:

Labels changed: added release-go1.3maybe, removed release-go1.3.

Status changed to Accepted.

[bradfitz]

Comment 7:

Labels changed: added os-plan9.

[rsc]

Comment 8:

Labels changed: added release-none, suggested, removed release-go1.3maybe.

[gopherbot]

Comment 9 by lucio.dere:

I have no idea if my problem is related, but I've been getting frequent stalls on
execution of a fairly trivial SPAM message parser on a Plan 9 native implementation of
Go for a project I'm involved with.
Even interrupting execution did not have the desired effect immediately, although
peeking from another window sometimes released the blocked program, sometimes caused the
new window to block too.  I never quite needed to reset the system, though.
Stats suggested that the system was load-saturated, but I never dug any deeper, leaving
that for when the utility is complete.
If this is not a familiar situation for anyone else (I'm running a fairly stock Bell
Labs distribution), then I'll report it separately when I start investigating it
properly.
Lucio.

[gopherbot]

Comment 10 by lucio.dere:

I seem to be causing a plan 9 system hang quite frequently now, but I can't be sure
whether it's the Go application that's responsible or whether it just tickles a problem
in the kernel.
Right now, I have "ls /proc" hanging in a rio window.  Stats shows full "load"
utilisation and I'm fairly certain that the Go application has been crashed when I
deleted the rio window it was hanging in.
The natural response to such a hang has been to type "ps" in another window and I am
convinced that doing so either jams the machine (not tightly: I can open new windows and
mess with the rio menu; some things get very slow) or causes the hanging Go application
to finish.
I know my guesses are usually uninspired, but /proc seems very much involved in the
problem and load saturation seems also relevant.  It is however hard to debug because
one can't easily access the guilty process.  I'm hoping that someone else may recognise
the symptoms as familiar and recommend some unconventional debugging technique (I'm not
much good with the conventional ones, I tend to use printf() a lot).
Lucio.

[0intro]

Comment 11:

Last failure on the builder:
http://build.golang.org/log/7741353b19e1fbb83310d1f02781cde345fb039b
djc           43036    0:00   0:00      240K Await    all.rc -e
/tmp/gobuilder/plan9-386-cnielsen-d628e9e34434/go/src/all.rc
djc           43891    0:00   0:00      240K Await    run.rc -e ./run.rc --no-rebuild
djc           46768    0:00   0:00      240K Await    run.rc
djc           46771    0:00   0:00       48K Await    time go run run.go
djc           46772    0:00   0:00   795628K Await    go run run.go
djc           46773    0:00   0:00   795628K Semacqui go
djc           46774    0:00   0:00   795628K Semacqui go
djc           46775    0:00   0:00   795628K Tsemacqu go
djc           46779    0:00   0:00   795628K Semacqui go
djc           46782    0:00   0:04   792720K Pread   
/tmp/go-build858568877/command-line-arguments/_obj/exe/run
djc           46783    0:00   0:00   792720K Semacqui run
djc           46784    0:00   0:00   792720K Semacqui run
djc           46785    0:01   0:04   792720K Tsemacqu run
djc           46790    0:00   0:00   792720K Semacqui run
djc           52342    0:00   0:01   789088K Sleep    a.exe
/proc/46782/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: syscall.Syscall6()+0x1a ?file?:0
syscall.Pread(syscall.err=0x0,syscall.n=0x108fc1,syscall.offset=0xffffffff,syscall.p=0x108f1c00,syscall.fd=0x5)+0x7f
?file?:0
syscall.Read(syscall.err=0x0,syscall.n=0x200,syscall.p=0x108f1c00,syscall.fd=0x5)+0x65
?file?:0
os.(*File).read(os.err=0x0,os.n=0x10720100,os.b=0x108f1c00,os.f=0x1054c990)+0x5a ?file?:0
os.(*File).Read(os.err=0x0,os.n=0x1,os.b=0x108f1c00,os.f=0x1054c990)+0x7b ?file?:0
bytes.(*Buffer).ReadFrom(bytes.err=0x0,bytes.n=0x0,bytes.r=0x303363a8,bytes.b=0x1080d4a0)+0x1bc
?file?:0
io.Copy(io.err=0x0,io.written=0x0,io.src=0x303363a8,io.dst=0x303363c0)+0x123 ?file?:0
os/exec.func·003(os/exec.~r0=0x0)+0x70 ?file?:0
os/exec.func·004(os/exec.fn=0x105cb400)+0x30 ?file?:0
runtime.goexit()+0x0 ?file?:0
0x105cb400 ?file?:0
acid: syscall.Syscall6+0x1a 0x000d7d4a  MOVL    AX,0x20(FP)
syscall.Syscall6+0x1e 0x000d7d4e    MOVL    $0x0,0x24(FP)
syscall.Syscall6+0x26 0x000d7d56    CMPL    AX,$0xffffffff
syscall.Syscall6+0x29 0x000d7d59    JNE syscall.Syscall6+0x45(SB)
syscall.Syscall6+0x2b 0x000d7d5b    SUBL    $0x8,SP
syscall.Syscall6+0x2e 0x000d7d5e    CALL    runtime.errstr(SB)
syscall.Syscall6+0x33 0x000d7d63    MOVL    SP,SI
syscall.Syscall6+0x35 0x000d7d65    ADDL    $0x8,SP
syscall.Syscall6+0x38 0x000d7d68    LEAL    0x28(FP),DI
syscall.Syscall6+0x3c 0x000d7d6c    CLD
syscall.Syscall6+0x3d 0x000d7d6d    MOVSL   (SI),(DI)
syscall.Syscall6+0x3e 0x000d7d6e    MOVSL   (SI),(DI)
syscall.Syscall6+0x3f 0x000d7d6f    CALL    runtime.exitsyscall(SB)
syscall.Syscall6+0x44 0x000d7d74    RET
syscall.Syscall6+0x45 0x000d7d75    LEAL    runtime.emptystring(SB),SI
syscall.Syscall6+0x4b 0x000d7d7b    JMP syscall.Syscall6+0x38(SB)
syscall.Syscall6+0x4d 0x000d7d7d    ADDB    AL,0x0(AX)
syscall.Syscall6+0x4f 0x000d7d7f    ADDB    CL,0x8d042444(BX)
acid: 
echo kill > /proc/46782/ctl
/proc/46783/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x3a ?file?:0
runtime.notesleep()+0xe8 ?file?:0
sysmon()+0x29e ?file?:0
runtime.mstart()+0xdf ?file?:0
runtime.rfork+0x49 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x00032247   RET
runtime.plan9_semacquire+0x8 0x00032248 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0003224a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0003224c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0003224e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x00032250    MOVL    $0x34,AX
acid: 
echo kill > /proc/46783/ctl
/proc/46784/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x3a ?file?:0
runtime.notesleep()+0xe8 ?file?:0
stopm()+0xe8 ?file?:0
findrunnable()+0x32e ?file?:0
schedule()+0xfd ?file?:0
park0()+0x100 ?file?:0
runtime.mcall()+0x3f ?file?:0
0x10326320 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x00032247   RET
runtime.plan9_semacquire+0x8 0x00032248 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0003224a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0003224c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0003224e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x00032250    MOVL    $0x34,AX
acid: 
echo kill > /proc/46784/ctl
/proc/46785/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_tsemacquire()+0x7 ?file?:0
runtime.semasleep()+0x96 ?file?:0
notetsleep()+0xef ?file?:0
runtime.notetsleepg()+0xb3 ?file?:0
runtime.MHeap_Scavenger()+0xcb ?file?:0
runtime.goexit ?file?:0
acid: runtime.plan9_tsemacquire+0x7 0x00032257  RET
runtime.plan9_tsemacquire+0x8 0x00032258    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xa 0x0003225a    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xc 0x0003225c    ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire+0xe 0x0003225e    ADDB    AL,0x0(AX)
runtime.notify 0x00032260   MOVL    $0x1c,AX
acid: 
echo kill > /proc/46785/ctl
/proc/46790/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.plan9_semacquire()+0x7 ?file?:0
runtime.semasleep()+0x3a ?file?:0
runtime.notesleep()+0xe8 ?file?:0
stopm()+0xe8 ?file?:0
findrunnable()+0x32e ?file?:0
schedule()+0xfd ?file?:0
park0()+0x100 ?file?:0
runtime.mcall()+0x3f ?file?:0
0x10326320 ?file?:0
acid: runtime.plan9_semacquire+0x7 0x00032247   RET
runtime.plan9_semacquire+0x8 0x00032248 ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xa 0x0003224a ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xc 0x0003224c ADDB    AL,0x0(AX)
runtime.plan9_semacquire+0xe 0x0003224e ADDB    AL,0x0(AX)
runtime.plan9_tsemacquire 0x00032250    MOVL    $0x34,AX
acid: 
echo kill > /proc/46790/ctl
/proc/52342/text:386 plan 9 executable
/sys/lib/acid/port
/sys/lib/acid/386
acid: runtime.sleep()+0x7 ?file?:0
runtime.usleep()+0x25 ?file?:0
sysmon()+0x63 ?file?:0
runtime.mstart()+0xdf ?file?:0
runtime.rfork+0x49 ?file?:0
acid: runtime.sleep+0x7 0x0001ed57  RET
runtime.sleep+0x8 0x0001ed58    ADDB    AL,0x0(AX)
runtime.sleep+0xa 0x0001ed5a    ADDB    AL,0x0(AX)
runtime.sleep+0xc 0x0001ed5c    ADDB    AL,0x0(AX)
runtime.sleep+0xe 0x0001ed5e    ADDB    AL,0x0(AX)
runtime.plan9_semacquire 0x0001ed60 MOVL    $0x25,AX
acid: 
echo kill > /proc/52342/ctl

[4ad]

Comment 12:

The builder is hitting this a lot lately, and I am too, both on 386 and amd64. It's
exec-related, it seems one proc is always blocked in await, and another proc is always
blocked in the io.Copy in os/exec/exec.go:/writerDescriptor. The additional system calls
hammering the system when this hang occurs are 10ms sleeps from the sysmon thread.
If I were to guess, I'd guess that tsemacquire doesn't work correctly or we don't use it
correctly.