runtime: improve block profiler support for channels

1. Handle select statements.
2. Handle chan close.
3. Show top frame in debug mode (chansend/chanrecv/selectgo).
Fixes #6049.

R=golang-dev, daniel.morsing, rsc
CC=golang-dev
https://golang.org/cl/12694050

diff --git a/src/pkg/runtime/chan.c b/src/pkg/runtime/chan.c
index 698c5f95a5154f0d29e4699f862fbf593610f08c..1cb3d99aa72ecb6419febae5596fdd3e5a67bcf0 100644 (file)
--- 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; i<sel->ncase; 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 e7eb66a5576d73cc73fdd86fcc69b52caf97feb1..3b8428519d74c4bc275f026d77de4e7fbeacaae4 100644 (file)
--- 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 738e2c4ec4e9e3b2278cc8245a81170b49c6e44e..c25331d8b3f152e48e647d78f0716305f918f9d2 100644 (file)
--- 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()