[release-branch.go1.5] 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/17147Reviewed-by: Rick Hudson <rlh@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
Reviewed-on: https://go-review.googlesource.com/17193
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

src/runtime/mgcmark.go

@@ -608,22 +608,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 = 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("]")
 }
 
@@ -648,7 +662,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")
 	}
 }

src/runtime/traceback.go

@@ -142,7 +142,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 {
@@ -206,8 +207,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")
 		}
@@ -244,7 +245,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))
 			if !usesLR {
@@ -282,9 +284,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")
 				}
@@ -504,7 +506,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")
 	}