diff --git a/src/pkg/runtime/chan.c b/src/pkg/runtime/chan.c index 698c5f95a51..1cb3d99aa72 100644 --- a/src/pkg/runtime/chan.c +++ b/src/pkg/runtime/chan.c @@ -851,6 +851,7 @@ selectgo(Select **selp) { Select *sel; uint32 o, i, j, k; + int64 t0; Scase *cas, *dfl; Hchan *c; SudoG *sg; @@ -865,6 +866,13 @@ selectgo(Select **selp) if(debug) runtime·printf("select: sel=%p\n", sel); + t0 = 0; + if(runtime·blockprofilerate > 0) { + t0 = runtime·cputicks(); + for(i=0; incase; i++) + sel->scase[i].sg.releasetime = -1; + } + // The compiler rewrites selects that statically have // only 0 or 1 cases plus default into simpler constructs. // The only way we can end up with such small sel->ncase @@ -1048,6 +1056,8 @@ asyncrecv: if(sg != nil) { gp = sg->g; selunlock(sel); + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); } else { selunlock(sel); @@ -1066,6 +1076,8 @@ asyncsend: if(sg != nil) { gp = sg->g; selunlock(sel); + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); } else { selunlock(sel); @@ -1085,6 +1097,8 @@ syncrecv: c->elemalg->copy(c->elemsize, cas->sg.elem, sg->elem); gp = sg->g; gp->param = sg; + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); goto retc; @@ -1110,6 +1124,8 @@ syncsend: c->elemalg->copy(c->elemsize, sg->elem, cas->sg.elem); gp = sg->g; gp->param = sg; + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); retc: @@ -1123,6 +1139,8 @@ retc: as = (byte*)selp + cas->so; *as = true; } + if(cas->sg.releasetime > 0) + runtime·blockevent(cas->sg.releasetime - t0, 2); runtime·free(sel); return pc; @@ -1265,6 +1283,8 @@ closechan(Hchan *c, void *pc) break; gp = sg->g; gp->param = nil; + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); } @@ -1275,6 +1295,8 @@ closechan(Hchan *c, void *pc) break; gp = sg->g; gp->param = nil; + if(sg->releasetime) + sg->releasetime = runtime·cputicks(); runtime·ready(gp); } diff --git a/src/pkg/runtime/pprof/pprof.go b/src/pkg/runtime/pprof/pprof.go index e7eb66a5576..3b8428519d7 100644 --- a/src/pkg/runtime/pprof/pprof.go +++ b/src/pkg/runtime/pprof/pprof.go @@ -666,7 +666,7 @@ func writeBlock(w io.Writer, debug int) error { } fmt.Fprint(w, "\n") if debug > 0 { - printStackRecord(w, r.Stack(), false) + printStackRecord(w, r.Stack(), true) } } diff --git a/src/pkg/runtime/pprof/pprof_test.go b/src/pkg/runtime/pprof/pprof_test.go index 738e2c4ec4e..c25331d8b3f 100644 --- a/src/pkg/runtime/pprof/pprof_test.go +++ b/src/pkg/runtime/pprof/pprof_test.go @@ -181,10 +181,55 @@ var badOS = map[string]bool{ } func TestBlockProfile(t *testing.T) { + type TestCase struct { + name string + f func() + re string + } + tests := [...]TestCase{ + {"chan recv", blockChanRecv, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ runtime\.chanrecv1\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + {"chan send", blockChanSend, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ runtime\.chansend1\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockChanSend\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + {"chan close", blockChanClose, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ runtime\.chanrecv1\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockChanClose\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + {"select recv async", blockSelectRecvAsync, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ runtime\.selectgo\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockSelectRecvAsync\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + {"select send sync", blockSelectSendSync, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ runtime\.selectgo\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + {"mutex", blockMutex, ` +[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ +# 0x[0-9,a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+ .*/src/pkg/sync/mutex\.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ +`}, + } + runtime.SetBlockProfileRate(1) defer runtime.SetBlockProfileRate(0) - produceChanContention() - produceMutexContention() + for _, test := range tests { + test.f() + } var w bytes.Buffer Lookup("block").WriteTo(&w, 1) prof := w.String() @@ -193,40 +238,73 @@ func TestBlockProfile(t *testing.T) { t.Fatalf("Bad profile header:\n%v", prof) } - reChan := regexp.MustCompile(` -[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ -# 0x[0-9,a-f]+ runtime/pprof_test\.produceChanContention\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ -# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ -`) - if !reChan.MatchString(prof) { - t.Fatalf("Bad chan entry, expect:\n%v\ngot:\n%v", reChan, prof) - } - - reMutex := regexp.MustCompile(` -[0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ -# 0x[0-9,a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+ .*/src/pkg/sync/mutex\.go:[0-9]+ -# 0x[0-9,a-f]+ runtime/pprof_test\.produceMutexContention\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ -# 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+ -`) - if !reMutex.MatchString(prof) { - t.Fatalf("Bad mutex entry, expect:\n%v\ngot:\n%v", reMutex, prof) + for _, test := range tests { + if !regexp.MustCompile(test.re).MatchString(prof) { + t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) + } } } -func produceChanContention() { +const blockDelay = 10 * time.Millisecond + +func blockChanRecv() { c := make(chan bool) go func() { - time.Sleep(10 * time.Millisecond) + time.Sleep(blockDelay) c <- true }() <-c } -func produceMutexContention() { +func blockChanSend() { + c := make(chan bool) + go func() { + time.Sleep(blockDelay) + <-c + }() + c <- true +} + +func blockChanClose() { + c := make(chan bool) + go func() { + time.Sleep(blockDelay) + close(c) + }() + <-c +} + +func blockSelectRecvAsync() { + c := make(chan bool, 1) + c2 := make(chan bool, 1) + go func() { + time.Sleep(blockDelay) + c <- true + }() + select { + case <-c: + case <-c2: + } +} + +func blockSelectSendSync() { + c := make(chan bool) + c2 := make(chan bool) + go func() { + time.Sleep(blockDelay) + <-c + }() + select { + case c <- true: + case c2 <- true: + } +} + +func blockMutex() { var mu sync.Mutex mu.Lock() go func() { - time.Sleep(10 * time.Millisecond) + time.Sleep(blockDelay) mu.Unlock() }() mu.Lock()