code review 10796043: runtime: preempt long-running goroutines

runtime: preempt long-running goroutines
If a goroutine runs for more than 10ms, preempt it.
Update issue 543.

[dvyukov, 2013-06-29 19:40:03]

https://codereview.appspot.com/10796043/diff/3001/src/pkg/runtime/stack.c
File src/pkg/runtime/stack.c (right):

https://codereview.appspot.com/10796043/diff/3001/src/pkg/runtime/stack.c#new...
src/pkg/runtime/stack.c:251: if(oldstatus != Grunning || m->locks ||
m->mallocing || m->gcing || m->p->status != Prunning) {
During GC P can be in Pgcstop status, then it crashes as:

fatal error: runtime: g is running but p is not

goroutine 0 [idle]:
runtime.throw(0x392098)
	src/pkg/runtime/panic.c:474 +0x69
runtime.newstack()
	src/pkg/runtime/stack.c:248 +0x214
runtime.morestack()
	src/pkg/runtime/asm_amd64.s:213 +0x61

goroutine 200100 [stack split]:
pidleget()
	src/pkg/runtime/proc.c:2261 fp=0x22109a9ef8
runtime.stoptheworld()
	src/pkg/runtime/proc.c:379 +0xce fp=0x22109a9f28
runtime.gc(0x1)
	src/pkg/runtime/mgc0.c:1993 +0x11c fp=0x22109a9f60
runtime.GC()
	src/pkg/runtime/zmalloc_darwin_amd64.c:734 +0x26 fp=0x22109a9f70
runtime_test.func·030()
	src/pkg/runtime/proc_test.go:34 +0x37 fp=0x22109a9fa0
runtime.goexit()
	src/pkg/runtime/proc.c:1276 fp=0x22109a9fa8
created by runtime_test.TestStopTheWorldDeadlock
	src/pkg/runtime/proc_test.go:37 +0x13f

[rsc, 2013-07-18 16:25:51]

This patch doesn't apply cleanly to tip. Can you please update it?

[dvyukov, 2013-07-18 16:40:56]

Hello rsc@golang.org (cc: golang-dev@googlegroups.com),

I'd like you to review this change to
https://dvyukov%40google.com@code.google.com/p/go/

[dvyukov, 2013-07-18 16:41:48]

Done

On Thu, Jul 18, 2013 at 8:25 PM,  <rsc@golang.org> wrote:
> This patch doesn't apply cleanly to tip. Can you please update it?
>
>
> https://codereview.appspot.com/10796043/

[rsc, 2013-07-18 17:27:50]

LGTM

[dvyukov, 2013-07-18 21:16:55]

I've successfully run
$ GOARCH=386 ./all.bash && GOMAXPROCS=4 ./all.bash && GOARCH=386 ./all.bash &&
GOMAXPROCS=4 ./all.bash

but when I've run hg submit, it said:

$ hg submit 10796043
Issue updated. URL: https://codereview.appspot.com/10796043
gofmt errors:
runtime: newstack framesize=0x0 argsize=0x20 sp=0x21034b090 stack=[0x21034c000,
0x21034d530]
	morebuf={pc:0x64c2c sp:0x21034b0a0 lr:0x0}
	sched={pc:0x72ca0 sp:0x21034b098 lr:0x0 ctxt:0x6e9}
runtime: split stack overflow: 0x21034b090 < 0x21034c000
fatal error: runtime: split stack overflow

goroutine 0 [idle]:
runtime.throw(0x23bf38)
	src/pkg/runtime/panic.c:474 +0x69 fp=0x21030de88
runtime.newstack()
	src/pkg/runtime/stack.c:236 +0x136 fp=0x21030df80
runtime.morestack()
	src/pkg/runtime/asm_amd64.s:213 +0x61 fp=0x21030df88

goroutine 1 [stack split]:
go/printer.(*printer).print(0x210325500, 0x21034bcf8, 0x1, 0x1)
	src/pkg/go/printer/printer.go:786 fp=0x21034b0a0
go/printer.(*printer).expr1(0x210325500, 0x297950, 0x210323e00, 0x4, 0x2)
	src/pkg/go/printer/nodes.go:676 +0xcc fp=0x21034c210
go/printer.(*printer).binaryExpr(0x210325500, 0x2102ccc60, 0x0, 0x6, 0x1)
	src/pkg/go/printer/nodes.go:664 +0x54e fp=0x21034c398
go/printer.(*printer).expr1(0x210325500, 0x297c98, 0x2102ccc60, 0x0, 0x1)
	src/pkg/go/printer/nodes.go:690 +0x1077 fp=0x21034d508
----- stack segment boundary -----
go/printer.(*printer).expr(0x210325500, 0x297c98, 0x2102ccc60)
	src/pkg/go/printer/nodes.go:891 +0x4d fp=0x2210445e50
go/printer.(*printer).controlClause(0x210325500, 0x2210446301, 0x297c60,
0x210329340, 0x297c98, ...)
	src/pkg/go/printer/nodes.go:994 +0x30f fp=0x2210445f60
----- stack segment boundary -----
go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329800, 0x290000)
	src/pkg/go/printer/nodes.go:1201 +0x4de fp=0x2210446ea8
