runtime: simplify stack traces

Make the stack traces more readable for new
Go programmers while preserving their utility for old hands.

- Change status number [4] to string.
- Elide frames in runtime package (internal details).
- Swap file:line and arguments.
- Drop 'created by' for main goroutine.
- Show goroutines in order of allocation:
  implies main goroutine first if nothing else.

There is no option to get the extra frames back.
Uncomment 'return 1' at the bottom of symtab.c.

$ 6.out
throw: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
       /Users/rsc/g/go/src/pkg/runtime/x.go:22 +0x8a

goroutine 2 [select (no cases)]:
main.sel()
       /Users/rsc/g/go/src/pkg/runtime/x.go:11 +0x18
created by main.main
       /Users/rsc/g/go/src/pkg/runtime/x.go:19 +0x23

goroutine 3 [chan receive]:
main.recv(0xf8400010a0, 0x0)
       /Users/rsc/g/go/src/pkg/runtime/x.go:15 +0x2e
created by main.main
       /Users/rsc/g/go/src/pkg/runtime/x.go:20 +0x50

goroutine 4 [chan receive (nil chan)]:
main.recv(0x0, 0x0)
       /Users/rsc/g/go/src/pkg/runtime/x.go:15 +0x2e
created by main.main
       /Users/rsc/g/go/src/pkg/runtime/x.go:21 +0x66
$

$ 6.out index
panic: runtime error: index out of range

goroutine 1 [running]:
main.main()
        /Users/rsc/g/go/src/pkg/runtime/x.go:25 +0xb9
$

$ 6.out nil
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x0 pc=0x22ca]

goroutine 1 [running]:
main.main()
        /Users/rsc/g/go/src/pkg/runtime/x.go:28 +0x211
$

$ 6.out panic
panic: panic

goroutine 1 [running]:
main.main()
        /Users/rsc/g/go/src/pkg/runtime/x.go:30 +0x101
$

R=golang-dev, qyzhai, n13m3y3r, r
CC=golang-dev
https://golang.org/cl/4907048

