1 // Copyright 2014 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.
25 saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
28 // TestEventBatch tests Flush calls that happen during Start
29 // don't produce corrupted traces.
30 func TestEventBatch(t *testing.T) {
32 t.Skip("skipping in race mode")
35 t.Skip("skipping because -test.trace is set")
38 t.Skip("skipping in short mode")
40 // During Start, bunch of records are written to reflect the current
41 // snapshot of the program, including state of each goroutines.
42 // And some string constants are written to the trace to aid trace
43 // parsing. This test checks Flush of the buffer occurred during
44 // this process doesn't cause corrupted traces.
45 // When a Flush is called during Start is complicated
46 // so we test with a range of number of goroutines hoping that one
47 // of them triggers Flush.
48 // This range was chosen to fill up a ~64KB buffer with traceEvGoCreate
49 // and traceEvGoWaiting events (12~13bytes per goroutine).
50 for g := 4950; g < 5050; g++ {
52 t.Run("G="+strconv.Itoa(n), func(t *testing.T) {
56 in := make(chan bool, 1000)
57 for i := 0; i < n; i++ {
63 buf := new(bytes.Buffer)
64 if err := Start(buf); err != nil {
65 t.Fatalf("failed to start tracing: %v", err)
68 for i := 0; i < n; i++ {
74 _, err := trace.Parse(buf, "")
75 if err == trace.ErrTimeOrder {
76 t.Skipf("skipping trace: %v", err)
80 t.Fatalf("failed to parse trace: %v", err)
86 func TestTraceStartStop(t *testing.T) {
88 t.Skip("skipping because -test.trace is set")
90 buf := new(bytes.Buffer)
91 if err := Start(buf); err != nil {
92 t.Fatalf("failed to start tracing: %v", err)
97 t.Fatalf("trace is empty")
99 time.Sleep(100 * time.Millisecond)
100 if size != buf.Len() {
101 t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
103 saveTrace(t, buf, "TestTraceStartStop")
106 func TestTraceDoubleStart(t *testing.T) {
108 t.Skip("skipping because -test.trace is set")
111 buf := new(bytes.Buffer)
112 if err := Start(buf); err != nil {
113 t.Fatalf("failed to start tracing: %v", err)
115 if err := Start(buf); err == nil {
116 t.Fatalf("succeed to start tracing second time")
122 func TestTrace(t *testing.T) {
124 t.Skip("skipping because -test.trace is set")
126 buf := new(bytes.Buffer)
127 if err := Start(buf); err != nil {
128 t.Fatalf("failed to start tracing: %v", err)
131 saveTrace(t, buf, "TestTrace")
132 _, err := trace.Parse(buf, "")
133 if err == trace.ErrTimeOrder {
134 t.Skipf("skipping trace: %v", err)
137 t.Fatalf("failed to parse trace: %v", err)
141 func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
142 res, err := trace.Parse(r, "")
143 if err == trace.ErrTimeOrder {
144 t.Skipf("skipping trace: %v", err)
147 t.Fatalf("failed to parse trace: %v", err)
149 gs := trace.GoroutineStats(res.Events)
150 for goid := range gs {
151 // We don't do any particular checks on the result at the moment.
152 // But still check that RelatedGoroutines does not crash, hang, etc.
153 _ = trace.RelatedGoroutines(res.Events, goid)
155 return res.Events, gs
158 func testBrokenTimestamps(t *testing.T, data []byte) {
159 // On some processors cputicks (used to generate trace timestamps)
160 // produce non-monotonic timestamps. It is important that the parser
161 // distinguishes logically inconsistent traces (e.g. missing, excessive
162 // or misordered events) from broken timestamps. The former is a bug
163 // in tracer, the latter is a machine issue.
164 // So now that we have a consistent trace, test that (1) parser does
165 // not return a logical error in case of broken timestamps
166 // and (2) broken timestamps are eventually detected and reported.
167 trace.BreakTimestampsForTesting = true
169 trace.BreakTimestampsForTesting = false
171 for i := 0; i < 1e4; i++ {
172 _, err := trace.Parse(bytes.NewReader(data), "")
173 if err == trace.ErrTimeOrder {
177 t.Fatalf("failed to parse trace: %v", err)
182 func TestTraceStress(t *testing.T) {
183 if runtime.GOOS == "js" {
184 t.Skip("no os.Pipe on js")
187 t.Skip("skipping because -test.trace is set")
189 var wg sync.WaitGroup
190 done := make(chan bool)
192 // Create a goroutine blocked before tracing.
199 // Create a goroutine blocked in syscall before tracing.
200 rp, wp, err := os.Pipe()
202 t.Fatalf("failed to create pipe: %v", err)
215 time.Sleep(time.Millisecond) // give the goroutine above time to block
217 buf := new(bytes.Buffer)
218 if err := Start(buf); err != nil {
219 t.Fatalf("failed to start tracing: %v", err)
222 procs := runtime.GOMAXPROCS(10)
223 time.Sleep(50 * time.Millisecond) // test proc stop/start events
226 runtime.LockOSThread()
238 // Trigger GC from malloc.
240 if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
241 // Reduce allocation to avoid running out of
242 // memory on the builder - see issue/12032.
245 for i := 0; i < n; i++ {
246 _ = make([]byte, 1<<20)
249 // Create a bunch of busy goroutines to load all Ps.
250 for p := 0; p < 10; p++ {
253 // Do something useful.
254 tmp := make([]byte, 1<<16)
274 timerDone := make(chan bool)
276 time.Sleep(time.Millisecond)
282 ln, err := net.Listen("tcp", "127.0.0.1:0")
284 t.Fatalf("listen failed: %v", err)
288 c, err := ln.Accept()
292 time.Sleep(time.Millisecond)
297 c, err := net.Dial("tcp", ln.Addr().String())
299 t.Fatalf("dial failed: %v", err)
310 // Unblock helper goroutines and wait them to finish.
316 runtime.GOMAXPROCS(procs)
319 saveTrace(t, buf, "TestTraceStress")
322 testBrokenTimestamps(t, trace)
325 // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
326 // And concurrently with all that start/stop trace 3 times.
327 func TestTraceStressStartStop(t *testing.T) {
328 if runtime.GOOS == "js" {
329 t.Skip("no os.Pipe on js")
332 t.Skip("skipping because -test.trace is set")
334 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
335 outerDone := make(chan bool)
342 var wg sync.WaitGroup
343 done := make(chan bool)
351 rp, wp, err := os.Pipe()
353 t.Errorf("failed to create pipe: %v", err)
367 time.Sleep(time.Millisecond)
370 runtime.LockOSThread()
382 // Trigger GC from malloc.
384 if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
385 // Reduce allocation to avoid running out of
386 // memory on the builder - see issue/12032.
389 for i := 0; i < n; i++ {
390 _ = make([]byte, 1<<20)
393 // Create a bunch of busy goroutines to load all Ps.
394 for p := 0; p < 10; p++ {
397 // Do something useful.
398 tmp := make([]byte, 1<<16)
417 runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
420 timerDone := make(chan bool)
422 time.Sleep(time.Millisecond)
428 ln, err := net.Listen("tcp", "127.0.0.1:0")
430 t.Errorf("listen failed: %v", err)
435 c, err := ln.Accept()
439 time.Sleep(time.Millisecond)
444 c, err := net.Dial("tcp", ln.Addr().String())
446 t.Errorf("dial failed: %v", err)
458 // Unblock helper goroutines and wait them to finish.
465 for i := 0; i < 3; i++ {
466 buf := new(bytes.Buffer)
467 if err := Start(buf); err != nil {
468 t.Fatalf("failed to start tracing: %v", err)
470 time.Sleep(time.Millisecond)
472 saveTrace(t, buf, "TestTraceStressStartStop")
475 testBrokenTimestamps(t, trace)
480 func TestTraceFutileWakeup(t *testing.T) {
482 t.Skip("skipping because -test.trace is set")
484 buf := new(bytes.Buffer)
485 if err := Start(buf); err != nil {
486 t.Fatalf("failed to start tracing: %v", err)
489 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
490 c0 := make(chan int, 1)
491 c1 := make(chan int, 1)
492 c2 := make(chan int, 1)
494 var done sync.WaitGroup
496 for p := 0; p < procs; p++ {
499 for i := 0; i < iters; i++ {
506 for i := 0; i < iters; i++ {
513 for i := 0; i < iters; i++ {
523 for i := 0; i < iters; i++ {
536 saveTrace(t, buf, "TestTraceFutileWakeup")
537 events, _ := parseTrace(t, buf)
538 // Check that (1) trace does not contain EvFutileWakeup events and
539 // (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
540 // (we call runtime.Gosched between all operations, so these would be futile wakeups).
541 gs := make(map[uint64]int)
542 for _, ev := range events {
544 case trace.EvFutileWakeup:
545 t.Fatalf("found EvFutileWakeup event")
546 case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
548 t.Fatalf("goroutine %v blocked on %v at %v right after start",
549 ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
552 t.Fatalf("goroutine %v blocked on %v at %v while blocked",
553 ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
556 case trace.EvGoStart:
566 func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
570 if err := ioutil.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
571 t.Errorf("failed to write trace file: %s", err)