runtime: output how long goroutines are blocked

Example of output:

goroutine 4 [sleep for 3 min]:
time.Sleep(0x34630b8a000)
        src/pkg/runtime/time.goc:31 +0x31
main.func·002()
        block.go:16 +0x2c
created by main.main
        block.go:17 +0x33

Full program and output are here:
http://play.golang.org/p/NEZdADI3Td

Fixes #6809.

R=golang-codereviews, khr, kamil.kisiel, bradfitz, rsc
CC=golang-codereviews
https://golang.org/cl/50420043

diff --git a/doc/go1.3.txt b/doc/go1.3.txt
index 27a72e4a901de599df4d132e4ab451ea3b81f59f..dfb21f4fd9d781249214dbe67c9d6a21c95a948f 100644 (file)
--- a/doc/go1.3.txt
+++ b/doc/go1.3.txt
@@ -1,4 +1,5 @@
 cmd/gofmt: remove -tabwidth and -tabs flags (CL 52170043)
 liblink: pull linker i/o into separate liblink C library (CL 35790044)
 misc/dist: renamed misc/makerelease (CL 39920043)
+runtime: output how long goroutines are blocked (CL 50420043)
 syscall: add NewCallbackCDecl to use for windows callbacks (CL 36180044)

diff --git a/src/pkg/runtime/mgc0.c b/src/pkg/runtime/mgc0.c
index 5d38db27ba7d9f4f6e7dd34736b718a32c1a24db..393de7a8363c07498261c56c1774b2e0c781dc6f 100644 (file)
--- a/src/pkg/runtime/mgc0.c
+++ b/src/pkg/runtime/mgc0.c
@@ -188,6 +188,7 @@ static struct {
        uint64  empty; // lock-free list of empty blocks
        byte    pad0[CacheLineSize]; // prevents false-sharing between full/empty and nproc/nwait
        uint32  nproc;
+       int64   tstart;
        volatile uint32 nwait;
        volatile uint32 ndone;
        volatile uint32 debugmarkdone;
@@ -1675,6 +1676,11 @@ addroots(void)
                        addstackroots(gp);
                        break;
                }
+
+               // remember when we've first observed the G blocked
+               // needed only to output in traceback
+               if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince == 0)
+                       gp->waitsince = work.tstart;
        }
 
        for(fb=allfin; fb; fb=fb->alllink)
@@ -2230,6 +2236,7 @@ gc(struct gc_args *args)
        Eface eface;
 
        t0 = args->start_time;
+       work.tstart = args->start_time; 
 
        if(CollectStats)
                runtime·memclr((byte*)&gcstats, sizeof(gcstats));

diff --git a/src/pkg/runtime/proc.c b/src/pkg/runtime/proc.c
index bc371260fc53325ebbc4f72f7e71e9b344de6832..064e8cb24893071ea2c864997bb5f48763048fad 100644 (file)
--- a/src/pkg/runtime/proc.c
+++ b/src/pkg/runtime/proc.c
@@ -237,6 +237,7 @@ void
 runtime·goroutineheader(G *gp)
 {
        int8 *status;
+       int64 waitfor;
 
        switch(gp->status) {
        case Gidle:
@@ -261,7 +262,16 @@ runtime·goroutineheader(G *gp)
                status = "???";
                break;
        }
-       runtime·printf("goroutine %D [%s]:\n", gp->goid, status);
+
+       // approx time the G is blocked, in minutes
+       waitfor = 0;
+       if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince != 0)
+               waitfor = (runtime·nanotime() - gp->waitsince) / (60LL*1000*1000*1000);
+
+       if(waitfor < 1)
+               runtime·printf("goroutine %D [%s]:\n", gp->goid, status);
+       else
+               runtime·printf("goroutine %D [%s, %D minutes]:\n", gp->goid, status, waitfor);
 }
 
 void
@@ -1112,6 +1122,7 @@ execute(G *gp)
                runtime·throw("execute: bad g status");
        }
        gp->status = Grunning;
+       gp->waitsince = 0;
        gp->preempt = false;
        gp->stackguard0 = gp->stackguard;
        m->p->schedtick++;
@@ -1535,6 +1546,7 @@ runtime·exitsyscall(void)
        if(g->isbackground)  // do not consider blocked scavenger for deadlock detection
                incidlelocked(-1);
 
+       g->waitsince = 0;
        if(exitsyscallfast()) {
                // There's a cpu for us, so we can run.
                m->p->syscalltick++;

diff --git a/src/pkg/runtime/runtime.h b/src/pkg/runtime/runtime.h
index 236284b93e0d4d4ecf2b6b0af6af430677b51ae6..43ab84c807d1117b07936697e0d4361dfacf8d0b 100644 (file)
--- a/src/pkg/runtime/runtime.h
+++ b/src/pkg/runtime/runtime.h
@@ -268,6 +268,7 @@ struct      G
        void*   param;          // passed parameter on wakeup
        int16   status;
        int64   goid;
+       int64   waitsince;      // approx time when the G become blocked
        int8*   waitreason;     // if status==Gwaiting
        G*      schedlink;
        bool    ispanic;