diff --git a/src/pkg/runtime/amd64/traceback.c b/src/pkg/runtime/amd64/traceback.c
index 3e85d36bd7a3299c26a0095f57c9659a578cd8d5..6b758c270d07221337c305a718e49ab75ed55150 100644 (file)
--- a/src/pkg/runtime/amd64/traceback.c
+++ b/src/pkg/runtime/amd64/traceback.c
@@ -123,27 +123,30 @@ runtime·gentraceback(byte *pc0, byte *sp, byte *lr0, G *g, int32 skip, uintptr
                else if(pcbuf != nil)
                        pcbuf[n++] = pc;
                else {
-                       // Print during crash.
-                       //      main+0xf /home/rsc/go/src/runtime/x.go:23
-                       //              main(0x1, 0x2, 0x3)
-                       runtime·printf("%S", f->name);
-                       if(pc > f->entry)
-                               runtime·printf("+%p", (uintptr)(pc - f->entry));
-                       tracepc = pc;   // back up to CALL instruction for funcline.
-                       if(n > 0 && pc > f->entry && !waspanic)
-                               tracepc--;
-                       runtime·printf(" %S:%d\n", f->src, runtime·funcline(f, tracepc));
-                       runtime·printf("\t%S(", f->name);
-                       for(i = 0; i < f->args; i++) {
-                               if(i != 0)
-                                       runtime·prints(", ");
-                               runtime·printhex(((uintptr*)fp)[i]);
-                               if(i >= 4) {
-                                       runtime·prints(", ...");
-                                       break;
+                       if(showframe(f)) {
+                               // Print during crash.
+                               //      main(0x1, 0x2, 0x3)
+                               //              /home/rsc/go/src/runtime/x.go:23 +0xf
+                               //              
+                               tracepc = pc;   // back up to CALL instruction for funcline.
+                               if(n > 0 && pc > f->entry && !waspanic)
+                                       tracepc--;
+                               runtime·printf("%S(", f->name);
+                               for(i = 0; i < f->args; i++) {
+                                       if(i != 0)
+                                               runtime·prints(", ");
+                                       runtime·printhex(((uintptr*)fp)[i]);
+                                       if(i >= 4) {
+                                               runtime·prints(", ...");
+                                               break;
+                                       }
                                }
+                               runtime·prints(")\n");
+                               runtime·printf("\t%S:%d", f->src, runtime·funcline(f, tracepc));
+                               if(pc > f->entry)
+                                       runtime·printf(" +%p", (uintptr)(pc - f->entry));
+                               runtime·printf("\n");
                        }
-                       runtime·prints(")\n");
                        n++;
                }
                
@@ -189,14 +192,16 @@ runtime·gentraceback(byte *pc0, byte *sp, byte *lr0, G *g, int32 skip, uintptr
                fp = nil;
        }
        
-       if(pcbuf == nil && (pc = g->gopc) != 0 && (f = runtime·findfunc(pc)) != nil) {
-               runtime·printf("----- goroutine created by -----\n%S", f->name);
-               if(pc > f->entry)
-                       runtime·printf("+%p", (uintptr)(pc - f->entry));
+       // Show what created goroutine, except main goroutine (goid 1).
+       if(pcbuf == nil && (pc = g->gopc) != 0 && (f = runtime·findfunc(pc)) != nil && g->goid != 1) {
+               runtime·printf("created by %S\n", f->name);
                tracepc = pc;   // back up to CALL instruction for funcline.
                if(n > 0 && pc > f->entry)
                        tracepc--;
-               runtime·printf(" %S:%d\n", f->src, runtime·funcline(f, tracepc));
+               runtime·printf("\t%S:%d", f->src, runtime·funcline(f, tracepc));
+               if(pc > f->entry)
+                       runtime·printf(" +%p", (uintptr)(pc - f->entry));
+               runtime·printf("\n");
        }
                
        return n;

diff --git a/src/pkg/runtime/arm/traceback.c b/src/pkg/runtime/arm/traceback.c
index 5628b8349e04065da251ed1c2722ff33053163cd..f99d738a93253f9dc5cd20f94b5a41b635833c5a 100644 (file)
--- a/src/pkg/runtime/arm/traceback.c
+++ b/src/pkg/runtime/arm/traceback.c
@@ -117,27 +117,29 @@ runtime·gentraceback(byte *pc0, byte *sp, byte *lr0, G *g, int32 skip, uintptr
                else if(pcbuf != nil)
                        pcbuf[n++] = pc;
                else {
-                       // Print during crash.
-                       //      main+0xf /home/rsc/go/src/runtime/x.go:23
-                       //              main(0x1, 0x2, 0x3)
-                       runtime·printf("[%p] %S", fp, f->name);
-                       if(pc > f->entry)
-                               runtime·printf("+%p", (uintptr)(pc - f->entry));
-                       tracepc = pc;   // back up to CALL instruction for funcline.
-                       if(n > 0 && pc > f->entry && !waspanic)
-                               tracepc -= sizeof(uintptr);
-                       runtime·printf(" %S:%d\n", f->src, runtime·funcline(f, tracepc));
-                       runtime·printf("\t%S(", f->name);
-                       for(i = 0; i < f->args; i++) {
-                               if(i != 0)
-                                       runtime·prints(", ");
-                               runtime·printhex(((uintptr*)fp)[1+i]);
-                               if(i >= 4) {
-                                       runtime·prints(", ...");
-                                       break;
+                       if(showframe(f)) {
+                               // Print during crash.
+                               //      main(0x1, 0x2, 0x3)
+                               //              /home/rsc/go/src/runtime/x.go:23 +0xf
+                               tracepc = pc;   // back up to CALL instruction for funcline.
+                               if(n > 0 && pc > f->entry && !waspanic)
+                                       tracepc -= sizeof(uintptr);
+                               runtime·printf("%S(", f->name);
+                               for(i = 0; i < f->args; i++) {
+                                       if(i != 0)
+                                               runtime·prints(", ");
+                                       runtime·printhex(((uintptr*)fp)[1+i]);
+                                       if(i >= 4) {
+                                               runtime·prints(", ...");
+                                               break;
+                                       }
                                }
+                               runtime·prints(")\n");
+                               runtime·printf("\t%S:%d", f->src, runtime·funcline(f, tracepc));
+                               if(pc > f->entry)
+                                       runtime·printf(" +%p", (uintptr)(pc - f->entry));
+                               runtime·printf("\n");
                        }
-                       runtime·prints(")\n");
                        n++;
                }
                
@@ -181,14 +183,15 @@ runtime·gentraceback(byte *pc0, byte *sp, byte *lr0, G *g, int32 skip, uintptr
                        sp += 12;
        }
        
-       if(pcbuf == nil && (pc = g->gopc) != 0 && (f = runtime·findfunc(pc)) != nil) {
-               runtime·printf("----- goroutine created by -----\n%S", f->name);
-               if(pc > f->entry)
-                       runtime·printf("+%p", (uintptr)(pc - f->entry));
+       if(pcbuf == nil && (pc = g->gopc) != 0 && (f = runtime·findfunc(pc)) != nil && g->goid != 1) {
+               runtime·printf("created by %S\n", f->name);
                tracepc = pc;   // back up to CALL instruction for funcline.
                if(n > 0 && pc > f->entry)
                        tracepc -= sizeof(uintptr);
-               runtime·printf(" %S:%d\n", f->src, runtime·funcline(f, tracepc));
+               runtime·printf("\t%S:%d", f->src, runtime·funcline(f, tracepc));
+               if(pc > f->entry)
+                       runtime·printf(" +%p", (uintptr)(pc - f->entry));
+               runtime·printf("\n");
        }
 
        return n;               

diff --git a/src/pkg/runtime/chan.c b/src/pkg/runtime/chan.c
index ef534235388564ca13aec234ac783ee076564e0c..92a6c288bfc885f180a8678ac015f0d6861bc990 100644 (file)
--- a/src/pkg/runtime/chan.c
+++ b/src/pkg/runtime/chan.c
@@ -171,6 +171,7 @@ runtime·chansend(ChanType *t, Hchan *c, byte *ep, bool *pres)
                        return;
                }
                g->status = Gwaiting;
+               g->waitreason = "chan send (nil chan)";
                runtime·gosched();
                return;  // not reached
        }
@@ -217,6 +218,7 @@ runtime·chansend(ChanType *t, Hchan *c, byte *ep, bool *pres)
        mysg.selgen = NOSELGEN;
        g->param = nil;
        g->status = Gwaiting;
+       g->waitreason = "chan send";
        enqueue(&c->sendq, &mysg);
        runtime·unlock(c);
        runtime·gosched();
@@ -244,6 +246,7 @@ asynch:
                mysg.elem = nil;
                mysg.selgen = NOSELGEN;
                g->status = Gwaiting;
+               g->waitreason = "chan send";
                enqueue(&c->sendq, &mysg);
                runtime·unlock(c);
                runtime·gosched();
@@ -293,6 +296,7 @@ runtime·chanrecv(ChanType *t, Hchan* c, byte *ep, bool *selected, bool *receive
                        return;
                }
                g->status = Gwaiting;
+               g->waitreason = "chan receive (nil chan)";
                runtime·gosched();
                return;  // not reached
        }
@@ -332,6 +336,7 @@ runtime·chanrecv(ChanType *t, Hchan* c, byte *ep, bool *selected, bool *receive
        mysg.selgen = NOSELGEN;
        g->param = nil;
        g->status = Gwaiting;
+       g->waitreason = "chan receive";
        enqueue(&c->recvq, &mysg);
        runtime·unlock(c);
        runtime·gosched();
@@ -363,6 +368,7 @@ asynch:
                mysg.elem = nil;
                mysg.selgen = NOSELGEN;
                g->status = Gwaiting;
+               g->waitreason = "chan receive";
                enqueue(&c->recvq, &mysg);
                runtime·unlock(c);
                runtime·gosched();
@@ -780,6 +786,7 @@ void
 runtime·block(void)
 {
        g->status = Gwaiting;   // forever
+       g->waitreason = "select (no cases)";
        runtime·gosched();
 }
 
@@ -912,6 +919,7 @@ loop:
 
        g->param = nil;
        g->status = Gwaiting;
+       g->waitreason = "select";
        selunlock(sel);
        runtime·gosched();
 

diff --git a/src/pkg/runtime/mgc0.c b/src/pkg/runtime/mgc0.c
index 78ea2aa2b9d77c7618255583fc0e71056f703bf0..e79317bf6fb06bec8a8837e6838a053a1e54fab5 100644 (file)
--- a/src/pkg/runtime/mgc0.c
+++ b/src/pkg/runtime/mgc0.c
@@ -697,6 +697,7 @@ runfinq(void)
                if(f == nil) {
                        fingwait = 1;
                        g->status = Gwaiting;
+                       g->waitreason = "finalizer wait";
                        runtime·gosched();
                        continue;
                }

diff --git a/src/pkg/runtime/proc.c b/src/pkg/runtime/proc.c
index dd42675c2ab568824ec2b5ff7981ea07eea99d7b..3a431ef35e0842914f7ed405f7bfcf04f61ccd18 100644 (file)
--- a/src/pkg/runtime/proc.c
+++ b/src/pkg/runtime/proc.c
@@ -249,6 +249,40 @@ runtime·goexit(void)
        runtime·gosched();
 }
 
+void
+runtime·goroutineheader(G *g)
+{
+       int8 *status;
+
+       switch(g->status) {
+       case Gidle:
+               status = "idle";
+               break;
+       case Grunnable:
+               status = "runnable";
+               break;
+       case Grunning:
+               status = "running";
+               break;
+       case Gsyscall:
+               status = "syscall";
+               break;
+       case Gwaiting:
+               if(g->waitreason)
+                       status = g->waitreason;
+               else
+                       status = "waiting";
+               break;
+       case Gmoribund:
+               status = "moribund";
+               break;
+       default:
+               status = "???";
+               break;
+       }
+       runtime·printf("goroutine %d [%s]:\n", g->goid, status);
+}
+
 void
 runtime·tracebackothers(G *me)
 {
@@ -257,7 +291,8 @@ runtime·tracebackothers(G *me)
        for(g = runtime·allg; g != nil; g = g->alllink) {
                if(g == me || g->status == Gdead)
                        continue;
-               runtime·printf("\ngoroutine %d [%d]:\n", g->goid, g->status);
+               runtime·printf("\n");
+               runtime·goroutineheader(g);
                runtime·traceback(g->sched.pc, g->sched.sp, 0, g);
        }
 }
@@ -1073,15 +1108,18 @@ runtime·newproc1(byte *fn, byte *argp, int32 narg, int32 nret, void *callerpc)
        schedlock();
 
        if((newg = gfget()) != nil){
-               newg->status = Gwaiting;
                if(newg->stackguard - StackGuard != newg->stack0)
                        runtime·throw("invalid stack in newg");
        } else {
                newg = runtime·malg(StackMin);
-               newg->status = Gwaiting;
-               newg->alllink = runtime·allg;
-               runtime·allg = newg;
+               if(runtime·lastg == nil)
+                       runtime·allg = newg;
+               else
+                       runtime·lastg->alllink = newg;
+               runtime·lastg = newg;
        }
+       newg->status = Gwaiting;
+       newg->waitreason = "new goroutine";
 
        sp = newg->stackbase;
        sp -= siz;

diff --git a/src/pkg/runtime/runtime.c b/src/pkg/runtime/runtime.c
index 49aba7da018efbca7e0f93cfe9e7ec05c75e5323..c4bd40882936a03948af6f846048526990f9b584 100644 (file)
--- a/src/pkg/runtime/runtime.c
+++ b/src/pkg/runtime/runtime.c
@@ -51,12 +51,15 @@ runtime·dopanic(int32 unused)
        static bool didothers;
 
        if(g->sig != 0)
-               runtime·printf("\n[signal %x code=%p addr=%p pc=%p]\n",
+               runtime·printf("[signal %x code=%p addr=%p pc=%p]\n",
                        g->sig, g->sigcode0, g->sigcode1, g->sigpc);
 
-       runtime·printf("\n");
        if(runtime·gotraceback()){
-               runtime·traceback(runtime·getcallerpc(&unused), runtime·getcallersp(&unused), 0, g);
+               if(g != m->g0) {
+                       runtime·printf("\n");
+                       runtime·goroutineheader(g);
+                       runtime·traceback(runtime·getcallerpc(&unused), runtime·getcallersp(&unused), 0, g);
+               }
                if(!didothers) {
                        didothers = true;
                        runtime·tracebackothers(g);
@@ -703,7 +706,13 @@ runtime·Caller(int32 skip, uintptr retpc, String retfile, int32 retline, bool r
 void
 runtime·Callers(int32 skip, Slice pc, int32 retn)
 {
-       retn = runtime·callers(skip, (uintptr*)pc.array, pc.len);
+       // runtime.callers uses pc.array==nil as a signal
+       // to print a stack trace.  Pick off 0-length pc here
+       // so that we don't let a nil pc slice get to it.
+       if(pc.len == 0)
+               retn = 0;
+       else
+               retn = runtime·callers(skip, (uintptr*)pc.array, pc.len);
        FLUSH(&retn);
 }
 

diff --git a/src/pkg/runtime/runtime.h b/src/pkg/runtime/runtime.h
index bea8636a9f08421524601526ccdcebd068fc9e08..1e52d76ad08d437e6bc648a372b697089c825a4f 100644 (file)
--- a/src/pkg/runtime/runtime.h
+++ b/src/pkg/runtime/runtime.h
@@ -199,6 +199,7 @@ struct      G
        int16   status;
        int32   goid;
        uint32  selgen;         // valid sudog pointer
+       int8*   waitreason;     // if status==Gwaiting
        G*      schedlink;
        bool    readyonstop;
        bool    ispanic;
@@ -384,6 +385,7 @@ struct Panic
 extern Alg     runtime·algarray[Amax];
 extern String  runtime·emptystring;
 G*     runtime·allg;
+G*     runtime·lastg;
 M*     runtime·allm;
 extern int32   runtime·gomaxprocs;
 extern bool    runtime·singleproc;
@@ -434,6 +436,7 @@ String      runtime·gostringnocopy(byte*);
 String runtime·gostringw(uint16*);
 void   runtime·initsig(int32);
 int32  runtime·gotraceback(void);
+void   runtime·goroutineheader(G*);
 void   runtime·traceback(uint8 *pc, uint8 *sp, uint8 *lr, G* gp);
 void   runtime·tracebackothers(G*);
 int32  runtime·write(int32, void*, int32);
@@ -631,6 +634,7 @@ void        runtime·chansend(ChanType*, Hchan*, void*, bool*);
 void   runtime·chanrecv(ChanType*, Hchan*, void*, bool*, bool*);
 int32  runtime·chanlen(Hchan*);
 int32  runtime·chancap(Hchan*);
+bool   runtime·showframe(Func*);
 
 void   runtime·ifaceE2I(struct InterfaceType*, Eface, Iface*);
 

diff --git a/src/pkg/runtime/sema.goc b/src/pkg/runtime/sema.goc
index ae84351edf93af191dadf384dfeb5cf2c0d35dc0..d202a9d0a5a8e940860f7c8c439a5dc7fef26cc8 100644 (file)
--- a/src/pkg/runtime/sema.goc
+++ b/src/pkg/runtime/sema.goc
@@ -129,6 +129,7 @@ runtime·semacquire(uint32 volatile *addr)
                // (we set nwait above), so go to sleep.
                semqueue(root, addr, &s);
                g->status = Gwaiting;
+               g->waitreason = "semacquire";
                runtime·unlock(root);
                runtime·gosched();
                if(cansemacquire(addr))

diff --git a/src/pkg/runtime/symtab.c b/src/pkg/runtime/symtab.c
index d2ebf9b400ffc067e78d4aeac3c0fc25cb2ad438..b9035119fe2604c0b58bc2e2a8bd28a180c11115 100644 (file)
--- a/src/pkg/runtime/symtab.c
+++ b/src/pkg/runtime/symtab.c
@@ -464,3 +464,40 @@ runtime·findfunc(uintptr addr)
        runtime·prints("findfunc unreachable\n");
        return nil;
 }
+
+static bool
+hasprefix(String s, int8 *p)
+{
+       int32 i;
+       
+       for(i=0; i<s.len; i++) {
+               if(p[i] == 0)
+                       return 1;
+               if(p[i] != s.str[i])
+                       return 0;
+       }
+       return p[i] == 0;
+}
+
+static bool
+contains(String s, int8 *p)
+{
+       int32 i;
+       
+       if(p[0] == 0)
+               return 1;
+       for(i=0; i<s.len; i++) {
+               if(s.str[i] != p[0])
+                       continue;
+               if(hasprefix((String){s.str + i, s.len - i}, p))
+                       return 1;
+       }
+       return 0;
+}
+
+bool
+showframe(Func *f)
+{
+       // return 1;  // for debugging - show all frames
+       return contains(f->name, ".") && !hasprefix(f->name, "runtime.");
+}

diff --git a/test/golden.out b/test/golden.out
index 655ceda5653d6e91adbfcd0938e8fea3e45dc5e8..d2a104b79879bbbf59a3820d74061c3a02dfa64e 100644 (file)
--- a/test/golden.out
+++ b/test/golden.out
@@ -4,19 +4,15 @@
 =========== ./cmp2.go
 panic: runtime error: comparing uncomparable type []int
 
-
 =========== ./cmp3.go
 panic: runtime error: comparing uncomparable type []int
 
-
 =========== ./cmp4.go
 panic: runtime error: hash of unhashable type []int
 
-
 =========== ./cmp5.go
 panic: runtime error: hash of unhashable type []int
 
-
 =========== ./deferprint.go
 printing: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
 42 true false true +1.500000e+000 world 0x0 [0/0]0x0 0x0 0x0 255
@@ -115,11 +111,9 @@ PASS
 =========== interface/fail.go
 panic: interface conversion: *main.S is not main.I: missing method Foo
 
-
 =========== interface/returntype.go
 panic: interface conversion: *main.S is not main.I2: missing method Name
 
-
 == nilptr/
 
 == syntax/
@@ -154,12 +148,10 @@ M
 =========== fixedbugs/bug113.go
 panic: interface conversion: interface is int, not int32
 
-
 =========== fixedbugs/bug148.go
 2 3
 panic: interface conversion: interface is main.T, not main.T
 
-
 =========== fixedbugs/bug328.go
 0x0