Skip to content

Commit 4219da4

Browse files
egonelbreegonelbre
committed
testtrace,testcontext: add package for stacktrace summary
It's useful for debugging goroutines started from a test. Package testtrace adds getting a goroutine summary filtered by pprof labels. Package testcontext now attaches a unique ID label to tests allowing to filter for related goroutines. Change-Id: If3ff8766fc28a788bfc02ac2dad8fad265e8e33e
1 parent 34a5992 commit 4219da4

File tree

7 files changed

+260
-15
lines changed

7 files changed

+260
-15
lines changed

‎go.mod

+3-2
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,14 @@ require (
66
github.com/btcsuite/btcutil v1.0.3-0.20201208143702-a53e38424cce
77
github.com/calebcase/tmpfile v1.0.3
88
github.com/gogo/protobuf v1.3.2
9+
github.com/google/pprof v0.0.0-20211008130755-947d60d73cc0
910
github.com/lucas-clemente/quic-go v0.23.0
1011
github.com/spacemonkeygo/monkit/v3 v3.0.12
1112
github.com/stretchr/testify v1.7.0
1213
github.com/zeebo/admission/v3 v3.0.2
1314
github.com/zeebo/errs v1.2.2
14-
golang.org/x/crypto v0.0.0-20210415154028-4f45737414dc
15+
golang.org/x/crypto v0.0.0-20210921155107-089bfa567519
1516
golang.org/x/sync v0.0.0-20210220032951-036812b2e83c
16-
golang.org/x/sys v0.0.0-20210823070655-63515b42dcdf
17+
golang.org/x/sys v0.0.0-20211020064051-0ec99a608a1b
1718
storj.io/drpc v0.0.26
1819
)

‎go.sum

