[dev.garbage] cmd/gc, runtime: add locks around print statements

Now each C printf, Go print, or Go println is guaranteed
not to be interleaved with other calls of those functions.
This should help when debugging concurrent failures.

LGTM=rlh
R=rlh
CC=golang-codereviews
https://golang.org/cl/169120043

src/cmd/gc/builtin.c

@@ -24,6 +24,8 @@ char *runtimeimport =
 	"func @\"\".printslice (? any)\n"
 	"func @\"\".printnl ()\n"
 	"func @\"\".printsp ()\n"
+	"func @\"\".printlock ()\n"
+	"func @\"\".printunlock ()\n"
 	"func @\"\".concatstring2 (? string, ? string) (? string)\n"
 	"func @\"\".concatstring3 (? string, ? string, ? string) (? string)\n"
 	"func @\"\".concatstring4 (? string, ? string, ? string, ? string) (? string)\n"

src/cmd/gc/go.h

@@ -1464,6 +1464,7 @@ void	walk(Node *fn);
 void	walkexpr(Node **np, NodeList **init);
 void	walkexprlist(NodeList *l, NodeList **init);
 void	walkexprlistsafe(NodeList *l, NodeList **init);
+void	walkexprlistcheap(NodeList *l, NodeList **init);
 void	walkstmt(Node **np);
 void	walkstmtlist(NodeList *l);
 Node*	conv(Node*, Type*);

src/cmd/gc/runtime.go

@@ -36,6 +36,8 @@ func printeface(any)
 func printslice(any)
 func printnl()
 func printsp()
+func printlock()
+func printunlock()
 
 func concatstring2(string, string) string
 func concatstring3(string, string, string) string

src/cmd/gc/walk.c

@@ -363,6 +363,15 @@ walkexprlistsafe(NodeList *l, NodeList **init)
 	}
 }
 