go/printer.(*printer).stmtList(0x210325500, 0x210329840, 0x4, 0x4, 0x1, ...)
	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210446f70
----- stack segment boundary -----
go/printer.(*printer).block(0x210325500, 0x2102ccf00, 0x1)
	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22104371d0
go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329980, 0x290001)
	src/pkg/go/printer/nodes.go:1202 +0x509 fp=0x2210437f80
----- stack segment boundary -----
go/printer.(*printer).stmtList(0x210325500, 0x2103299c0, 0x3, 0x4, 0x1, ...)
	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210326608
go/printer.(*printer).block(0x210325500, 0x2102ccf30, 0x1)
	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22103266c0
go/printer.(*printer).adjBlock(0x210325500, 0x2b, 0xb, 0x2102ccf30)
	src/pkg/go/printer/nodes.go:1498 +0x5d9 fp=0x2210326878
go/printer.(*printer).funcDecl(0x210325500, 0x2102ccf60)
	src/pkg/go/printer/nodes.go:1522 +0x2a2 fp=0x2210326920
go/printer.(*printer).decl(0x210325500, 0x297a68, 0x2102ccf60)
	src/pkg/go/printer/nodes.go:1532 +0x9f fp=0x22103269a8
go/printer.(*printer).declList(0x210325500, 0x210340c00, 0x26, 0x40)
	src/pkg/go/printer/nodes.go:1573 +0x174 fp=0x2210326a18
go/printer.(*printer).file(0x210325500, 0x21030e780)
	src/pkg/go/printer/nodes.go:1581 +0x16f fp=0x2210326ac0
go/printer.(*printer).printNode(0x210325500, 0x1217c0, 0x21030e780, 0x2103224c0,
0xfbb1)
	src/pkg/go/printer/printer.go:1026 +0x7b4 fp=0x2210326be8
go/printer.(*Config).fprint(0x2210326e30, 0x298088, 0x210312230, 0x2102e6540,
0x1217c0, ...)
	src/pkg/go/printer/printer.go:1165 +0xa8 fp=0x2210326c70
go/printer.(*Config).Fprint(0x2210326e30, 0x298088, 0x210312230, 0x2102e6540,
0x1217c0, ...)
	src/pkg/go/printer/printer.go:1223 +0x7e fp=0x2210326cc0
main.processFile(0x7fff5fbffb61, 0x1c, 0x0, 0x0, 0x297890, ...)
	src/cmd/gofmt/gofmt.go:121 +0x2ef fp=0x2210326e70
main.gofmtMain()
	src/cmd/gofmt/gofmt.go:220 +0x597 fp=0x2210326f68
main.main()
	src/cmd/gofmt/gofmt.go:176 +0x1e fp=0x2210326f78
runtime.main()
	src/pkg/runtime/proc.c:182 +0x94 fp=0x2210326fa0
runtime.goexit()
	src/pkg/runtime/proc.c:1276 fp=0x2210326fa8

[dvyukov, 2013-07-18 21:21:13]