+12-4
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,9 @@ github.com/calebcase/tmpfile v1.0.3 h1:BZrOWZ79gJqQ3XbAQlihYZf/YCV0H4KPIdM5K5oMp
2727
github.com/calebcase/tmpfile v1.0.3/go.mod h1:UAUc01aHeC+pudPagY/lWvt2qS9ZO5Zzof6/tIUzqeI=
2828
github.com/cheekybits/genny v1.0.0 h1:uGGa4nei+j20rOSeDeP5Of12XVm7TGUd4dJA9RDitfE=
2929
github.com/cheekybits/genny v1.0.0/go.mod h1:+tQajlRqAUrPI7DOSpB0XAqZYtQakVtB7wXkRAgjxjQ=
30+
github.com/chzyer/logex v1.1.10/go.mod h1:+Ywpsq7O8HXn0nuIou7OrIPyXbp3wmkHB+jjWRnGsAI=
31+
github.com/chzyer/readline v0.0.0-20180603132655-2972be24d48e/go.mod h1:nSuG5e5PlCu98SY8svDHJxuZscDgtXS6KTTbou5AhLI=
32+
github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU=
3033
github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw=
3134
github.com/coreos/go-systemd v0.0.0-20181012123002-c6f51f82210d/go.mod h1:F5haX7vjVVG0kc13fIWeqUViNPyEJxv/OmvnBo0Yme4=
3235
github.com/davecgh/go-spew v0.0.0-20171005155431-ecdeabc65495/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -76,12 +79,15 @@ github.com/google/go-github v17.0.0+incompatible/go.mod h1:zLgOLi98H3fifZn+44m+u
7679
github.com/google/go-querystring v1.0.0/go.mod h1:odCYkC5MyYFN7vkCjXpyrEuKhc/BUO6wN/zVPAxq5ck=
7780
github.com/google/martian v2.1.0+incompatible/go.mod h1:9I4somxYTbIHy5NJKHRl3wXiIaQGbYVAs8BPL6v8lEs=
7881
github.com/google/pprof v0.0.0-20181206194817-3ea8567a2e57/go.mod h1:zfwlbNMJ+OItoe0UupaVj+oy1omPYYDuagoSzA8v9mc=
82+
github.com/google/pprof v0.0.0-20211008130755-947d60d73cc0 h1:zHs+jv3LO743/zFGcByu2KmpbliCU2AhjcGgrdTwSG4=
83+
github.com/google/pprof v0.0.0-20211008130755-947d60d73cc0/go.mod h1:KgnwoLYCZ8IQu3XUZ8Nc/bM9CCZFOyjUNOSygVozoDg=
7984
github.com/googleapis/gax-go v2.0.0+incompatible/go.mod h1:SFVmujtThgffbyetf+mdk2eWhX2bMyUtNHzFKcPA9HY=
8085
github.com/googleapis/gax-go/v2 v2.0.3/go.mod h1:LLvjysVCY1JZeum8Z6l8qUty8fiNwE08qbEPm1M08qg=
8186
github.com/gopherjs/gopherjs v0.0.0-20181017120253-0766667cb4d1/go.mod h1:wJfORRmW1u3UXTncJ5qlYoELFm8eSnnEO6hX4iZ3EWY=
8287
github.com/gregjones/httpcache v0.0.0-20180305231024-9cad4c3443a7/go.mod h1:FecbI9+v66THATjSRHfNgh1IVFe/9kFxbXtjV0ctIMA=
8388
github.com/grpc-ecosystem/grpc-gateway v1.5.0/go.mod h1:RSKVYQBd5MCa4OVpNdGskqpgL2+G+NZTnrVHpWWfpdw=
8489
github.com/hpcloud/tail v1.0.0/go.mod h1:ab1qPbhIpdTxEkNHXyeSf5vhxWSCs/tWer42PpOxQnU=
90+
github.com/ianlancetaylor/demangle v0.0.0-20210905161508-09a460cdf81d/go.mod h1:aYm2/VgdVmcIU8iMfdMvDMsRAQjcfZSKFby6HOFvi/w=
8591
github.com/jellevandenhooff/dkim v0.0.0-20150330215556-f50fe3d243e1/go.mod h1:E0B/fFc00Y+Rasa88328GlI/XbtyysCtTHZS8h7IrBU=
8692
github.com/jessevdk/go-flags v0.0.0-20141203071132-1679536dcc89/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI=
8793
github.com/jrick/logrotate v1.0.0/go.mod h1:LNinyqDIJnpAur+b8yyulnQw/wDuN1+BYKlTRt3OuAQ=
@@ -197,8 +203,8 @@ golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8U
197203
golang.org/x/crypto v0.0.0-20200115085410-6d4e4cb37c7d/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
198204
golang.org/x/crypto v0.0.0-20200221231518-2aa609cf4a9d/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
199205
golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
200-
golang.org/x/crypto v0.0.0-20210415154028-4f45737414dc h1:+q90ECDSAQirdykUN6sPEiBXBsp8Csjcca8Oy7bgLTA=
201-
golang.org/x/crypto v0.0.0-20210415154028-4f45737414dc/go.mod h1:T9bdIzuCu7OtxOm1hfPfRQxPLYneinmdGuTeoZ9dtd4=
206+
golang.org/x/crypto v0.0.0-20210921155107-089bfa567519 h1:7I4JAnoQBe7ZtJcBaYHi5UtiO8tQHbUSXxL+pnGRANg=
207+
golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
202208
golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
203209
golang.org/x/lint v0.0.0-20180702182130-06c8688daad7/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
204210
golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
@@ -260,8 +266,10 @@ golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7w
260266
golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
261267
golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
262268
golang.org/x/sys v0.0.0-20210514084401-e8d321eab015/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
263-
golang.org/x/sys v0.0.0-20210823070655-63515b42dcdf h1:2ucpDCmfkl8Bd/FsLtiD653Wf96cW37s+iGx93zsu4k=
264-
golang.org/x/sys v0.0.0-20210823070655-63515b42dcdf/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
269+
golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
270+
golang.org/x/sys v0.0.0-20211007075335-d3039528d8ac/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
271+
golang.org/x/sys v0.0.0-20211020064051-0ec99a608a1b h1:byBDhtWGQmWDrv1MlEv/BzGRMkw36h9QqsNnZQcDhRw=
272+
golang.org/x/sys v0.0.0-20211020064051-0ec99a608a1b/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
265273
golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
266274
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
267275
golang.org/x/text v0.3.1-0.20180807135948-17ff2d5776d2/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

‎testcontext/context.go

+29-7
Original file line numberDiff line numberDiff line change
@@ -11,13 +11,15 @@ import (
1111
"os"
1212
"path/filepath"
1313
"runtime"
14+
"runtime/pprof"
1415
"strings"
1516
"sync"
1617
"time"
1718

1819
"golang.org/x/sync/errgroup"
1920

2021
"storj.io/common/memory"
22+
"storj.io/common/testtrace"
2123
)
2224

