runtime: improve stack barrier debugging

This improves stack barrier debugging messages in various ways:

1) Rather than printing only the remaining stack barriers (of which
   there may be none, which isn't very useful), print all of the G's
   stack barriers with a marker at the position the stack itself has
   unwound to and a marker at the problematic stack barrier (where
   applicable).

2) Rather than crashing if we encounter a stack barrier when there are
   no more stkbar entries, print the same debug message we would if we
   had encountered a stack barrier at an unexpected location.

Hopefully this will help with debugging #12528.

Change-Id: I2e6fe6a778e0d36dd8ef30afd4c33d5d94731262
Reviewed-on: https://go-review.googlesource.com/17147
Reviewed-by: Rick Hudson <rlh@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>

diff --git a/src/runtime/mstkbar.go b/src/runtime/mstkbar.go
index 1c1c2eaf0a323c37546fa0196aff2b629a198e69..6b4fc8d4a6a08b98cbb67754897a042e91ef7532 100644 (file)
--- a/src/runtime/mstkbar.go
+++ b/src/runtime/mstkbar.go
@@ -231,22 +231,36 @@ func gcRemoveStackBarrier(gp *g, stkbar stkbar) {
                printlock()
                print("at *", hex(stkbar.savedLRPtr), " expected stack barrier PC ", hex(stackBarrierPC), ", found ", hex(val), ", goid=", gp.goid, "\n")
                print("gp.stkbar=")
-               gcPrintStkbars(gp.stkbar)
-               print(", gp.stkbarPos=", gp.stkbarPos, ", gp.stack=[", hex(gp.stack.lo), ",", hex(gp.stack.hi), ")\n")
+               gcPrintStkbars(gp, -1)
+               print(", gp.stack=[", hex(gp.stack.lo), ",", hex(gp.stack.hi), ")\n")
                throw("stack barrier lost")
        }
        *lrPtr = sys.Uintreg(stkbar.savedLRVal)
 }
 
-// gcPrintStkbars prints a []stkbar for debugging.
-func gcPrintStkbars(stkbar []stkbar) {
+// gcPrintStkbars prints the stack barriers of gp for debugging. It
+// places a "@@@" marker at gp.stkbarPos. If marker >= 0, it will also
+// place a "==>" marker before the marker'th entry.
+func gcPrintStkbars(gp *g, marker int) {
        print("[")
-       for i, s := range stkbar {
+       for i, s := range gp.stkbar {
                if i > 0 {
                        print(" ")
                }
+               if i == int(gp.stkbarPos) {
+                       print("@@@ ")
+               }
+               if i == marker {
+                       print("==> ")
+               }
                print("*", hex(s.savedLRPtr), "=", hex(s.savedLRVal))
        }
+       if int(gp.stkbarPos) == len(gp.stkbar) {
+               print(" @@@")
+       }
+       if marker == len(gp.stkbar) {
+               print(" ==>")
+       }
        print("]")
 }
 
@@ -271,7 +285,9 @@ func gcUnwindBarriers(gp *g, sp uintptr) {
        gcUnlockStackBarriers(gp)
        if debugStackBarrier && gp.stkbarPos != before {
                print("skip barriers below ", hex(sp), " in goid=", gp.goid, ": ")
-               gcPrintStkbars(gp.stkbar[before:gp.stkbarPos])
+               // We skipped barriers between the "==>" marker
+               // (before) and the "@@@" marker (gp.stkbarPos).
+               gcPrintStkbars(gp, int(before))
                print("\n")
        }
 }

diff --git a/src/runtime/traceback.go b/src/runtime/traceback.go
index 1743a93507a5e427a2f22ba8fdc8b949de90e2cb..ee58473a13a617fab7411b53dcf5b65d3e3d8191 100644 (file)
--- a/src/runtime/traceback.go
+++ b/src/runtime/traceback.go
@@ -144,7 +144,8 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
 
        // Fix up returns to the stack barrier by fetching the
        // original return PC from gp.stkbar.
-       stkbar := gp.stkbar[gp.stkbarPos:]
+       stkbarG := gp
+       stkbar := stkbarG.stkbar[stkbarG.stkbarPos:]
 
        if pc0 == ^uintptr(0) && sp0 == ^uintptr(0) { // Signal to fetch saved values from gp.
                if gp.syscallsp != 0 {
@@ -208,8 +209,8 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
                        stkbarPos = gp.stkbarPos - 1
                } else {
                        printlock()
-                       print("runtime: failed to unwind through stackBarrier at SP ", hex(sp0), " index ", gp.stkbarPos, "; ")
-                       gcPrintStkbars(gp.stkbar)
+                       print("runtime: failed to unwind through stackBarrier at SP ", hex(sp0), "; ")
+                       gcPrintStkbars(gp, int(gp.stkbarPos))
                        print("\n")
                        throw("inconsistent state in stackBarrier")
                }
@@ -248,7 +249,8 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
                        sp := frame.sp
                        if flags&_TraceJumpStack != 0 && f.entry == systemstackPC && gp == g.m.g0 && gp.m.curg != nil {
                                sp = gp.m.curg.sched.sp
-                               stkbar = gp.m.curg.stkbar[gp.m.curg.stkbarPos:]
+                               stkbarG = gp.m.curg
+                               stkbar = stkbarG.stkbar[stkbarG.stkbarPos:]
                        }
                        frame.fp = sp + uintptr(funcspdelta(f, frame.pc, &cache))
                        if !usesLR {
@@ -286,9 +288,9 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
                        }
                        if frame.lr == stackBarrierPC {
                                // Recover original PC.
-                               if stkbar[0].savedLRPtr != lrPtr {
+                               if len(stkbar) == 0 || stkbar[0].savedLRPtr != lrPtr {
                                        print("found next stack barrier at ", hex(lrPtr), "; expected ")
-                                       gcPrintStkbars(stkbar)
+                                       gcPrintStkbars(stkbarG, len(stkbarG.stkbar)-len(stkbar))
                                        print("\n")
                                        throw("missed stack barrier")
                                }
@@ -505,7 +507,7 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
 
        if callback != nil && n < max && len(stkbar) > 0 {
                print("runtime: g", gp.goid, ": leftover stack barriers ")
-               gcPrintStkbars(stkbar)
+               gcPrintStkbars(stkbarG, len(stkbarG.stkbar)-len(stkbar))
                print("\n")
                throw("traceback has leftover stack barriers")
        }