On 2013/07/18 21:16:55, dvyukov wrote:
> I've successfully run
> $ GOARCH=386 ./all.bash && GOMAXPROCS=4 ./all.bash && GOARCH=386 ./all.bash &&
> GOMAXPROCS=4 ./all.bash
> 
> but when I've run hg submit, it said:
> 
> $ hg submit 10796043
> Issue updated. URL: https://codereview.appspot.com/10796043
> gofmt errors:
> runtime: newstack framesize=0x0 argsize=0x20 sp=0x21034b090
stack=[0x21034c000,
> 0x21034d530]
> 	morebuf={pc:0x64c2c sp:0x21034b0a0 lr:0x0}
> 	sched={pc:0x72ca0 sp:0x21034b098 lr:0x0 ctxt:0x6e9}
> runtime: split stack overflow: 0x21034b090 < 0x21034c000
> fatal error: runtime: split stack overflow
> 
> goroutine 0 [idle]:
> runtime.throw(0x23bf38)
> 	src/pkg/runtime/panic.c:474 +0x69 fp=0x21030de88
> runtime.newstack()
> 	src/pkg/runtime/stack.c:236 +0x136 fp=0x21030df80
> runtime.morestack()
> 	src/pkg/runtime/asm_amd64.s:213 +0x61 fp=0x21030df88
> 
> goroutine 1 [stack split]:
> go/printer.(*printer).print(0x210325500, 0x21034bcf8, 0x1, 0x1)
> 	src/pkg/go/printer/printer.go:786 fp=0x21034b0a0
> go/printer.(*printer).expr1(0x210325500, 0x297950, 0x210323e00, 0x4, 0x2)
> 	src/pkg/go/printer/nodes.go:676 +0xcc fp=0x21034c210
> go/printer.(*printer).binaryExpr(0x210325500, 0x2102ccc60, 0x0, 0x6, 0x1)
> 	src/pkg/go/printer/nodes.go:664 +0x54e fp=0x21034c398
> go/printer.(*printer).expr1(0x210325500, 0x297c98, 0x2102ccc60, 0x0, 0x1)
> 	src/pkg/go/printer/nodes.go:690 +0x1077 fp=0x21034d508
> ----- stack segment boundary -----
> go/printer.(*printer).expr(0x210325500, 0x297c98, 0x2102ccc60)
> 	src/pkg/go/printer/nodes.go:891 +0x4d fp=0x2210445e50
> go/printer.(*printer).controlClause(0x210325500, 0x2210446301, 0x297c60,
> 0x210329340, 0x297c98, ...)
> 	src/pkg/go/printer/nodes.go:994 +0x30f fp=0x2210445f60
> ----- stack segment boundary -----
> go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329800, 0x290000)
> 	src/pkg/go/printer/nodes.go:1201 +0x4de fp=0x2210446ea8
> go/printer.(*printer).stmtList(0x210325500, 0x210329840, 0x4, 0x4, 0x1, ...)
> 	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210446f70
> ----- stack segment boundary -----
> go/printer.(*printer).block(0x210325500, 0x2102ccf00, 0x1)
> 	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22104371d0
> go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329980, 0x290001)
> 	src/pkg/go/printer/nodes.go:1202 +0x509 fp=0x2210437f80
> ----- stack segment boundary -----
> go/printer.(*printer).stmtList(0x210325500, 0x2103299c0, 0x3, 0x4, 0x1, ...)
> 	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210326608
> go/printer.(*printer).block(0x210325500, 0x2102ccf30, 0x1)
> 	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22103266c0
> go/printer.(*printer).adjBlock(0x210325500, 0x2b, 0xb, 0x2102ccf30)
> 	src/pkg/go/printer/nodes.go:1498 +0x5d9 fp=0x2210326878
> go/printer.(*printer).funcDecl(0x210325500, 0x2102ccf60)
> 	src/pkg/go/printer/nodes.go:1522 +0x2a2 fp=0x2210326920
> go/printer.(*printer).decl(0x210325500, 0x297a68, 0x2102ccf60)
> 	src/pkg/go/printer/nodes.go:1532 +0x9f fp=0x22103269a8
> go/printer.(*printer).declList(0x210325500, 0x210340c00, 0x26, 0x40)
> 	src/pkg/go/printer/nodes.go:1573 +0x174 fp=0x2210326a18
> go/printer.(*printer).file(0x210325500, 0x21030e780)
> 	src/pkg/go/printer/nodes.go:1581 +0x16f fp=0x2210326ac0
> go/printer.(*printer).printNode(0x210325500, 0x1217c0, 0x21030e780,
0x2103224c0,
> 0xfbb1)
> 	src/pkg/go/printer/printer.go:1026 +0x7b4 fp=0x2210326be8
> go/printer.(*Config).fprint(0x2210326e30, 0x298088, 0x210312230, 0x2102e6540,
> 0x1217c0, ...)
> 	src/pkg/go/printer/printer.go:1165 +0xa8 fp=0x2210326c70
> go/printer.(*Config).Fprint(0x2210326e30, 0x298088, 0x210312230, 0x2102e6540,
> 0x1217c0, ...)
> 	src/pkg/go/printer/printer.go:1223 +0x7e fp=0x2210326cc0
> main.processFile(0x7fff5fbffb61, 0x1c, 0x0, 0x0, 0x297890, ...)
> 	src/cmd/gofmt/gofmt.go:121 +0x2ef fp=0x2210326e70
> main.gofmtMain()
> 	src/cmd/gofmt/gofmt.go:220 +0x597 fp=0x2210326f68
> main.main()
> 	src/cmd/gofmt/gofmt.go:176 +0x1e fp=0x2210326f78
> runtime.main()
> 	src/pkg/runtime/proc.c:182 +0x94 fp=0x2210326fa0
> runtime.goexit()
> 	src/pkg/runtime/proc.c:1276 fp=0x2210326fa8


