-
Notifications
You must be signed in to change notification settings - Fork 17.3k
/
trace_test.go
615 lines (589 loc) · 18.1 KB
/
trace_test.go
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
// Copyright 2023 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.
package trace_test
import (
"bufio"
"bytes"
"fmt"
"internal/race"
"internal/testenv"
"internal/trace/v2"
"internal/trace/v2/testtrace"
"io"
"os"
"path/filepath"
"runtime"
"strings"
"testing"
)
func TestTraceAnnotations(t *testing.T) {
testTraceProg(t, "annotations.go", func(t *testing.T, tb, _ []byte, _ bool) {
type evDesc struct {
kind trace.EventKind
task trace.TaskID
args []string
}
want := []evDesc{
{trace.EventTaskBegin, trace.TaskID(1), []string{"task0"}},
{trace.EventRegionBegin, trace.TaskID(1), []string{"region0"}},
{trace.EventRegionBegin, trace.TaskID(1), []string{"region1"}},
{trace.EventLog, trace.TaskID(1), []string{"key0", "0123456789abcdef"}},
{trace.EventRegionEnd, trace.TaskID(1), []string{"region1"}},
{trace.EventRegionEnd, trace.TaskID(1), []string{"region0"}},
{trace.EventTaskEnd, trace.TaskID(1), []string{"task0"}},
// Currently, pre-existing region is not recorded to avoid allocations.
{trace.EventRegionBegin, trace.BackgroundTask, []string{"post-existing region"}},
}
r, err := trace.NewReader(bytes.NewReader(tb))
if err != nil {
t.Error(err)
}
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatal(err)
}
for i, wantEv := range want {
if wantEv.kind != ev.Kind() {
continue
}
match := false
switch ev.Kind() {
case trace.EventTaskBegin, trace.EventTaskEnd:
task := ev.Task()
match = task.ID == wantEv.task && task.Type == wantEv.args[0]
case trace.EventRegionBegin, trace.EventRegionEnd:
reg := ev.Region()
match = reg.Task == wantEv.task && reg.Type == wantEv.args[0]
case trace.EventLog:
log := ev.Log()
match = log.Task == wantEv.task && log.Category == wantEv.args[0] && log.Message == wantEv.args[1]
}
if match {
want[i] = want[len(want)-1]
want = want[:len(want)-1]
break
}
}
}
if len(want) != 0 {
for _, ev := range want {
t.Errorf("no match for %s TaskID=%d Args=%#v", ev.kind, ev.task, ev.args)
}
}
})
}
func TestTraceAnnotationsStress(t *testing.T) {
testTraceProg(t, "annotations-stress.go", nil)
}
func TestTraceCgoCallback(t *testing.T) {
testenv.MustHaveCGO(t)
switch runtime.GOOS {
case "plan9", "windows":
t.Skipf("cgo callback test requires pthreads and is not supported on %s", runtime.GOOS)
}
testTraceProg(t, "cgo-callback.go", nil)
}
func TestTraceCPUProfile(t *testing.T) {
testTraceProg(t, "cpu-profile.go", func(t *testing.T, tb, stderr []byte, _ bool) {
// Parse stderr which has a CPU profile summary, if everything went well.
// (If it didn't, we shouldn't even make it here.)
scanner := bufio.NewScanner(bytes.NewReader(stderr))
pprofSamples := 0
pprofStacks := make(map[string]int)
for scanner.Scan() {
var stack string
var samples int
_, err := fmt.Sscanf(scanner.Text(), "%s\t%d", &stack, &samples)
if err != nil {
t.Fatalf("failed to parse CPU profile summary in stderr: %s\n\tfull:\n%s", scanner.Text(), stderr)
}
pprofStacks[stack] = samples
pprofSamples += samples
}
if err := scanner.Err(); err != nil {
t.Fatalf("failed to parse CPU profile summary in stderr: %v", err)
}
if pprofSamples == 0 {
t.Skip("CPU profile did not include any samples while tracing was active")
}
// Examine the execution tracer's view of the CPU profile samples. Filter it
// to only include samples from the single test goroutine. Use the goroutine
// ID that was recorded in the events: that should reflect getg().m.curg,
// same as the profiler's labels (even when the M is using its g0 stack).
totalTraceSamples := 0
traceSamples := 0
traceStacks := make(map[string]int)
r, err := trace.NewReader(bytes.NewReader(tb))
if err != nil {
t.Error(err)
}
var hogRegion *trace.Event
var hogRegionClosed bool
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatal(err)
}
if ev.Kind() == trace.EventRegionBegin && ev.Region().Type == "cpuHogger" {
hogRegion = &ev
}
if ev.Kind() == trace.EventStackSample {
totalTraceSamples++
if hogRegion != nil && ev.Goroutine() == hogRegion.Goroutine() {
traceSamples++
var fns []string
ev.Stack().Frames(func(frame trace.StackFrame) bool {
if frame.Func != "runtime.goexit" {
fns = append(fns, fmt.Sprintf("%s:%d", frame.Func, frame.Line))
}
return true
})
stack := strings.Join(fns, "|")
traceStacks[stack]++
}
}
if ev.Kind() == trace.EventRegionEnd && ev.Region().Type == "cpuHogger" {
hogRegionClosed = true
}
}
if hogRegion == nil {
t.Fatalf("execution trace did not identify cpuHogger goroutine")
} else if !hogRegionClosed {
t.Fatalf("execution trace did not close cpuHogger region")
}
// The execution trace may drop CPU profile samples if the profiling buffer
// overflows. Based on the size of profBufWordCount, that takes a bit over
// 1900 CPU samples or 19 thread-seconds at a 100 Hz sample rate. If we've
// hit that case, then we definitely have at least one full buffer's worth
// of CPU samples, so we'll call that success.
overflowed := totalTraceSamples >= 1900
if traceSamples < pprofSamples {
t.Logf("execution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples)
if !overflowed {
t.Fail()
}
}
for stack, traceSamples := range traceStacks {
pprofSamples := pprofStacks[stack]
delete(pprofStacks, stack)
if traceSamples < pprofSamples {
t.Logf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace",
stack, pprofSamples, traceSamples)
if !overflowed {
t.Fail()
}
}
}
for stack, pprofSamples := range pprofStacks {
t.Logf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack)
if !overflowed {
t.Fail()
}
}
if t.Failed() {
t.Logf("execution trace CPU samples:")
for stack, samples := range traceStacks {
t.Logf("%d: %q", samples, stack)
}
t.Logf("CPU profile:\n%s", stderr)
}
})
}
func TestTraceFutileWakeup(t *testing.T) {
testTraceProg(t, "futile-wakeup.go", func(t *testing.T, tb, _ []byte, _ bool) {
// Check to make sure that no goroutine in the "special" trace region
// ends up blocking, unblocking, then immediately blocking again.
//
// The goroutines are careful to call runtime.Gosched in between blocking,
// so there should never be a clean block/unblock on the goroutine unless
// the runtime was generating extraneous events.
const (
entered = iota
blocked
runnable
running
)
gs := make(map[trace.GoID]int)
seenSpecialGoroutines := false
r, err := trace.NewReader(bytes.NewReader(tb))
if err != nil {
t.Error(err)
}
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatal(err)
}
// Only track goroutines in the special region we control, so runtime
// goroutines don't interfere (it's totally valid in traces for a
// goroutine to block, run, and block again; that's not what we care about).
if ev.Kind() == trace.EventRegionBegin && ev.Region().Type == "special" {
seenSpecialGoroutines = true
gs[ev.Goroutine()] = entered
}
if ev.Kind() == trace.EventRegionEnd && ev.Region().Type == "special" {
delete(gs, ev.Goroutine())
}
// Track state transitions for goroutines we care about.
//
// The goroutines we care about will advance through the state machine
// of entered -> blocked -> runnable -> running. If in the running state
// we block, then we have a futile wakeup. Because of the runtime.Gosched
// on these specially marked goroutines, we should end up back in runnable
// first. If at any point we go to a different state, switch back to entered
// and wait for the next time the goroutine blocks.
if ev.Kind() != trace.EventStateTransition {
continue
}
st := ev.StateTransition()
if st.Resource.Kind != trace.ResourceGoroutine {
continue
}
id := st.Resource.Goroutine()
state, ok := gs[id]
if !ok {
continue
}
_, new := st.Goroutine()
switch state {
case entered:
if new == trace.GoWaiting {
state = blocked
} else {
state = entered
}
case blocked:
if new == trace.GoRunnable {
state = runnable
} else {
state = entered
}
case runnable:
if new == trace.GoRunning {
state = running
} else {
state = entered
}
case running:
if new == trace.GoWaiting {
t.Fatalf("found futile wakeup on goroutine %d", id)
} else {
state = entered
}
}
gs[id] = state
}
if !seenSpecialGoroutines {
t.Fatal("did not see a goroutine in a the region 'special'")
}
})
}
func TestTraceGCStress(t *testing.T) {
testTraceProg(t, "gc-stress.go", nil)
}
func TestTraceGOMAXPROCS(t *testing.T) {
testTraceProg(t, "gomaxprocs.go", nil)
}
func TestTraceStacks(t *testing.T) {
testTraceProg(t, "stacks.go", func(t *testing.T, tb, _ []byte, stress bool) {
type frame struct {
fn string
line int
}
type evDesc struct {
kind trace.EventKind
match string
frames []frame
}
// mainLine is the line number of `func main()` in testprog/stacks.go.
const mainLine = 21
want := []evDesc{
{trace.EventStateTransition, "Goroutine Running->Runnable", []frame{
{"main.main", mainLine + 82},
}},
{trace.EventStateTransition, "Goroutine NotExist->Runnable", []frame{
{"main.main", mainLine + 11},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.block", 0},
{"main.main.func1", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.chansend1", 0},
{"main.main.func2", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.chanrecv1", 0},
{"main.main.func3", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.chanrecv1", 0},
{"main.main.func4", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"runtime.chansend1", 0},
{"main.main", mainLine + 84},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.chansend1", 0},
{"main.main.func5", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"runtime.chanrecv1", 0},
{"main.main", mainLine + 85},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"runtime.selectgo", 0},
{"main.main.func6", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"runtime.selectgo", 0},
{"main.main", mainLine + 86},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"sync.(*Mutex).Lock", 0},
{"main.main.func7", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"sync.(*Mutex).Unlock", 0},
{"main.main", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"sync.(*WaitGroup).Wait", 0},
{"main.main.func8", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"sync.(*WaitGroup).Add", 0},
{"sync.(*WaitGroup).Done", 0},
{"main.main", mainLine + 91},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"sync.(*Cond).Wait", 0},
{"main.main.func9", 0},
}},
{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
{"sync.(*Cond).Signal", 0},
{"main.main", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"time.Sleep", 0},
{"main.main", 0},
}},
{trace.EventMetric, "/sched/gomaxprocs:threads", []frame{
{"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
{"runtime.startTheWorldGC", 0},
{"runtime.GOMAXPROCS", 0},
{"main.main", 0},
}},
}
if !stress {
// Only check for this stack if !stress because traceAdvance alone could
// allocate enough memory to trigger a GC if called frequently enough.
// This might cause the runtime.GC call we're trying to match against to
// coalesce with an active GC triggered this by traceAdvance. In that case
// we won't have an EventRangeBegin event that matches the stace trace we're
// looking for, since runtime.GC will not have triggered the GC.
gcEv := evDesc{trace.EventRangeBegin, "GC concurrent mark phase", []frame{
{"runtime.GC", 0},
{"main.main", 0},
}}
want = append(want, gcEv)
}
if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
want = append(want, []evDesc{
{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
{"internal/poll.(*FD).Accept", 0},
{"net.(*netFD).accept", 0},
{"net.(*TCPListener).accept", 0},
{"net.(*TCPListener).Accept", 0},
{"main.main.func10", 0},
}},
{trace.EventStateTransition, "Goroutine Running->Syscall", []frame{
{"syscall.read", 0},
{"syscall.Read", 0},
{"internal/poll.ignoringEINTRIO", 0},
{"internal/poll.(*FD).Read", 0},
{"os.(*File).read", 0},
{"os.(*File).Read", 0},
{"main.main.func11", 0},
}},
}...)
}
stackMatches := func(stk trace.Stack, frames []frame) bool {
i := 0
match := true
stk.Frames(func(f trace.StackFrame) bool {
if f.Func != frames[i].fn {
match = false
return false
}
if line := uint64(frames[i].line); line != 0 && line != f.Line {
match = false
return false
}
i++
return true
})
return match
}
r, err := trace.NewReader(bytes.NewReader(tb))
if err != nil {
t.Error(err)
}
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatal(err)
}
for i, wantEv := range want {
if wantEv.kind != ev.Kind() {
continue
}
match := false
switch ev.Kind() {
case trace.EventStateTransition:
st := ev.StateTransition()
str := ""
switch st.Resource.Kind {
case trace.ResourceGoroutine:
old, new := st.Goroutine()
str = fmt.Sprintf("%s %s->%s", st.Resource.Kind, old, new)
}
match = str == wantEv.match
case trace.EventRangeBegin:
rng := ev.Range()
match = rng.Name == wantEv.match
case trace.EventMetric:
metric := ev.Metric()
match = metric.Name == wantEv.match
}
match = match && stackMatches(ev.Stack(), wantEv.frames)
if match {
want[i] = want[len(want)-1]
want = want[:len(want)-1]
break
}
}
}
if len(want) != 0 {
for _, ev := range want {
t.Errorf("no match for %s Match=%s Stack=%#v", ev.kind, ev.match, ev.frames)
}
}
})
}
func TestTraceStress(t *testing.T) {
switch runtime.GOOS {
case "js", "wasip1":
t.Skip("no os.Pipe on " + runtime.GOOS)
}
testTraceProg(t, "stress.go", nil)
}
func TestTraceStressStartStop(t *testing.T) {
switch runtime.GOOS {
case "js", "wasip1":
t.Skip("no os.Pipe on " + runtime.GOOS)
}
testTraceProg(t, "stress-start-stop.go", nil)
}
func TestTraceManyStartStop(t *testing.T) {
testTraceProg(t, "many-start-stop.go", nil)
}
func TestTraceWaitOnPipe(t *testing.T) {
switch runtime.GOOS {
case "dragonfly", "freebsd", "linux", "netbsd", "openbsd", "solaris":
testTraceProg(t, "wait-on-pipe.go", nil)
return
}
t.Skip("no applicable syscall.Pipe on " + runtime.GOOS)
}
func TestTraceIterPull(t *testing.T) {
testTraceProg(t, "iter-pull.go", nil)
}
func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace, stderr []byte, stress bool)) {
testenv.MustHaveGoRun(t)
// Check if we're on a builder.
onBuilder := testenv.Builder() != ""
onOldBuilder := !strings.Contains(testenv.Builder(), "gotip") && !strings.Contains(testenv.Builder(), "go1")
testPath := filepath.Join("./testdata/testprog", progName)
testName := progName
runTest := func(t *testing.T, stress bool) {
// Run the program and capture the trace, which is always written to stdout.
cmd := testenv.Command(t, testenv.GoToolPath(t), "run")
if race.Enabled {
cmd.Args = append(cmd.Args, "-race")
}
cmd.Args = append(cmd.Args, testPath)
cmd.Env = append(os.Environ(), "GOEXPERIMENT=exectracer2", "GOEXPERIMENT=rangefunc")
if stress {
// Advance a generation constantly.
cmd.Env = append(cmd.Env, "GODEBUG=traceadvanceperiod=0")
}
// Capture stdout and stderr.
//
// The protocol for these programs is that stdout contains the trace data
// and stderr is an expectation in string format.
var traceBuf, errBuf bytes.Buffer
cmd.Stdout = &traceBuf
cmd.Stderr = &errBuf
// Run the program.
if err := cmd.Run(); err != nil {
if errBuf.Len() != 0 {
t.Logf("stderr: %s", string(errBuf.Bytes()))
}
t.Fatal(err)
}
tb := traceBuf.Bytes()
// Test the trace and the parser.
testReader(t, bytes.NewReader(tb), testtrace.ExpectSuccess())
// Run some extra validation.
if !t.Failed() && extra != nil {
extra(t, tb, errBuf.Bytes(), stress)
}
// Dump some more information on failure.
if t.Failed() && onBuilder {
// Dump directly to the test log on the builder, since this
// data is critical for debugging and this is the only way
// we can currently make sure it's retained.
t.Log("found bad trace; dumping to test log...")
s := dumpTraceToText(t, tb)
if onOldBuilder && len(s) > 1<<20+512<<10 {
// The old build infrastructure truncates logs at ~2 MiB.
// Let's assume we're the only failure and give ourselves
// up to 1.5 MiB to dump the trace.
//
// TODO(mknyszek): Remove this when we've migrated off of
// the old infrastructure.
t.Logf("text trace too large to dump (%d bytes)", len(s))
} else {
t.Log(s)
}
} else if t.Failed() || *dumpTraces {
// We asked to dump the trace or failed. Write the trace to a file.
t.Logf("wrote trace to file: %s", dumpTraceToFile(t, testName, stress, tb))
}
}
t.Run("Default", func(t *testing.T) {
runTest(t, false)
})
t.Run("Stress", func(t *testing.T) {
if testing.Short() {
t.Skip("skipping trace reader stress tests in short mode")
}
runTest(t, true)
})
}