tstest: parse goroutines for diff in ResourceCheck (#15619)

ResourceCheck was previously using cmp.Diff on multiline goroutine stacks The produced output was difficult to read for a number of reasons: - the goroutines were sorted by count, and a changing count caused them to jump around - diffs would be in the middle of stacks Instead, we now parse the pprof/goroutines?debug=1 format goroutines and only diff whole stacks. Updates #1253 Signed-off-by: Paul Scott <paul@tailscale.com>
1 year ago · ed052eac62
parent 5c562116fc
commit ed052eac62
2 changed files with 477 additions and 3 deletions
--- a/tstest/resource.go
+++ b/tstest/resource.go
@ -7,10 +7,10 @@ import (
 	"bytes"
 	"runtime"
 	"runtime/pprof"
+	"slices"
+	"strings"
 	"testing"
 	"time"
-
-	"github.com/google/go-cmp/cmp"
 )

 // ResourceCheck takes a snapshot of the current goroutines and registers a
@ -44,7 +44,20 @@ func ResourceCheck(tb testing.TB) {
 		if endN <= startN {
 			return
 		}
-		tb.Logf("goroutine diff:\n%v\n", cmp.Diff(startStacks, endStacks))
+
+		// Parse and print goroutines.
+		start := parseGoroutines(startStacks)
+		end := parseGoroutines(endStacks)
+		if testing.Verbose() {
+			tb.Logf("goroutines start:\n%s", printGoroutines(start))
+			tb.Logf("goroutines end:\n%s", printGoroutines(end))
+		}
+
+		// Print goroutine diff, omitting tstest.ResourceCheck goroutines.
+		self := func(g goroutine) bool { return bytes.Contains(g.stack, []byte("\ttailscale.com/tstest.goroutines+")) }
+		start.goroutines = slices.DeleteFunc(start.goroutines, self)
+		end.goroutines = slices.DeleteFunc(end.goroutines, self)
+		tb.Logf("goroutine diff (-start +end):\n%s", diffGoroutines(start, end))

 		// tb.Failed() above won't report on panics, so we shouldn't call Fatal
 		// here or we risk suppressing reporting of the panic.
@ -58,3 +71,208 @@ func goroutines() (int, []byte) {
 	p.WriteTo(b, 1)
 	return p.Count(), b.Bytes()
 }
+
+// parseGoroutines takes pprof/goroutines?debug=1 -formatted output sorted by
+// count, and splits it into a separate list of goroutines with count and stack
+// separated.
+//
+// Example input:
+//
+//	goroutine profile: total 408
+//	48 @ 0x47bc0e 0x136c6b9 0x136c69e 0x136c7ab 0x1379809 0x13797fa 0x483da1
+//	#   0x136c6b8   gvisor.dev/gvisor/pkg/sync.Gopark+0x78                  gvisor.dev/gvisor@v0.0.0-20250205023644-9414b50a5633/pkg/sync/runtime_unsafe.go:33
+//	#   0x136c69d   gvisor.dev/gvisor/pkg/sleep.(*Sleeper).nextWaker+0x5d           gvisor.dev/gvisor@v0.0.0-20250205023644-9414b50a5633/pkg/sleep/sleep_unsafe.go:210
+//	#   0x136c7aa   gvisor.dev/gvisor/pkg/sleep.(*Sleeper).fetch+0x2a           gvisor.dev/gvisor@v0.0.0-20250205023644-9414b50a5633/pkg/sleep/sleep_unsafe.go:257
+//	#   0x1379808   gvisor.dev/gvisor/pkg/sleep.(*Sleeper).Fetch+0xa8           gvisor.dev/gvisor@v0.0.0-20250205023644-9414b50a5633/pkg/sleep/sleep_unsafe.go:280
+//	#   0x13797f9   gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*processor).start+0x99   gvisor.dev/gvisor@v0.0.0-20250205023644-9414b50a5633/pkg/tcpip/transport/tcp/dispatcher.go:291
+//
+//	48 @ 0x47bc0e 0x413705 0x4132b2 0x10fc905 0x483da1
+//	#   0x10fc904   github.com/tailscale/wireguard-go/device.(*Device).RoutineDecryption+0x184  github.com/tailscale/wireguard-go@v0.0.0-20250107165329-0b8b35511f19/device/receive.go:245
+//
+//	48 @ 0x47bc0e 0x413705 0x4132b2 0x10fcd2a 0x483da1
+//	#   0x10fcd29   github.com/tailscale/wireguard-go/device.(*Device).RoutineHandshake+0x169   github.com/tailscale/wireguard-go@v0.0.0-20250107165329-0b8b35511f19/device/receive.go:279
+//
+//	48 @ 0x47bc0e 0x413705 0x4132b2 0x1100ba7 0x483da1
+//	#   0x1100ba6   github.com/tailscale/wireguard-go/device.(*Device).RoutineEncryption+0x186  github.com/tailscale/wireguard-go@v0.0.0-20250107165329-0b8b35511f19/device/send.go:451
+//
+//	26 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+//	#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+//
+//	13 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+//	#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+//
+//	7 @ 0x47bc0e 0x413705 0x4132b2 0x10fda4d 0x483da1
+//	#   0x10fda4c   github.com/tailscale/wireguard-go/device.(*Peer).RoutineSequentialReceiver+0x16c    github.com/tailscale/wireguard-go@v0.0.0-20250107165329-0b8b35511f19/device/receive.go:443
+func parseGoroutines(g []byte) goroutineDump {
+	head, tail, ok := bytes.Cut(g, []byte("\n"))
+	if !ok {
+		return goroutineDump{head: head}
+	}
+
+	raw := bytes.Split(tail, []byte("\n\n"))
+	parsed := make([]goroutine, 0, len(raw))
+	for _, s := range raw {
+		count, rem, ok := bytes.Cut(s, []byte(" @ "))
+		if !ok {
+			continue
+		}
+		header, stack, _ := bytes.Cut(rem, []byte("\n"))
+		sort := slices.Clone(header)
+		reverseWords(sort)
+		parsed = append(parsed, goroutine{count, header, stack, sort})
+	}
+
+	return goroutineDump{head, parsed}
+}
+
+type goroutineDump struct {
+	head       []byte
+	goroutines []goroutine
+}
+
+// goroutine is a parsed stack trace in pprof goroutine output, e.g.
+// "10 @ 0x100 0x001\n# 0x100 test() test.go\n# 0x001 main() test.go".
+type goroutine struct {
+	count  []byte // e.g. "10"
+	header []byte // e.g. "0x100 0x001"
+	stack  []byte // e.g. "# 0x100 test() test.go\n# 0x001 main() test.go"
+
+	// sort is the same pointers as in header, but in reverse order so that we
+	// can place related goroutines near each other by sorting on this field.
+	// E.g. "0x001 0x100".
+	sort []byte
+}
+
+func (g goroutine) Compare(h goroutine) int {
+	return bytes.Compare(g.sort, h.sort)
+}
+
+// reverseWords repositions the words in b such that they are reversed.
+// Words are separated by spaces. New lines are not considered.
+// https://sketch.dev/sk/a4ef
+func reverseWords(b []byte) {
+	if len(b) == 0 {
+		return
+	}
+
+	// First, reverse the entire slice.
+	reverse(b)
+
+	// Then reverse each word individually.
+	start := 0
+	for i := 0; i <= len(b); i++ {
+		if i == len(b) || b[i] == ' ' {
+			reverse(b[start:i])
+			start = i + 1
+		}
+	}
+}
+
+// reverse reverses bytes in place
+func reverse(b []byte) {
+	for i, j := 0, len(b)-1; i < j; i, j = i+1, j-1 {
+		b[i], b[j] = b[j], b[i]
+	}
+}
+
+// printGoroutines returns a text representation of h, gs equivalent to the
+// pprof ?debug=1 input parsed by parseGoroutines, except the goroutines are
+// sorted in an order easier for diffing.
+func printGoroutines(g goroutineDump) []byte {
+	var b bytes.Buffer
+	b.Write(g.head)
+
+	slices.SortFunc(g.goroutines, goroutine.Compare)
+	for _, g := range g.goroutines {
+		b.WriteString("\n\n")
+		b.Write(g.count)
+		b.WriteString(" @ ")
+		b.Write(g.header)
+		b.WriteString("\n")
+		if len(g.stack) > 0 {
+			b.Write(g.stack)
+		}
+	}
+
+	return b.Bytes()
+}
+
+// diffGoroutines returns a diff between goroutines of gx and gy.
+// Goroutines present in gx and absent from gy are prefixed with "-".
+// Goroutines absent from gx and present in gy are prefixed with "+".
+// Goroutines present in both but with different counts only show a prefix on the count line.
+func diffGoroutines(x, y goroutineDump) string {
+	hx, hy := x.head, y.head
+	gx, gy := x.goroutines, y.goroutines
+	var b strings.Builder
+	if !bytes.Equal(hx, hy) {
+		b.WriteString("- ")
+		b.Write(hx)
+		b.WriteString("\n+ ")
+		b.Write(hy)
+		b.WriteString("\n")
+	}
+
+	slices.SortFunc(gx, goroutine.Compare)
+	slices.SortFunc(gy, goroutine.Compare)
+
+	writeHeader := func(prefix string, g goroutine) {
+		b.WriteString(prefix)
+		b.Write(g.count)
+		b.WriteString(" @ ")
+		b.Write(g.header)
+		b.WriteString("\n")
+	}
+	writeStack := func(prefix string, g goroutine) {
+		s := g.stack
+		for {
+			var h []byte
+			h, s, _ = bytes.Cut(s, []byte("\n"))
+			if len(h) == 0 && len(s) == 0 {
+				break
+			}
+			b.WriteString(prefix)
+			b.Write(h)
+			b.WriteString("\n")
+		}
+	}
+
+	i, j := 0, 0
+	for {
+		var d int
+		switch {
+		case i < len(gx) && j < len(gy):
+			d = gx[i].Compare(gy[j])
+		case i < len(gx):
+			d = -1
+		case j < len(gy):
+			d = 1
+		default:
+			return b.String()
+		}
+
+		switch d {
+		case -1:
+			b.WriteString("\n")
+			writeHeader("- ", gx[i])
+			writeStack("- ", gx[i])
+			i++
+
+		case +1:
+			b.WriteString("\n")
+			writeHeader("+ ", gy[j])
+			writeStack("+ ", gy[j])
+			j++
+
+		case 0:
+			if !bytes.Equal(gx[i].count, gy[j].count) {
+				b.WriteString("\n")
+				writeHeader("- ", gx[i])
+				writeHeader("+ ", gy[j])
+				writeStack("  ", gy[j])
+			}
+			i++
+			j++
+		}
+	}
+}
--- a/tstest/resource_test.go
+++ b/tstest/resource_test.go
@ -0,0 +1,256 @@
+// Copyright (c) Tailscale Inc & AUTHORS
+// SPDX-License-Identifier: BSD-3-Clause
+
+package tstest
+
+import (
+	"strings"
+	"testing"
+
+	"github.com/google/go-cmp/cmp"
+)
+
+func TestPrintGoroutines(t *testing.T) {
+	tests := []struct {
+		name string
+		in   string
+		want string
+	}{
+		{
+			name: "empty",
+			in:   "goroutine profile: total 0\n",
+			want: "goroutine profile: total 0",
+		},
+		{
+			name: "single goroutine",
+			in: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			want: `goroutine profile: total 1
+
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+		},
+		{
+			name: "multiple goroutines sorted",
+			in: `goroutine profile: total 14
+7 @ 0x47bc0e 0x413705 0x4132b2 0x10fda4d 0x483da1
+#   0x10fda4c   github.com/user/pkg.RoutineA+0x16c    pkg/a.go:443
+
+7 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+			want: `goroutine profile: total 14
+
+7 @ 0x47bc0e 0x413705 0x4132b2 0x10fda4d 0x483da1
+#   0x10fda4c   github.com/user/pkg.RoutineA+0x16c    pkg/a.go:443
+
+7 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got := string(printGoroutines(parseGoroutines([]byte(tt.in))))
+			if got != tt.want {
+				t.Errorf("printGoroutines() = %q, want %q, diff:\n%s", got, tt.want, cmp.Diff(tt.want, got))
+			}
+		})
+	}
+}
+
+func TestDiffPprofGoroutines(t *testing.T) {
+	tests := []struct {
+		name string
+		x, y string
+		want string
+	}{
+		{
+			name: "no difference",
+			x: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261`,
+			y: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			want: "",
+		},
+		{
+			name: "different counts",
+			x: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			y: `goroutine profile: total 2
+2 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			want: `- goroutine profile: total 1
+ goroutine profile: total 2
+
+- 1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+ 2 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+  #   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+		},
+		{
+			name: "new goroutine",
+			x: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			y: `goroutine profile: total 2
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+
+1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+			want: `- goroutine profile: total 1
+ goroutine profile: total 2
+
+ 1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+ #   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+		},
+		{
+			name: "removed goroutine",
+			x: `goroutine profile: total 2
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+
+1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+			y: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			want: `- goroutine profile: total 2
+ goroutine profile: total 1
+
+- 1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+- #   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+		},
+		{
+			name: "removed many goroutine",
+			x: `goroutine profile: total 2
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+
+1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+			y: `goroutine profile: total 0`,
+			want: `- goroutine profile: total 2
+ goroutine profile: total 0
+
+- 1 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+- #   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+
+- 1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+- #   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+		},
+		{
+			name: "invalid input x",
+			x:    "invalid",
+			y:    "goroutine profile: total 0\n",
+			want: "- invalid\n+ goroutine profile: total 0\n",
+		},
+		{
+			name: "invalid input y",
+			x:    "goroutine profile: total 0\n",
+			y:    "invalid",
+			want: "- goroutine profile: total 0\n+ invalid\n",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got := diffGoroutines(
+				parseGoroutines([]byte(tt.x)),
+				parseGoroutines([]byte(tt.y)),
+			)
+			if got != tt.want {
+				t.Errorf("diffPprofGoroutines() diff:\ngot:\n%s\nwant:\n%s\ndiff (-want +got):\n%s", got, tt.want, cmp.Diff(tt.want, got))
+			}
+		})
+	}
+}
+
+func TestParseGoroutines(t *testing.T) {
+	tests := []struct {
+		name       string
+		in         string
+		wantHeader string
+		wantCount  int
+	}{
+		{
+			name:       "empty profile",
+			in:         "goroutine profile: total 0\n",
+			wantHeader: "goroutine profile: total 0",
+			wantCount:  0,
+		},
+		{
+			name: "single goroutine",
+			in: `goroutine profile: total 1
+1 @ 0x47bc0e 0x458e57 0x847587 0x483da1
+#   0x847586    database/sql.(*DB).connectionOpener+0x86    database/sql/sql.go:1261
+`,
+			wantHeader: "goroutine profile: total 1",
+			wantCount:  1,
+		},
+		{
+			name: "multiple goroutines",
+			in: `goroutine profile: total 14
+7 @ 0x47bc0e 0x413705 0x4132b2 0x10fda4d 0x483da1
+#   0x10fda4c   github.com/user/pkg.RoutineA+0x16c    pkg/a.go:443
+
+7 @ 0x47bc0e 0x458e57 0x754927 0x483da1
+#   0x754926    net/http.(*persistConn).writeLoop+0xe6  net/http/transport.go:2596
+`,
+			wantHeader: "goroutine profile: total 14",
+			wantCount:  2,
+		},
+		{
+			name:       "invalid format",
+			in:         "invalid",
+			wantHeader: "invalid",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			g := parseGoroutines([]byte(tt.in))
+
+			if got := string(g.head); got != tt.wantHeader {
+				t.Errorf("parseGoroutines() header = %q, want %q", got, tt.wantHeader)
+			}
+			if got := len(g.goroutines); got != tt.wantCount {
+				t.Errorf("parseGoroutines() goroutine count = %d, want %d", got, tt.wantCount)
+			}
+
+			// Verify that the sort field is correctly reversed
+			for _, g := range g.goroutines {
+				original := strings.Fields(string(g.header))
+				sorted := strings.Fields(string(g.sort))
+				if len(original) != len(sorted) {
+					t.Errorf("sort field has different number of words: got %d, want %d", len(sorted), len(original))
+					continue
+				}
+				for i := 0; i < len(original); i++ {
+					if original[i] != sorted[len(sorted)-1-i] {
+						t.Errorf("sort field word mismatch at position %d: got %q, want %q", i, sorted[len(sorted)-1-i], original[i])
+					}
+				}
+			}
+		})
+	}
+}