runtime: ring buffer for binary debug logging

This adds an internal runtime debug log. It uses per-M time-stamped
ring buffers of binary log records. On panic, these buffers are
collected, interleaved, and printed.

The entry-point to the debug log is a new "dlog" function. dlog is
designed so it can be used even from very constrained corners of the
runtime such as signal handlers or inside the write barrier.

The facility is only enabled if the debuglog build tag is set.
Otherwise, it compiles away to a no-op implementation.

The debug log format is also designed so it would be reasonable to
decode from a core dump, though this hasn't been implemented.

Change-Id: I6e2737c286358e97a0d8091826498070b95b66a3
Reviewed-on: https://go-review.googlesource.com/c/go/+/157997
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Michael Knyszek <mknyszek@google.com>

src/runtime/debuglog_off.go

+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// +build !debuglog
+
+package runtime
+
+const dlogEnabled = false
+
+type dlogPerM struct{}
+
+func getCachedDlogger() *dlogger {
+	return nil
+}
+
+func putCachedDlogger(l *dlogger) bool {
+	return false
+}

src/runtime/debuglog_on.go

+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// +build debuglog
+
+package runtime
+
+const dlogEnabled = true
+
+// dlogPerM is the per-M debug log data. This is embedded in the m
+// struct.
+type dlogPerM struct {
+	dlogCache *dlogger
+}
+
+// getCachedDlogger returns a cached dlogger if it can do so
+// efficiently, or nil otherwise. The returned dlogger will be owned.
+func getCachedDlogger() *dlogger {
+	mp := acquirem()
+	// We don't return a cached dlogger if we're running on the
+	// signal stack in case the signal arrived while in
+	// get/putCachedDlogger. (Too bad we don't have non-atomic
+	// exchange!)
+	var l *dlogger
+	if getg() != mp.gsignal {
+		l = mp.dlogCache
+		mp.dlogCache = nil
+	}
+	releasem(mp)
+	return l
+}
+
+// putCachedDlogger attempts to return l to the local cache. It
+// returns false if this fails.
+func putCachedDlogger(l *dlogger) bool {
+	mp := acquirem()
+	if getg() != mp.gsignal && mp.dlogCache == nil {
+		mp.dlogCache = l
+		releasem(mp)
+		return true
+	}
+	releasem(mp)
+	return false
+}

src/runtime/debuglog_test.go

+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// TODO(austin): All of these tests are skipped if the debuglog build
+// tag isn't provided. That means we basically never test debuglog.
+// There are two potential ways around this:
+//
+// 1. Make these tests re-build the runtime test with the debuglog
+// build tag and re-invoke themselves.
+//
+// 2. Always build the whole debuglog infrastructure and depend on
+// linker dead-code elimination to drop it. This is easy for dlog()
+// since there won't be any calls to it. For printDebugLog, we can
+// make panic call a wrapper that is call printDebugLog if the
+// debuglog build tag is set, or otherwise do nothing. Then tests
+// could call printDebugLog directly. This is the right answer in
+// principle, but currently our linker reads in all symbols
+// regardless, so this would slow down and bloat all links. If the
+// linker gets more efficient about this, we should revisit this
+// approach.
+
+package runtime_test
+
+import (
+	"bytes"
+	"fmt"
+	"regexp"
+	"runtime"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"testing"
+)
+
+func skipDebugLog(t *testing.T) {
+	if !runtime.DlogEnabled {
+		t.Skip("debug log disabled (rebuild with -tags debuglog)")
+	}
+}
+
+func dlogCanonicalize(x string) string {
+	begin := regexp.MustCompile(`(?m)^>> begin log \d+ <<\n`)
+	x = begin.ReplaceAllString(x, "")
+	prefix := regexp.MustCompile(`(?m)^\[[^]]+\]`)
+	x = prefix.ReplaceAllString(x, "[]")
+	return x
+}
+
+func TestDebugLog(t *testing.T) {
+	skipDebugLog(t)
+	runtime.ResetDebugLog()
+	runtime.Dlog().S("testing").End()
+	got := dlogCanonicalize(runtime.DumpDebugLog())
+	if want := "[] testing\n"; got != want {
+		t.Fatalf("want %q, got %q", want, got)
+	}
+}
+
+func TestDebugLogTypes(t *testing.T) {
+	skipDebugLog(t)
+	runtime.ResetDebugLog()
+	var varString = strings.Repeat("a", 4)
+	runtime.Dlog().B(true).B(false).I(-42).I16(0x7fff).U64(^uint64(0)).Hex(0xfff).P(nil).S(varString).S("const string").End()
+	got := dlogCanonicalize(runtime.DumpDebugLog())
+	if want := "[] true false -42 32767 18446744073709551615 0xfff 0x0 aaaa const string\n"; got != want {
+		t.Fatalf("want %q, got %q", want, got)
+	}
+}
+
+func TestDebugLogSym(t *testing.T) {
+	skipDebugLog(t)
+	runtime.ResetDebugLog()
+	pc, _, _, _ := runtime.Caller(0)
+	runtime.Dlog().PC(pc).End()
+	got := dlogCanonicalize(runtime.DumpDebugLog())
+	want := regexp.MustCompile(`\[\] 0x[0-9a-f]+ \[runtime_test\.TestDebugLogSym\+0x[0-9a-f]+ .*/debuglog_test\.go:[0-9]+\]\n`)
+	if !want.MatchString(got) {
+		t.Fatalf("want matching %s, got %q", want, got)
+	}
+}
+
+func TestDebugLogInterleaving(t *testing.T) {
+	skipDebugLog(t)
+	runtime.ResetDebugLog()
+	var wg sync.WaitGroup
+	done := int32(0)
+	wg.Add(1)
+	go func() {
+		// Encourage main goroutine to move around to
+		// different Ms and Ps.
+		for atomic.LoadInt32(&done) == 0 {
+			runtime.Gosched()
+		}
+		wg.Done()
+	}()
+	var want bytes.Buffer
+	for i := 0; i < 1000; i++ {
+		runtime.Dlog().I(i).End()
+		fmt.Fprintf(&want, "[] %d\n", i)
+		runtime.Gosched()
+	}
+	atomic.StoreInt32(&done, 1)
+	wg.Wait()
+
+	gotFull := runtime.DumpDebugLog()
+	got := dlogCanonicalize(gotFull)
+	if got != want.String() {
+		// Since the timestamps are useful in understand
+		// failures of this test, we print the uncanonicalized
+		// output.
+		t.Fatalf("want %q, got (uncanonicalized) %q", want.String(), gotFull)
+	}
+}
+
+func TestDebugLogWraparound(t *testing.T) {
+	skipDebugLog(t)
+
+	// Make sure we don't switch logs so it's easier to fill one up.
+	runtime.LockOSThread()
+	defer runtime.UnlockOSThread()
+
+	runtime.ResetDebugLog()
+	var longString = strings.Repeat("a", 128)
+	var want bytes.Buffer
+	for i, j := 0, 0; j < 2*runtime.DebugLogBytes; i, j = i+1, j+len(longString) {
+		runtime.Dlog().I(i).S(longString).End()
+		fmt.Fprintf(&want, "[] %d %s\n", i, longString)
+	}
+	log := runtime.DumpDebugLog()
+
+	// Check for "lost" message.
+	lost := regexp.MustCompile(`^>> begin log \d+; lost first \d+KB <<\n`)
+	if !lost.MatchString(log) {
+		t.Fatalf("want matching %s, got %q", lost, log)
+	}
+	idx := lost.FindStringIndex(log)
+	// Strip lost message.
+	log = dlogCanonicalize(log[idx[1]:])
+
+	// Check log.
+	if !strings.HasSuffix(want.String(), log) {
+		t.Fatalf("wrong suffix:\n%s", log)
+	}
+}
+
+func TestDebugLogLongString(t *testing.T) {
+	skipDebugLog(t)
+
+	runtime.ResetDebugLog()
+	var longString = strings.Repeat("a", runtime.DebugLogStringLimit+1)
+	runtime.Dlog().S(longString).End()
+	got := dlogCanonicalize(runtime.DumpDebugLog())
+	want := "[] " + strings.Repeat("a", runtime.DebugLogStringLimit) + " ..(1 more bytes)..\n"
+	if got != want {
+		t.Fatalf("want %q, got %q", want, got)
+	}
+}

