diff --git a/tstest/resource.go b/tstest/resource.go index b094c7911..f50bb3330 100644 --- 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++ + } + } +} diff --git a/tstest/resource_test.go b/tstest/resource_test.go new file mode 100644 index 000000000..7199ac5d1 --- /dev/null +++ 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]) + } + } + } + }) + } +}