+void
+walkexprlistcheap(NodeList *l, NodeList **init)
+{
+	for(; l; l=l->next) {
+		l->n = cheapexpr(l->n, init);
+		walkexpr(&l->n, init);
+	}
+}
+
 void
 walkexpr(Node **np, NodeList **init)
 {
@@ -1773,6 +1782,11 @@ walkprint(Node *nn, NodeList **init)
 	calls = nil;
 	notfirst = 0;
 
+	// Hoist all the argument evaluation up before the lock.
+	walkexprlistcheap(all, init);
+
+	calls = list(calls, mkcall("printlock", T, init));
+
 	for(l=all; l; l=l->next) {
 		if(notfirst) {
 			calls = list(calls, mkcall("printsp", T, init));
@@ -1853,6 +1867,9 @@ walkprint(Node *nn, NodeList **init)
 
 	if(op == OPRINTN)
 		calls = list(calls, mkcall("printnl", T, nil));
+
+	calls = list(calls, mkcall("printunlock", T, init));
+
 	typechecklist(calls, Etop);
 	walkexprlist(calls, init);
 

src/runtime/print1.go

@@ -41,7 +41,31 @@ func snprintf(dst *byte, n int32, s *byte) {
 	gp.writebuf = nil
 }
 
-//var debuglock mutex
+var debuglock mutex
+
+// The compiler emits calls to printlock and printunlock around
+// the multiple calls that implement a single Go print or println
+// statement. Some of the print helpers (printsp, for example)
+// call print recursively. There is also the problem of a crash
+// happening during the print routines and needing to acquire
+// the print lock to print information about the crash.
+// For both these reasons, let a thread acquire the printlock 'recursively'.
+
+func printlock() {
+	mp := getg().m
+	mp.printlock++
+	if mp.printlock == 1 {
+		lock(&debuglock)
+	}
+}
+
+func printunlock() {
+	mp := getg().m
+	mp.printlock--
+	if mp.printlock == 0 {
+		unlock(&debuglock)
+	}
+}
 
 // write to goroutine-local buffer if diverting output,
 // or else standard error.
@@ -80,7 +104,7 @@ func printnl() {
 // Very simple printf.  Only for debugging prints.
 // Do not add to this without checking with Rob.
 func vprintf(str string, arg unsafe.Pointer) {
-	//lock(&debuglock);
+	printlock()
 
 	s := bytes(str)
 	start := 0
@@ -160,7 +184,7 @@ func vprintf(str string, arg unsafe.Pointer) {
 		gwrite(s[start:i])
 	}
 
-	//unlock(&debuglock);
+	printunlock()
 }
 
 func printpc(p unsafe.Pointer) {

src/runtime/runtime.h

@@ -345,6 +345,7 @@ struct	M
 	int32	helpgc;
 	bool	spinning;	// M is out of work and is actively looking for work
 	bool	blocked;	// M is blocked on a Note
+	int8	printlock;
 	uint32	fastrand;
 	uint64	ncgocall;	// number of cgo calls in total
 	int32	ncgo;		// number of cgo calls currently in progress

test/live.go

@@ -9,20 +9,39 @@
 
 package main
 
+func printnl()
+
+//go:noescape
+func printpointer(**int)
+
+//go:noescape
+func printintpointer(*int)
+
+//go:noescape
+func printstringpointer(*string)
+
+//go:noescape
+func printstring(string)
+
+//go:noescape
+func printbytepointer(*byte)
+
+func printint(int)
+
 func f1() {
 	var x *int
-	print(&x) // ERROR "live at call to printpointer: x$"
-	print(&x) // ERROR "live at call to printpointer: x$"
+	printpointer(&x) // ERROR "live at call to printpointer: x$"
+	printpointer(&x) // ERROR "live at call to printpointer: x$"
 }
 
 func f2(b bool) {
 	if b {
-		print(0) // nothing live here
+		printint(0) // nothing live here
 		return
 	}
 	var x *int
-	print(&x) // ERROR "live at call to printpointer: x$"
-	print(&x) // ERROR "live at call to printpointer: x$"
+	printpointer(&x) // ERROR "live at call to printpointer: x$"
+	printpointer(&x) // ERROR "live at call to printpointer: x$"
 }
 
 func f3(b bool) {
@@ -30,22 +49,22 @@ func f3(b bool) {
 	// live throughout the function, to avoid being poisoned
 	// in GODEBUG=gcdead=1 mode.
 
-	print(0) // ERROR "live at call to printint: x y$"
+	printint(0) // ERROR "live at call to printint: x y$"
 	if b == false {
-		print(0) // ERROR "live at call to printint: x y$"
+		printint(0) // ERROR "live at call to printint: x y$"
 		return
 	}
 
 	if b {
 		var x *int
-		print(&x) // ERROR "live at call to printpointer: x y$"
-		print(&x) // ERROR "live at call to printpointer: x y$"
+		printpointer(&x) // ERROR "live at call to printpointer: x y$"
+		printpointer(&x) // ERROR "live at call to printpointer: x y$"
 	} else {
 		var y *int
-		print(&y) // ERROR "live at call to printpointer: x y$"
-		print(&y) // ERROR "live at call to printpointer: x y$"
+		printpointer(&y) // ERROR "live at call to printpointer: x y$"
+		printpointer(&y) // ERROR "live at call to printpointer: x y$"
 	}
-	print(0) // ERROR "live at call to printint: x y$" "x \(type \*int\) is ambiguously live" "y \(type \*int\) is ambiguously live"
+	printint(0) // ERROR "live at call to printint: x y$" "x \(type \*int\) is ambiguously live" "y \(type \*int\) is ambiguously live"
 }
 
 // The old algorithm treated x as live on all code that
@@ -56,20 +75,20 @@ func f3(b bool) {
 
 func f4(b1, b2 bool) { // x not live here
 	if b2 {
-		print(0) // x not live here
+		printint(0) // x not live here
 		return
 	}
 	var z **int
 	x := new(int)
 	*x = 42
 	z = &x
-	print(**z) // ERROR "live at call to printint: x z$"
+	printint(**z) // ERROR "live at call to printint: x z$"
 	if b2 {
-		print(1) // ERROR "live at call to printint: x$"
+		printint(1) // ERROR "live at call to printint: x$"
 		return
 	}
 	for {
-		print(**z) // ERROR "live at call to printint: x z$"
+		printint(**z) // ERROR "live at call to printint: x z$"
 	}
 }
 
@@ -84,7 +103,7 @@ func f5(b1 bool) {
 		*y = 54
 		z = &y
 	}
-	print(**z) // ERROR "live at call to printint: x y$" "x \(type \*int\) is ambiguously live" "y \(type \*int\) is ambiguously live"
+	printint(**z) // ERROR "live at call to printint: x y$" "x \(type \*int\) is ambiguously live" "y \(type \*int\) is ambiguously live"
 }
 
 // confusion about the _ result used to cause spurious "live at entry to f6: _".
@@ -155,8 +174,8 @@ func f11b() *int {
 		// At this point p is dead: the code here cannot
 		// get to the bottom of the function.
 		// This used to have a spurious "live at call to printint: p".
-		print(1) // nothing live here!
-		select { // ERROR "live at call to newselect: autotmp" "live at call to selectgo: autotmp"
+		printint(1) // nothing live here!
+		select {    // ERROR "live at call to newselect: autotmp" "live at call to selectgo: autotmp"
 		case <-c: // ERROR "live at call to selectrecv: autotmp"
 			return nil
 		case <-c: // ERROR "live at call to selectrecv: autotmp"
@@ -172,8 +191,8 @@ func f11c() *int {
 	if b {
 		// Unlike previous, the cases in this select fall through,
 		// so we can get to the println, so p is not dead.
-		print(1) // ERROR "live at call to printint: p"
-		select { // ERROR "live at call to newselect: autotmp.* p" "live at call to selectgo: autotmp.* p"
+		printint(1) // ERROR "live at call to printint: p"
+		select {    // ERROR "live at call to newselect: autotmp.* p" "live at call to selectgo: autotmp.* p"
 		case <-c: // ERROR "live at call to selectrecv: autotmp.* p"
 		case <-c: // ERROR "live at call to selectrecv: autotmp.* p"
 		}
@@ -209,7 +228,7 @@ func h13(string, string) string
 
 func f14() {
 	x := g14()
-	print(&x) // ERROR "live at call to printpointer: x"
+	printstringpointer(&x) // ERROR "live at call to printstringpointer: x"
 }
 
 func g14() string
@@ -217,8 +236,8 @@ func g14() string
 func f15() {
 	var x string
 	_ = &x
-	x = g15() // ERROR "live at call to g15: x"
-	print(x)  // ERROR "live at call to printstring: x"
+	x = g15()      // ERROR "live at call to g15: x"
+	printstring(x) // ERROR "live at call to printstring: x"
 }
 
 func g15() string
@@ -282,7 +301,7 @@ func f18() {
 	}
 	z = m2[g18()] // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
 	z = m2[g18()] // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-	print(z)
+	printbytepointer(z)
 }
 
 var ch chan *byte
@@ -296,7 +315,7 @@ func f19() {
 	}
 	z = <-ch // ERROR "live at call to chanrecv1: autotmp_[0-9]+$"
 	z = <-ch // ERROR "live at call to chanrecv1: autotmp_[0-9]+$"
-	print(z)
+	printbytepointer(z)
 }
 
 func f20() {
@@ -316,7 +335,7 @@ func f21() {
 	}
 	z = m2[[2]string{"x", "y"}] // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
 	z = m2[[2]string{"x", "y"}] // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-	print(z)
+	printbytepointer(z)
 }
 
 func f23() {
@@ -328,7 +347,8 @@ func f23() {
 	}
 	z, ok = m2[[2]string{"x", "y"}] // ERROR "live at call to mapaccess2: autotmp_[0-9]+$"
 	z, ok = m2[[2]string{"x", "y"}] // ERROR "live at call to mapaccess2: autotmp_[0-9]+$"
-	print(z, ok)
+	printbytepointer(z)
+	print(ok)
 }
 
 func f24() {
@@ -350,8 +370,8 @@ func f25(b bool) {
 	}
 	var x string
 	_ = &x
-	x = g15() // ERROR "live at call to g15: x"
-	print(x)  // ERROR "live at call to printstring: x"
+	x = g15()      // ERROR "live at call to g15: x"
+	printstring(x) // ERROR "live at call to printstring: x"
 } // ERROR "live at call to deferreturn: x"
 
 func g25()
@@ -366,7 +386,7 @@ func f26(b bool) {
 	}
 	print26((*int)(nil), (*int)(nil), (*int)(nil)) // ERROR "live at call to print26: autotmp_[0-9]+$"
 	print26((*int)(nil), (*int)(nil), (*int)(nil)) // ERROR "live at call to print26: autotmp_[0-9]+$"
-	println()
+	printnl()
 }
 
 //go:noescape
@@ -381,7 +401,7 @@ func f27(b bool) {
 	}
 	call27(func() { x++ }) // ERROR "live at call to call27: autotmp_[0-9]+$"
 	call27(func() { x++ }) // ERROR "live at call to call27: autotmp_[0-9]+$"
-	println()
+	printnl()
 }
 
 // but defer does escape to later execution in the function
@@ -392,7 +412,7 @@ func f27defer(b bool) {
 		defer call27(func() { x++ }) // ERROR "live at call to deferproc: autotmp_[0-9]+$" "live at call to deferreturn: autotmp_[0-9]+$"
 	}
 	defer call27(func() { x++ }) // ERROR "live at call to deferproc: autotmp_[0-9]+ autotmp_[0-9]+$" "live at call to deferreturn: autotmp_[0-9]+ autotmp_[0-9]+$" "ambiguously live"
-	println()                    // ERROR "live at call to printnl: autotmp_[0-9]+ autotmp_[0-9]+$"
+	printnl()                    // ERROR "live at call to printnl: autotmp_[0-9]+ autotmp_[0-9]+$"
 } // ERROR "live at call to deferreturn: autotmp_[0-9]+ autotmp_[0-9]+$"
 
 // and newproc (go) escapes to the heap
@@ -403,7 +423,7 @@ func f27go(b bool) {
 		go call27(func() { x++ }) // ERROR "live at call to newobject: &x" "live at call to newproc: &x$"
 	}
 	go call27(func() { x++ }) // ERROR "live at call to newobject: &x"
-	println()
+	printnl()
 }
 
 //go:noescape
@@ -415,10 +435,10 @@ var s1, s2, s3, s4, s5, s6, s7, s8, s9, s10 string
 
 func f28(b bool) {
 	if b {
-		print(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
+		printstring(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
 	}
-	print(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
-	print(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
+	printstring(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
+	printstring(s1 + s2 + s3 + s4 + s5 + s6 + s7 + s8 + s9 + s10) // ERROR "live at call to concatstrings: autotmp_[0-9]+$" "live at call to printstring: autotmp_[0-9]+$"
 }
 
 // map iterator should die on end of range loop
@@ -426,14 +446,14 @@ func f28(b bool) {
 func f29(b bool) {
 	if b {
 		for k := range m { // ERROR "live at call to mapiterinit: autotmp_[0-9]+$" "live at call to mapiternext: autotmp_[0-9]+$"
-			print(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
+			printstring(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
 		}
 	}
 	for k := range m { // ERROR "live at call to mapiterinit: autotmp_[0-9]+$" "live at call to mapiternext: autotmp_[0-9]+$"
-		print(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
+		printstring(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
 	}
 	for k := range m { // ERROR "live at call to mapiterinit: autotmp_[0-9]+$" "live at call to mapiternext: autotmp_[0-9]+$"
-		print(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
+		printstring(k) // ERROR "live at call to printstring: autotmp_[0-9]+$"
 	}
 }
 
@@ -446,14 +466,14 @@ func f30(b bool) {
 	// the copy of ptrarr and the internal iterator pointer.
 	if b {
 		for _, p := range ptrarr {
-			print(p) // ERROR "live at call to printpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
+			printintpointer(p) // ERROR "live at call to printintpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
 		}
 	}
 	for _, p := range ptrarr {
-		print(p) // ERROR "live at call to printpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
+		printintpointer(p) // ERROR "live at call to printintpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
 	}
 	for _, p := range ptrarr {
-		print(p) // ERROR "live at call to printpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
+		printintpointer(p) // ERROR "live at call to printintpointer: autotmp_[0-9]+ autotmp_[0-9]+$"
 	}
 }
 
@@ -503,44 +523,44 @@ var m33 map[interface{}]int
 
 func f33() {
 	if m33[nil] == 0 { // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-		println()
+		printnl()
 		return
 	} else {
-		println()
+		printnl()
 	}
-	println()
+	printnl()
 }
 
 func f34() {
 	if m33[nil] == 0 { // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-		println()
+		printnl()
 		return
 	}
-	println()
+	printnl()
 }
 
 func f35() {
 	if m33[nil] == 0 && m33[nil] == 0 { // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-		println()
+		printnl()
 		return
 	}
-	println()
+	printnl()
 }
 
 func f36() {
 	if m33[nil] == 0 || m33[nil] == 0 { // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-		println()
+		printnl()
 		return
 	}
-	println()
+	printnl()
 }
 
 func f37() {
 	if (m33[nil] == 0 || m33[nil] == 0) && m33[nil] == 0 { // ERROR "live at call to mapaccess1: autotmp_[0-9]+$"
-		println()
+		printnl()
 		return
 	}
-	println()
+	printnl()
 }
 
 // select temps should disappear in the case bodies
@@ -558,44 +578,44 @@ func f38(b bool) {
 	if b {
 		select { // ERROR "live at call"
 		case <-fc38(): // ERROR "live at call"
-			println()
+			printnl()
 		case fc38() <- *fi38(1): // ERROR "live at call"
-			println()
+			printnl()
 		case *fi38(2) = <-fc38(): // ERROR "live at call"
-			println()
+			printnl()
 		case *fi38(3), *fb38() = <-fc38(): // ERROR "live at call"
-			println()
+			printnl()
 		}
-		println()
+		printnl()
 	}
-	println()
+	printnl()
 }
 
 // issue 8097: mishandling of x = x during return.
 
 func f39() (x []int) {
 	x = []int{1}
-	println() // ERROR "live at call to printnl: x"
+	printnl() // ERROR "live at call to printnl: x"
 	return x
 }
 
 func f39a() (x []int) {
 	x = []int{1}
-	println() // ERROR "live at call to printnl: x"
+	printnl() // ERROR "live at call to printnl: x"
 	return
 }
 
 func f39b() (x [10]*int) {
 	x = [10]*int{}
 	x[0] = new(int) // ERROR "live at call to newobject: x"
-	println()       // ERROR "live at call to printnl: x"
+	printnl()       // ERROR "live at call to printnl: x"
 	return x
 }
 
 func f39c() (x [10]*int) {
 	x = [10]*int{}
 	x[0] = new(int) // ERROR "live at call to newobject: x"
-	println()       // ERROR "live at call to printnl: x"
+	printnl()       // ERROR "live at call to printnl: x"
 	return
 }
 
@@ -614,7 +634,7 @@ func newT40() *T40 {
 
 func bad40() {
 	t := newT40()
-	println()
+	printnl()
 	_ = t
 }
 
@@ -622,6 +642,6 @@ func good40() {
 	ret := T40{}
 	ret.m = make(map[int]int) // ERROR "live at call to makemap: ret"
 	t := &ret
-	println() // ERROR "live at call to printnl: ret"
+	printnl() // ERROR "live at call to printnl: ret"
 	_ = t
 }

test/live2.go

@@ -12,6 +12,8 @@ package main
 // issue 8142: lost 'addrtaken' bit on inlined variables.
 // no inlining in this test, so just checking that non-inlined works.
 
+func printnl()
+
 type T40 struct {
 	m map[int]int
 }
@@ -24,7 +26,7 @@ func newT40() *T40 {
 
 func bad40() {
 	t := newT40() // ERROR "live at call to makemap: ret"
-	println()     // ERROR "live at call to printnl: ret"
+	printnl()     // ERROR "live at call to printnl: ret"
 	_ = t
 }
 
@@ -32,6 +34,6 @@ func good40() {
 	ret := T40{}
 	ret.m = make(map[int]int) // ERROR "live at call to makemap: ret"
 	t := &ret
-	println() // ERROR "live at call to printnl: ret"
+	printnl() // ERROR "live at call to printnl: ret"
 	_ = t
 }