src/runtime/export_debuglog_test.go

+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Export debuglog guts for testing.
+
+package runtime
+
+const DlogEnabled = dlogEnabled
+
+const DebugLogBytes = debugLogBytes
+
+const DebugLogStringLimit = debugLogStringLimit
+
+var Dlog = dlog
+
+func (l *dlogger) End()                     { l.end() }
+func (l *dlogger) B(x bool) *dlogger        { return l.b(x) }
+func (l *dlogger) I(x int) *dlogger         { return l.i(x) }
+func (l *dlogger) I16(x int16) *dlogger     { return l.i16(x) }
+func (l *dlogger) U64(x uint64) *dlogger    { return l.u64(x) }
+func (l *dlogger) Hex(x uint64) *dlogger    { return l.hex(x) }
+func (l *dlogger) P(x interface{}) *dlogger { return l.p(x) }
+func (l *dlogger) S(x string) *dlogger      { return l.s(x) }
+func (l *dlogger) PC(x uintptr) *dlogger    { return l.pc(x) }
+
+func DumpDebugLog() string {
+	g := getg()
+	g.writebuf = make([]byte, 0, 1<<20)
+	printDebugLog()
+	buf := g.writebuf
+	g.writebuf = nil
+
+	return string(buf)
+}
+
+func ResetDebugLog() {
+	stopTheWorld("ResetDebugLog")
+	for l := allDloggers; l != nil; l = l.allLink {
+		l.w.write = 0
+		l.w.tick, l.w.nano = 0, 0
+		l.w.r.begin, l.w.r.end = 0, 0
+		l.w.r.tick, l.w.r.nano = 0, 0
+	}
+	startTheWorld()
+}

src/runtime/panic.go

@@ -925,6 +925,8 @@ func dopanic_m(gp *g, pc, sp uintptr) bool {
 		lock(&deadlock)
 	}
 
+	printDebugLog()
+
 	return docrash
 }
 

src/runtime/runtime2.go

@@ -468,6 +468,8 @@ type m struct {
 	vdsoSP uintptr // SP for traceback while in VDSO call (0 if not in call)
 	vdsoPC uintptr // PC for traceback while in VDSO call
 
+	dlogPerM
+
 	mOS
 }
 

src/runtime/signal_sighandler.go

@@ -148,5 +148,7 @@ func sighandler(sig uint32, info *siginfo, ctxt unsafe.Pointer, gp *g) {
 		crash()
 	}
 
+	printDebugLog()
+
 	exit(2)
 }