[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

diff --git a/src/cmd/gc/builtin.c b/src/cmd/gc/builtin.c
index bd3fca167f5f95cd3e51af1cad3a698abef5951f..aeeadedca67cfc1e1cbc65398a2240cf240e6144 100644 (file)
--- a/src/cmd/gc/builtin.c
+++ b/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"

diff --git a/src/cmd/gc/go.h b/src/cmd/gc/go.h
index 965a0550d3683b64c097e8a6f07bb586d4180504..cc590416bdc22eaf4c3f4c2c3d6449b2b07436ff 100644 (file)
--- a/src/cmd/gc/go.h
+++ b/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*);

diff --git a/src/cmd/gc/runtime.go b/src/cmd/gc/runtime.go
index 38bf6abb60278b7fe8cddfc3531cf07c2b66c818..c6007714ce2ee616260402f752cbbb8c5faf0fd3 100644 (file)
--- a/src/cmd/gc/runtime.go
+++ b/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

diff --git a/src/cmd/gc/walk.c b/src/cmd/gc/walk.c
index 7b502eb60cf78ae7ac9c39d731f5668e0a5288ff..38bed1e22f7091165f2086a3650e6a73e0eebeda 100644 (file)
--- a/src/cmd/gc/walk.c
+++ b/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);
 

diff --git a/src/runtime/print1.go b/src/runtime/print1.go
index 8f8268873b21ede2e671f453179651a74e396b81..3d812bd04422facaea45ab9a37d402b39362be1b 100644 (file)
--- a/src/runtime/print1.go
+++ b/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) {

diff --git a/src/runtime/runtime.h b/src/runtime/runtime.h
index 6a02ef1d31d47fa9ad7ef1a1dcde0c985c717e07..ee86f2d1765af1cb778fb5d03fdd083bda627775 100644 (file)
--- a/src/runtime/runtime.h
+++ b/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

diff --git a/test/live.go b/test/live.go
index f15bb74ba1896f804bc005bce8923a1e7b0c60dc..55a1bd35d16c80ebe60a42f8beb49a777384d07b 100644 (file)
--- a/test/live.go
+++ b/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
 }

diff --git a/test/live2.go b/test/live2.go
index ef6ad994cc084af55c6c7baa85224d1aaecd6709..1bd0af2cc18654f62d6e637f2e99617e95bea63e 100644 (file)
--- a/test/live2.go
+++ b/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
 }