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
)