debuglog_test.go

Documentation: runtime

		 1  // Copyright 2019 The Go Authors. All rights reserved.
		 2  // Use of this source code is governed by a BSD-style
		 3  // license that can be found in the LICENSE file.
		 4  
		 5  // TODO(austin): All of these tests are skipped if the debuglog build
		 6  // tag isn't provided. That means we basically never test debuglog.
		 7  // There are two potential ways around this:
		 8  //
		 9  // 1. Make these tests re-build the runtime test with the debuglog
		10  // build tag and re-invoke themselves.
		11  //
		12  // 2. Always build the whole debuglog infrastructure and depend on
		13  // linker dead-code elimination to drop it. This is easy for dlog()
		14  // since there won't be any calls to it. For printDebugLog, we can
		15  // make panic call a wrapper that is call printDebugLog if the
		16  // debuglog build tag is set, or otherwise do nothing. Then tests
		17  // could call printDebugLog directly. This is the right answer in
		18  // principle, but currently our linker reads in all symbols
		19  // regardless, so this would slow down and bloat all links. If the
		20  // linker gets more efficient about this, we should revisit this
		21  // approach.
		22  
		23  package runtime_test
		24  
		25  import (
		26  	"bytes"
		27  	"fmt"
		28  	"regexp"
		29  	"runtime"
		30  	"strings"
		31  	"sync"
		32  	"sync/atomic"
		33  	"testing"
		34  )
		35  
		36  func skipDebugLog(t *testing.T) {
		37  	if !runtime.DlogEnabled {
		38  		t.Skip("debug log disabled (rebuild with -tags debuglog)")
		39  	}
		40  }
		41  
		42  func dlogCanonicalize(x string) string {
		43  	begin := regexp.MustCompile(`(?m)^>> begin log \d+ <<\n`)
		44  	x = begin.ReplaceAllString(x, "")
		45  	prefix := regexp.MustCompile(`(?m)^\[[^]]+\]`)
		46  	x = prefix.ReplaceAllString(x, "[]")
		47  	return x
		48  }
		49  
		50  func TestDebugLog(t *testing.T) {
		51  	skipDebugLog(t)
		52  	runtime.ResetDebugLog()
		53  	runtime.Dlog().S("testing").End()
		54  	got := dlogCanonicalize(runtime.DumpDebugLog())
		55  	if want := "[] testing\n"; got != want {
		56  		t.Fatalf("want %q, got %q", want, got)
		57  	}
		58  }
		59  
		60  func TestDebugLogTypes(t *testing.T) {
		61  	skipDebugLog(t)
		62  	runtime.ResetDebugLog()
		63  	var varString = strings.Repeat("a", 4)
		64  	runtime.Dlog().B(true).B(false).I(-42).I16(0x7fff).U64(^uint64(0)).Hex(0xfff).P(nil).S(varString).S("const string").End()
		65  	got := dlogCanonicalize(runtime.DumpDebugLog())
		66  	if want := "[] true false -42 32767 18446744073709551615 0xfff 0x0 aaaa const string\n"; got != want {
		67  		t.Fatalf("want %q, got %q", want, got)
		68  	}
		69  }
		70  
		71  func TestDebugLogSym(t *testing.T) {
		72  	skipDebugLog(t)
		73  	runtime.ResetDebugLog()
		74  	pc, _, _, _ := runtime.Caller(0)
		75  	runtime.Dlog().PC(pc).End()
		76  	got := dlogCanonicalize(runtime.DumpDebugLog())
		77  	want := regexp.MustCompile(`\[\] 0x[0-9a-f]+ \[runtime_test\.TestDebugLogSym\+0x[0-9a-f]+ .*/debuglog_test\.go:[0-9]+\]\n`)
		78  	if !want.MatchString(got) {
		79  		t.Fatalf("want matching %s, got %q", want, got)
		80  	}
		81  }
		82  
		83  func TestDebugLogInterleaving(t *testing.T) {
		84  	skipDebugLog(t)
		85  	runtime.ResetDebugLog()
		86  	var wg sync.WaitGroup
		87  	done := int32(0)
		88  	wg.Add(1)
		89  	go func() {
		90  		// Encourage main goroutine to move around to
		91  		// different Ms and Ps.
		92  		for atomic.LoadInt32(&done) == 0 {
		93  			runtime.Gosched()
		94  		}
		95  		wg.Done()
		96  	}()
		97  	var want bytes.Buffer
		98  	for i := 0; i < 1000; i++ {
		99  		runtime.Dlog().I(i).End()
	 100  		fmt.Fprintf(&want, "[] %d\n", i)
	 101  		runtime.Gosched()
	 102  	}
	 103  	atomic.StoreInt32(&done, 1)
	 104  	wg.Wait()
	 105  
	 106  	gotFull := runtime.DumpDebugLog()
	 107  	got := dlogCanonicalize(gotFull)
	 108  	if got != want.String() {
	 109  		// Since the timestamps are useful in understand
	 110  		// failures of this test, we print the uncanonicalized
	 111  		// output.
	 112  		t.Fatalf("want %q, got (uncanonicalized) %q", want.String(), gotFull)
	 113  	}
	 114  }
	 115  
	 116  func TestDebugLogWraparound(t *testing.T) {
	 117  	skipDebugLog(t)
	 118  
	 119  	// Make sure we don't switch logs so it's easier to fill one up.
	 120  	runtime.LockOSThread()
	 121  	defer runtime.UnlockOSThread()
	 122  
	 123  	runtime.ResetDebugLog()
	 124  	var longString = strings.Repeat("a", 128)
	 125  	var want bytes.Buffer
	 126  	for i, j := 0, 0; j < 2*runtime.DebugLogBytes; i, j = i+1, j+len(longString) {
	 127  		runtime.Dlog().I(i).S(longString).End()
	 128  		fmt.Fprintf(&want, "[] %d %s\n", i, longString)
	 129  	}
	 130  	log := runtime.DumpDebugLog()
	 131  
	 132  	// Check for "lost" message.
	 133  	lost := regexp.MustCompile(`^>> begin log \d+; lost first \d+KB <<\n`)
	 134  	if !lost.MatchString(log) {
	 135  		t.Fatalf("want matching %s, got %q", lost, log)
	 136  	}
	 137  	idx := lost.FindStringIndex(log)
	 138  	// Strip lost message.
	 139  	log = dlogCanonicalize(log[idx[1]:])
	 140  
	 141  	// Check log.
	 142  	if !strings.HasSuffix(want.String(), log) {
	 143  		t.Fatalf("wrong suffix:\n%s", log)
	 144  	}
	 145  }
	 146  
	 147  func TestDebugLogLongString(t *testing.T) {
	 148  	skipDebugLog(t)
	 149  
	 150  	runtime.ResetDebugLog()
	 151  	var longString = strings.Repeat("a", runtime.DebugLogStringLimit+1)
	 152  	runtime.Dlog().S(longString).End()
	 153  	got := dlogCanonicalize(runtime.DumpDebugLog())
	 154  	want := "[] " + strings.Repeat("a", runtime.DebugLogStringLimit) + " ..(1 more bytes)..\n"
	 155  	if got != want {
	 156  		t.Fatalf("want %q, got %q", want, got)
	 157  	}
	 158  }
	 159
View as plain text