2325
// DefaultTimeout is the default timeout used by new context.
@@ -27,9 +29,10 @@ const DefaultTimeout = 3 * time.Minute
2729
type Context struct {
2830
context.Context
2931

30-
timedctx context.Context
31-
cancel context.CancelFunc
32-
cleaning chan struct{}
32+
parentctx context.Context
33+
timedctx context.Context
34+
cancel context.CancelFunc
35+
cleaning chan struct{}
3336

3437
group *errgroup.Group
3538
test TB
@@ -87,21 +90,37 @@ func NewWithContextAndTimeout(parentCtx context.Context, test TB, timeout time.D
8790
ctx := &Context{
8891
Context: errctx,
8992

90-
timedctx: timedctx,
91-
cancel: cancel,
92-
cleaning: make(chan struct{}),
93+
parentctx: parentCtx,
94+
timedctx: timedctx,
95+
cancel: cancel,
96+
cleaning: make(chan struct{}),
9397

9498
group: group,
9599
test: test,
96100
}
97101

102+
ctx.Context = pprof.WithLabels(ctx.Context, pprof.Labels("testcontext", ctx.label()))
103+
pprof.SetGoroutineLabels(ctx.Context)
104+
98105
go ctx.monitorSlowShutdown()
99106

100107
test.Cleanup(ctx.Cleanup)
101108

102109
return ctx
103110
}
104111

112+
func (ctx *Context) label() string { return fmt.Sprintf("%p", ctx) }
113+
114+
// StackTrace returns stack trace about the goroutines that are related to this
115+
// Context.
116+
func (ctx *Context) StackTrace() string {
117+
content, err := testtrace.Summary("testcontext", ctx.label())
118+
if err != nil {
119+
return fmt.Sprintf("unable to create stack trace: %v", err)
120+
}
121+
return content
122+
}
123+
105124
func (ctx *Context) monitorSlowShutdown() {
106125
// Wait for either the timeout to trigger on an explicit call to Cleanup.
107126
select {
@@ -209,6 +228,7 @@ func (ctx *Context) File(elem ...string) string {
209228
// checks errors and goroutines which haven't ended and tries to cleanup
210229
// directories.
211230
func (ctx *Context) Cleanup() {
231+
pprof.SetGoroutineLabels(ctx.parentctx)
212232
ctx.test.Helper()
213233
ctx.cleanupOnce.Do(func() {
214234
close(ctx.cleaning)
@@ -258,9 +278,11 @@ func (ctx *Context) reportRunning() {
258278
if fn := runtime.FuncForPC(caller.pc); fn != nil {
259279
fnname = fn.Name()
260280
}
261-
fmt.Fprintf(&message, "\n%s:%d: %s", caller.file, caller.line, fnname)
281+
fmt.Fprintf(&message, "\n %s:%d: %s", caller.file, caller.line, fnname)
262282
}
263283
}
284+
_, _ = message.WriteString("\nRelated stack trace\n")
285+
_, _ = message.WriteString(ctx.StackTrace())
264286

265287
ctx.test.Error(message.String())
266288

‎testcontext/context_test.go

+2
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,8 @@ func TestMessage(t *testing.T) {
4343
})
4444
ctx.Cleanup()
4545

46+
t.Log(subtest.errors[0])
47+
4648
assert.Contains(t, subtest.errors[0], "Test exceeded timeout")
4749
assert.Contains(t, subtest.errors[0], "some goroutines are still running")
4850

‎testtrace/trace.go

+147
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,147 @@
1+
// Copyright (C) 2021 Storj Labs, Inc.
2+
// See LICENSE for copying information.
3+
4+
// Package testtrace provides profiling debugging utilities for
5+
// writing the state of all goroutines.
6+
package testtrace
7+
8+
import (
9+
"bytes"
10+
"fmt"
11+
"runtime/pprof"
12+
"sort"
13+
"strings"
14+
15+
"github.com/google/pprof/profile"
16+
"github.com/zeebo/errs"
17+
)
18+
19+
// Summary returns summary of the goroutines, excluding goroutines whose label
20+
// does not match the expected value. goroutines missing the specified label
21+
// is included.
22+
func Summary(filterByLabels ...string) (string, error) {
23+
var pb bytes.Buffer
24+
profiler := pprof.Lookup("goroutine")
25+
if profiler == nil {
26+
return "", errs.New("unable to find profile")
27+
}
28+
err := profiler.WriteTo(&pb, 0)
29+
if err != nil {
30+
return "", errs.Wrap(err)
31+
}
32+
33+
p, err := profile.ParseData(pb.Bytes())
34+
if err != nil {
35+
return "", errs.Wrap(err)
36+
}
37+
38+
return summary(p, createFilterMap(filterByLabels...))
39+
}
40+
41+
func createFilterMap(keyValue ...string) map[string]string {
42+
if len(keyValue)%2 != 0 {
43+
panic("keyValue should have key:value pairs")
44+
}
45+
m := map[string]string{}
46+
for i := 0; i < len(keyValue); i += 2 {
47+
m[keyValue[i]] = keyValue[i+1]
48+
}
49+
return m
50+
}
51+
52+
func filterMatches(sample *profile.Sample, filterLabel map[string]string) bool {
53+
if len(filterLabel) == 0 {
54+
return true
55+
}
56+
57+
for label, expected := range filterLabel {
58+
values, hasLabel := sample.Label[label]
59+
if !hasLabel {
60+
continue
61+
}
62+
63+
found := false
64+
for _, value := range values {
65+
if value == expected {
66+
found = true
67+
break
68+
}
69+
}
70+
if !found {
71+
return false
72+
}
73+
}
74+
75+
return true
76+
}
77+
78+
func summary(p *profile.Profile, filterLabel map[string]string) (string, error) {
79+
var b strings.Builder
80+
81+
for _, sample := range p.Sample {
82+
if !filterMatches(sample, filterLabel) {
83+
continue
84+
}
85+
86+
fmt.Fprintf(&b, "count %d @", sample.Value[0])
87+
88+
// stack trace summary
89+
90+
if len(sample.Label)+len(sample.NumLabel) > 0 {
91+
if len(sample.Label) > 0 {
92+
keys := []string{}
93+
for k := range sample.Label {
94+
if _, inFilter := filterLabel[k]; inFilter {
95+
continue
96+
}
97+
keys = append(keys, k)
98+
}
99+
sort.Strings(keys)
100+
for _, k := range keys {
101+
values := sample.Label[k]
102+
fmt.Fprintf(&b, " %s:", k)
103+
switch len(values) {
104+
case 0:
105+
case 1:
106+
fmt.Fprintf(&b, "%q", values[0])
107+
default:
108+
fmt.Fprintf(&b, "%q", values)
109+
}
110+
}
111+
}
112+
if len(sample.NumLabel) > 0 {
113+
keys := []string{}
114+
for k := range sample.NumLabel {
115+
keys = append(keys, k)
116+
}
117+
sort.Strings(keys)
118+
for _, k := range keys {
119+
fmt.Fprintf(&b, "%s:%v", k, sample.NumLabel[k])
120+
}
121+
}
122+
}
123+
fmt.Fprintf(&b, "\n")
124+
125+
// each line
126+
for _, loc := range sample.Location {
127+
for i, ln := range loc.Line {
128+
if i == 0 {
129+
fmt.Fprintf(&b, "# %#8x", loc.Address)
130+
if loc.IsFolded {
131+
fmt.Fprint(&b, " [F]")
132+
}
133+
} else {
134+
fmt.Fprint(&b, "# ")
135+
}
136+
if fn := ln.Function; fn != nil {
137+
fmt.Fprintf(&b, " %-50s %s:%d", fn.Name, fn.Filename, ln.Line)
138+
} else {
139+
fmt.Fprintf(&b, " ???")
140+
}
141+
fmt.Fprintf(&b, "\n")
142+
}
143+
}
144+
fmt.Fprintf(&b, "\n")
145+
}
146+
return b.String(), nil
147+
}

‎testtrace/trace_test.go

+58
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
// Copyright (C) 2021 Storj Labs, Inc.
2+
// See LICENSE for copying information.
3+
4+
package testtrace_test
5+
6+
import (
7+
"context"
8+
"runtime/pprof"
9+
"testing"
10+
"time"
11+
12+
"github.com/stretchr/testify/require"
13+
14+
"storj.io/common/testtrace"
15+
)
16+
17+
func TestLabels(t *testing.T) {
18+
const label = "LABEL IS VISIBLE"
19+
20+
ctx, cancel := context.WithCancel(context.Background())
21+
t.Cleanup(cancel)
22+
23+
pprof.Do(ctx, pprof.Labels("name", label), func(c context.Context) {
24+
for k := 0; k < 3; k++ {
25+
go func() { <-c.Done() }()
26+
}
27+
})
28+
29+
time.Sleep(time.Millisecond)
30+
31+
trace, err := testtrace.Summary()
32+
require.NoError(t, err)
33+
t.Log("\n" + trace)
34+
35+
require.Contains(t, trace, label)
36+
}
37+
38+
func TestFilter(t *testing.T) {
39+
ctx, cancel := context.WithCancel(context.Background())
40+
t.Cleanup(cancel)
41+
42+
pprof.Do(ctx, pprof.Labels("name", "alpha", "user", "ALPHA"), func(c context.Context) {
43+
go func() { <-c.Done() }()
44+
})
45+
pprof.Do(ctx, pprof.Labels("name", "beta", "user", "BETA"), func(c context.Context) {
46+
go func() { <-c.Done() }()
47+
})
48+
49+
time.Sleep(time.Millisecond)
50+
51+
trace, err := testtrace.Summary("name", "alpha")
52+
require.NoError(t, err)
53+
t.Log("\n" + trace)
54+
55+
require.Contains(t, trace, "ALPHA")
56+
require.NotContains(t, trace, "alpha")
57+
require.NotContains(t, trace, "BETA")
58+
}

0 commit comments

Comments
 (0)