this is still with preemption disabled
I think I've seen this before, but I thought that it's related to interaction
between new handling of big stack frames and preemption...

[dvyukov, 2013-07-18 21:22:18]

*** Submitted as https://code.google.com/p/go/source/detail?r=77be25034f84 ***

runtime: preempt long-running goroutines
If a goroutine runs for more than 10ms, preempt it.
Update issue 543.

R=rsc
CC=golang-dev
https://codereview.appspot.com/10796043

[dvyukov, 2013-07-18 21:22:33]

On 2013/07/18 21:21:13, dvyukov wrote:
> On 2013/07/18 21:16:55, dvyukov wrote:
> > I've successfully run
> > $ GOARCH=386 ./all.bash && GOMAXPROCS=4 ./all.bash && GOARCH=386 ./all.bash
&&
> > GOMAXPROCS=4 ./all.bash
> > 
> > but when I've run hg submit, it said:
> > 
> > $ hg submit 10796043
> > Issue updated. URL: https://codereview.appspot.com/10796043
> > gofmt errors:
> > runtime: newstack framesize=0x0 argsize=0x20 sp=0x21034b090
> stack=[0x21034c000,
> > 0x21034d530]
> > 	morebuf={pc:0x64c2c sp:0x21034b0a0 lr:0x0}
> > 	sched={pc:0x72ca0 sp:0x21034b098 lr:0x0 ctxt:0x6e9}
> > runtime: split stack overflow: 0x21034b090 < 0x21034c000
> > fatal error: runtime: split stack overflow
> > 
> > goroutine 0 [idle]:
> > runtime.throw(0x23bf38)
> > 	src/pkg/runtime/panic.c:474 +0x69 fp=0x21030de88
> > runtime.newstack()
> > 	src/pkg/runtime/stack.c:236 +0x136 fp=0x21030df80
> > runtime.morestack()
> > 	src/pkg/runtime/asm_amd64.s:213 +0x61 fp=0x21030df88
> > 
> > goroutine 1 [stack split]:
> > go/printer.(*printer).print(0x210325500, 0x21034bcf8, 0x1, 0x1)
> > 	src/pkg/go/printer/printer.go:786 fp=0x21034b0a0
> > go/printer.(*printer).expr1(0x210325500, 0x297950, 0x210323e00, 0x4, 0x2)
> > 	src/pkg/go/printer/nodes.go:676 +0xcc fp=0x21034c210
> > go/printer.(*printer).binaryExpr(0x210325500, 0x2102ccc60, 0x0, 0x6, 0x1)
> > 	src/pkg/go/printer/nodes.go:664 +0x54e fp=0x21034c398
> > go/printer.(*printer).expr1(0x210325500, 0x297c98, 0x2102ccc60, 0x0, 0x1)
> > 	src/pkg/go/printer/nodes.go:690 +0x1077 fp=0x21034d508
> > ----- stack segment boundary -----
> > go/printer.(*printer).expr(0x210325500, 0x297c98, 0x2102ccc60)
> > 	src/pkg/go/printer/nodes.go:891 +0x4d fp=0x2210445e50
> > go/printer.(*printer).controlClause(0x210325500, 0x2210446301, 0x297c60,
> > 0x210329340, 0x297c98, ...)
> > 	src/pkg/go/printer/nodes.go:994 +0x30f fp=0x2210445f60
> > ----- stack segment boundary -----
> > go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329800, 0x290000)
> > 	src/pkg/go/printer/nodes.go:1201 +0x4de fp=0x2210446ea8
> > go/printer.(*printer).stmtList(0x210325500, 0x210329840, 0x4, 0x4, 0x1, ...)
> > 	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210446f70
> > ----- stack segment boundary -----
> > go/printer.(*printer).block(0x210325500, 0x2102ccf00, 0x1)
> > 	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22104371d0
> > go/printer.(*printer).stmt(0x210325500, 0x297cd0, 0x210329980, 0x290001)
> > 	src/pkg/go/printer/nodes.go:1202 +0x509 fp=0x2210437f80
> > ----- stack segment boundary -----
> > go/printer.(*printer).stmtList(0x210325500, 0x2103299c0, 0x3, 0x4, 0x1, ...)
> > 	src/pkg/go/printer/nodes.go:916 +0x256 fp=0x2210326608
> > go/printer.(*printer).block(0x210325500, 0x2102ccf30, 0x1)
> > 	src/pkg/go/printer/nodes.go:929 +0xef fp=0x22103266c0
> > go/printer.(*printer).adjBlock(0x210325500, 0x2b, 0xb, 0x2102ccf30)
> > 	src/pkg/go/printer/nodes.go:1498 +0x5d9 fp=0x2210326878
> > go/printer.(*printer).funcDecl(0x210325500, 0x2102ccf60)
> > 	src/pkg/go/printer/nodes.go:1522 +0x2a2 fp=0x2210326920
> > go/printer.(*printer).decl(0x210325500, 0x297a68, 0x2102ccf60)
> > 	src/pkg/go/printer/nodes.go:1532 +0x9f fp=0x22103269a8
> > go/printer.(*printer).declList(0x210325500, 0x210340c00, 0x26, 0x40)
> > 	src/pkg/go/printer/nodes.go:1573 +0x174 fp=0x2210326a18
> > go/printer.(*printer).file(0x210325500, 0x21030e780)
> > 	src/pkg/go/printer/nodes.go:1581 +0x16f fp=0x2210326ac0
> > go/printer.(*printer).printNode(0x210325500, 0x1217c0, 0x21030e780,
> 0x2103224c0,
> > 0xfbb1)
> > 	src/pkg/go/printer/printer.go:1026 +0x7b4 fp=0x2210326be8
> > go/printer.(*Config).fprint(0x2210326e30, 0x298088, 0x210312230,
0x2102e6540,
> > 0x1217c0, ...)
> > 	src/pkg/go/printer/printer.go:1165 +0xa8 fp=0x2210326c70
> > go/printer.(*Config).Fprint(0x2210326e30, 0x298088, 0x210312230,
0x2102e6540,
> > 0x1217c0, ...)
> > 	src/pkg/go/printer/printer.go:1223 +0x7e fp=0x2210326cc0
> > main.processFile(0x7fff5fbffb61, 0x1c, 0x0, 0x0, 0x297890, ...)
> > 	src/cmd/gofmt/gofmt.go:121 +0x2ef fp=0x2210326e70
> > main.gofmtMain()
> > 	src/cmd/gofmt/gofmt.go:220 +0x597 fp=0x2210326f68
> > main.main()
> > 	src/cmd/gofmt/gofmt.go:176 +0x1e fp=0x2210326f78
> > runtime.main()
> > 	src/pkg/runtime/proc.c:182 +0x94 fp=0x2210326fa0
> > runtime.goexit()
> > 	src/pkg/runtime/proc.c:1276 fp=0x2210326fa8
> 
> 
> this is still with preemption disabled
> I think I've seen this before, but I thought that it's related to interaction
> between new handling of big stack frames and preemption...

not reproducible

[rsc, 2013-07-19 02:48:34]

Can you please mail me a copy of the gofmt binary that crashed? You may
have to gzip it to attach it to a mail message. Thanks.

Why do your file names begin with "src/" instead of being absolute paths?
Are you running with local patches?

Russ

[dvyukov, 2013-07-19 09:10:18]

On Fri, Jul 19, 2013 at 6:48 AM, Russ Cox <rsc@golang.org> wrote:
> Can you please mail me a copy of the gofmt binary that crashed? You may have
> to gzip it to attach it to a mail message. Thanks.
>
> Why do your file names begin with "src/" instead of being absolute paths?
> Are you running with local patches?


Sorry, it was inconsistent build (phew!)