From 3ebb1ad9cddf4711d4b0f44c24da1ceac3d9e069 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Sun, 30 Dec 2018 19:47:27 -0500 Subject: 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 TryBot-Result: Gobot Gobot Reviewed-by: Michael Knyszek --- src/runtime/debuglog_test.go | 158 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 158 insertions(+) create mode 100644 src/runtime/debuglog_test.go (limited to 'src/runtime/debuglog_test.go') diff --git a/src/runtime/debuglog_test.go b/src/runtime/debuglog_test.go new file mode 100644 index 0000000000..2570e3565b --- /dev/null +++ b/src/runtime/debuglog_test.go @@ -0,0 +1,158 @@ +// 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) + } +} -- cgit v1.3-5-g9baa