blob: 11f9aba616260eb4947e1b299604f5aa8700e4e2 [file] [log] [blame]
Dmitry Vyukovedadffa2015-01-30 13:31:43 +03001// 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.
4
5package trace
6
7import (
8 "bufio"
9 "bytes"
10 "fmt"
11 "io"
12 "os"
13 "os/exec"
14 "sort"
15 "strconv"
16 "strings"
17)
18
19// Event describes one event in the trace.
20type Event struct {
21 Off int // offset in input file (for debugging and error reporting)
22 Type byte // one of Ev*
Russ Cox80c98fa2015-07-23 14:01:03 -040023 Seq int64 // sequence number
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030024 Ts int64 // timestamp in nanoseconds
25 P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
26 G uint64 // G on which the event happened
27 StkID uint64 // unique stack ID
28 Stk []*Frame // stack trace (can be empty)
Russ Cox80c98fa2015-07-23 14:01:03 -040029 Args [3]uint64 // event-type-specific arguments
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030030 // linked event (can be nil), depends on event type:
31 // for GCStart: the GCStop
32 // for GCScanStart: the GCScanDone
33 // for GCSweepStart: the GCSweepDone
34 // for GoCreate: first GoStart of the created goroutine
35 // for GoStart: the associated GoEnd, GoBlock or other blocking event
36 // for GoSched/GoPreempt: the next GoStart
37 // for GoBlock and other blocking events: the unblock event
38 // for GoUnblock: the associated GoStart
39 // for blocking GoSysCall: the associated GoSysExit
40 // for GoSysExit: the next GoStart
41 Link *Event
42}
43
44// Frame is a frame in stack traces.
45type Frame struct {
46 PC uint64
47 Fn string
48 File string
49 Line int
50}
51
52const (
53 // Special P identifiers:
54 FakeP = 1000000 + iota
55 TimerP // depicts timer unblocks
56 NetpollP // depicts network unblocks
57 SyscallP // depicts returns from syscalls
58)
59
Dmitry Vyukov4396ea92015-03-11 18:29:12 +030060// Parse parses, post-processes and verifies the trace.
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030061func Parse(r io.Reader) ([]*Event, error) {
62 rawEvents, err := readTrace(r)
63 if err != nil {
64 return nil, err
65 }
66 events, err := parseEvents(rawEvents)
67 if err != nil {
68 return nil, err
69 }
Dmitry Vyukov4396ea92015-03-11 18:29:12 +030070 events, err = removeFutile(events)
71 if err != nil {
72 return nil, err
73 }
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030074 err = postProcessTrace(events)
75 if err != nil {
76 return nil, err
77 }
78 return events, nil
79}
80
81// rawEvent is a helper type used during parsing.
82type rawEvent struct {
83 off int
84 typ byte
85 args []uint64
86}
87
88// readTrace does wire-format parsing and verification.
89// It does not care about specific event types and argument meaning.
90func readTrace(r io.Reader) ([]rawEvent, error) {
91 // Read and validate trace header.
Russ Cox80c98fa2015-07-23 14:01:03 -040092 var buf [16]byte
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030093 off, err := r.Read(buf[:])
Russ Cox80c98fa2015-07-23 14:01:03 -040094 if off != 16 || err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030095 return nil, fmt.Errorf("failed to read header: read %v, err %v", off, err)
96 }
Russ Cox80c98fa2015-07-23 14:01:03 -040097 if bytes.Compare(buf[:], []byte("go 1.5 trace\x00\x00\x00\x00")) != 0 {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +030098 return nil, fmt.Errorf("not a trace file")
99 }
100
101 // Read events.
102 var events []rawEvent
103 for {
104 // Read event type and number of arguments (1 byte).
105 off0 := off
106 n, err := r.Read(buf[:1])
107 if err == io.EOF {
108 break
109 }
110 if err != nil || n != 1 {
111 return nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
112 }
113 off += n
114 typ := buf[0] << 2 >> 2
Russ Cox80c98fa2015-07-23 14:01:03 -0400115 narg := buf[0] >> 6
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300116 ev := rawEvent{typ: typ, off: off0}
Russ Cox80c98fa2015-07-23 14:01:03 -0400117 if narg < 3 {
118 for i := 0; i < int(narg)+2; i++ { // sequence number and time stamp are present but not counted in narg
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300119 var v uint64
120 v, off, err = readVal(r, off)
121 if err != nil {
122 return nil, err
123 }
124 ev.args = append(ev.args, v)
125 }
126 } else {
Russ Cox80c98fa2015-07-23 14:01:03 -0400127 // If narg == 3, the first value is length of the event in bytes.
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300128 var v uint64
129 v, off, err = readVal(r, off)
130 if err != nil {
131 return nil, err
132 }
133 evLen := v
134 off1 := off
135 for evLen > uint64(off-off1) {
136 v, off, err = readVal(r, off)
137 if err != nil {
138 return nil, err
139 }
140 ev.args = append(ev.args, v)
141 }
142 if evLen != uint64(off-off1) {
143 return nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
144 }
145 }
146 events = append(events, ev)
147 }
148 return events, nil
149}
150
151// Parse events transforms raw events into events.
152// It does analyze and verify per-event-type arguments.
153func parseEvents(rawEvents []rawEvent) (events []*Event, err error) {
Russ Cox80c98fa2015-07-23 14:01:03 -0400154 var ticksPerSec, lastSeq, lastTs int64
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300155 var lastG, timerGoid uint64
156 var lastP int
157 lastGs := make(map[int]uint64) // last goroutine running on P
158 stacks := make(map[uint64][]*Frame)
159 for _, raw := range rawEvents {
160 if raw.typ == EvNone || raw.typ >= EvCount {
161 err = fmt.Errorf("unknown event type %v at offset 0x%x", raw.typ, raw.off)
162 return
163 }
164 desc := EventDescriptions[raw.typ]
165 if desc.Name == "" {
166 err = fmt.Errorf("missing description for event type %v", raw.typ)
167 return
168 }
169 if raw.typ != EvStack {
170 narg := len(desc.Args)
171 if desc.Stack {
172 narg++
173 }
174 if raw.typ != EvBatch && raw.typ != EvFrequency && raw.typ != EvTimerGoroutine {
Russ Cox80c98fa2015-07-23 14:01:03 -0400175 narg++ // sequence number
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300176 narg++ // timestamp
177 }
178 if len(raw.args) != narg {
179 err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v",
180 desc.Name, raw.off, narg, len(raw.args))
181 return
182 }
183 }
184 switch raw.typ {
185 case EvBatch:
186 lastGs[lastP] = lastG
187 lastP = int(raw.args[0])
188 lastG = lastGs[lastP]
Russ Cox80c98fa2015-07-23 14:01:03 -0400189 lastSeq = int64(raw.args[1])
190 lastTs = int64(raw.args[2])
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300191 case EvFrequency:
192 ticksPerSec = int64(raw.args[0])
193 if ticksPerSec <= 0 {
Russ Coxca6f7e42015-07-30 13:39:30 -0400194 // The most likely cause for this is tick skew on different CPUs.
195 // For example, solaris/amd64 seems to have wildly different
196 // ticks on different CPUs.
197 err = ErrTimeOrder
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300198 return
199 }
200 case EvTimerGoroutine:
201 timerGoid = raw.args[0]
202 case EvStack:
203 if len(raw.args) < 2 {
204 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v",
205 raw.off, len(raw.args))
206 return
207 }
208 size := raw.args[1]
209 if size > 1000 {
210 err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v",
211 raw.off, size)
212 return
213 }
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700214 if uint64(len(raw.args)) != size+2 {
215 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want %v, got %v",
216 raw.off, size+2, len(raw.args))
217 return
218 }
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300219 id := raw.args[0]
220 if id != 0 && size > 0 {
221 stk := make([]*Frame, size)
222 for i := 0; i < int(size); i++ {
223 stk[i] = &Frame{PC: raw.args[i+2]}
224 }
225 stacks[id] = stk
226 }
227 default:
228 e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG}
Russ Cox80c98fa2015-07-23 14:01:03 -0400229 e.Seq = lastSeq + int64(raw.args[0])
230 e.Ts = lastTs + int64(raw.args[1])
231 lastSeq = e.Seq
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300232 lastTs = e.Ts
233 for i := range desc.Args {
Russ Cox80c98fa2015-07-23 14:01:03 -0400234 e.Args[i] = raw.args[i+2]
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300235 }
236 if desc.Stack {
Russ Cox80c98fa2015-07-23 14:01:03 -0400237 e.StkID = raw.args[len(desc.Args)+2]
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300238 }
239 switch raw.typ {
240 case EvGoStart:
241 lastG = e.Args[0]
242 e.G = lastG
243 case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone:
244 e.G = 0
245 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
246 EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
247 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
248 EvGoSysBlock:
249 lastG = 0
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300250 case EvGoSysExit:
Russ Cox80c98fa2015-07-23 14:01:03 -0400251 // EvGoSysExit emission is delayed until the thread has a P.
252 // Give it the real sequence number and time stamp.
253 e.Seq = int64(e.Args[1])
254 if e.Args[2] != 0 {
255 e.Ts = int64(e.Args[2])
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300256 }
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300257 }
258 events = append(events, e)
259 }
260 }
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700261 if len(events) == 0 {
262 err = fmt.Errorf("trace is empty")
263 return
264 }
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300265
266 // Attach stack traces.
267 for _, ev := range events {
268 if ev.StkID != 0 {
269 ev.Stk = stacks[ev.StkID]
270 }
271 }
272
Russ Cox80c98fa2015-07-23 14:01:03 -0400273 // Sort by sequence number and translate cpu ticks to real time.
274 sort.Sort(eventList(events))
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300275 if ticksPerSec == 0 {
276 err = fmt.Errorf("no EvFrequency event")
277 return
278 }
279 minTs := events[0].Ts
280 for _, ev := range events {
281 ev.Ts = (ev.Ts - minTs) * 1e9 / ticksPerSec
282 // Move timers and syscalls to separate fake Ps.
283 if timerGoid != 0 && ev.G == timerGoid && ev.Type == EvGoUnblock {
284 ev.P = TimerP
285 }
286 if ev.Type == EvGoSysExit {
287 ev.P = SyscallP
288 ev.G = ev.Args[0]
289 }
290 }
291
292 return
293}
294
Dmitry Vyukov4396ea92015-03-11 18:29:12 +0300295// removeFutile removes all constituents of futile wakeups (block, unblock, start).
296// For example, a goroutine was unblocked on a mutex, but another goroutine got
297// ahead and acquired the mutex before the first goroutine is scheduled,
298// so the first goroutine has to block again. Such wakeups happen on buffered
299// channels and sync.Mutex, but are generally not interesting for end user.
300func removeFutile(events []*Event) ([]*Event, error) {
301 // Two non-trivial aspects:
302 // 1. A goroutine can be preempted during a futile wakeup and migrate to another P.
303 // We want to remove all of that.
304 // 2. Tracing can start in the middle of a futile wakeup.
305 // That is, we can see a futile wakeup event w/o the actual wakeup before it.
306 // postProcessTrace runs after us and ensures that we leave the trace in a consistent state.
307
308 // Phase 1: determine futile wakeup sequences.
309 type G struct {
310 futile bool
311 wakeup []*Event // wakeup sequence (subject for removal)
312 }
313 gs := make(map[uint64]G)
314 futile := make(map[*Event]bool)
315 for _, ev := range events {
316 switch ev.Type {
317 case EvGoUnblock:
318 g := gs[ev.Args[0]]
319 g.wakeup = []*Event{ev}
320 gs[ev.Args[0]] = g
321 case EvGoStart, EvGoPreempt, EvFutileWakeup:
322 g := gs[ev.G]
323 g.wakeup = append(g.wakeup, ev)
324 if ev.Type == EvFutileWakeup {
325 g.futile = true
326 }
327 gs[ev.G] = g
328 case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond:
329 g := gs[ev.G]
330 if g.futile {
331 futile[ev] = true
332 for _, ev1 := range g.wakeup {
333 futile[ev1] = true
334 }
335 }
336 delete(gs, ev.G)
337 }
338 }
339
340 // Phase 2: remove futile wakeup sequences.
341 newEvents := events[:0] // overwrite the original slice
342 for _, ev := range events {
343 if !futile[ev] {
344 newEvents = append(newEvents, ev)
345 }
346 }
347 return newEvents, nil
348}
349
Russ Cox80c98fa2015-07-23 14:01:03 -0400350// ErrTimeOrder is returned by Parse when the trace contains
351// time stamps that do not respect actual event ordering.
352var ErrTimeOrder = fmt.Errorf("time stamps out of order")
353
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300354// postProcessTrace does inter-event verification and information restoration.
355// The resulting trace is guaranteed to be consistent
356// (for example, a P does not run two Gs at the same time, or a G is indeed
357// blocked before an unblock event).
358func postProcessTrace(events []*Event) error {
359 const (
360 gDead = iota
361 gRunnable
362 gRunning
363 gWaiting
364 )
365 type gdesc struct {
Dmitry Vyukov7b0c73a2015-03-10 19:40:09 +0300366 state int
367 ev *Event
368 evStart *Event
369 evCreate *Event
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300370 }
371 type pdesc struct {
372 running bool
373 g uint64
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300374 evScan *Event
375 evSweep *Event
376 }
377
378 gs := make(map[uint64]gdesc)
379 ps := make(map[int]pdesc)
380 gs[0] = gdesc{state: gRunning}
Austin Clementseec6fdc2015-04-09 10:03:26 -0400381 var evGC *Event
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300382
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700383 checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300384 name := EventDescriptions[ev.Type].Name
385 if g.state != gRunning {
386 return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts)
387 }
388 if p.g != ev.G {
389 return fmt.Errorf("p %v is not running g %v while %v (offset %v, time %v)", ev.P, ev.G, name, ev.Off, ev.Ts)
390 }
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700391 if !allowG0 && ev.G == 0 {
392 return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].Name, ev.Off, ev.Ts)
393 }
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300394 return nil
395 }
396
397 for _, ev := range events {
398 g := gs[ev.G]
399 p := ps[ev.P]
400
401 switch ev.Type {
402 case EvProcStart:
403 if p.running {
404 return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
405 }
406 p.running = true
407 case EvProcStop:
408 if !p.running {
409 return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
410 }
411 if p.g != 0 {
412 return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts)
413 }
414 p.running = false
415 case EvGCStart:
Austin Clementseec6fdc2015-04-09 10:03:26 -0400416 if evGC != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300417 return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
418 }
Austin Clementseec6fdc2015-04-09 10:03:26 -0400419 evGC = ev
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300420 case EvGCDone:
Austin Clementseec6fdc2015-04-09 10:03:26 -0400421 if evGC == nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300422 return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts)
423 }
Austin Clementseec6fdc2015-04-09 10:03:26 -0400424 evGC.Link = ev
425 evGC = nil
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300426 case EvGCScanStart:
427 if p.evScan != nil {
428 return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
429 }
430 p.evScan = ev
431 case EvGCScanDone:
432 if p.evScan == nil {
433 return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.Off, ev.Ts)
434 }
435 p.evScan.Link = ev
436 p.evScan = nil
437 case EvGCSweepStart:
438 if p.evSweep != nil {
439 return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
440 }
441 p.evSweep = ev
442 case EvGCSweepDone:
443 if p.evSweep == nil {
444 return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts)
445 }
446 p.evSweep.Link = ev
447 p.evSweep = nil
448 case EvGoWaiting:
449 g1 := gs[ev.Args[0]]
450 if g1.state != gRunnable {
451 return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
452 }
453 g1.state = gWaiting
454 gs[ev.Args[0]] = g1
455 case EvGoInSyscall:
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300456 g1 := gs[ev.Args[0]]
457 if g1.state != gRunnable {
458 return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
459 }
460 g1.state = gWaiting
461 gs[ev.Args[0]] = g1
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300462 case EvGoCreate:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700463 if err := checkRunning(p, g, ev, true); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300464 return err
465 }
466 if _, ok := gs[ev.Args[0]]; ok {
467 return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
468 }
Dmitry Vyukov7b0c73a2015-03-10 19:40:09 +0300469 gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev}
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300470 case EvGoStart:
471 if g.state != gRunnable {
472 return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
473 }
474 if p.g != 0 {
475 return fmt.Errorf("p %v is already running g %v while start g %v (offset %v, time %v)", ev.P, p.g, ev.G, ev.Off, ev.Ts)
476 }
477 g.state = gRunning
478 g.evStart = ev
479 p.g = ev.G
Dmitry Vyukov7b0c73a2015-03-10 19:40:09 +0300480 if g.evCreate != nil {
Ainar Garipov7f9f70e2015-06-11 16:49:38 +0300481 // +1 because symbolizer expects return pc.
Didier Spezia4f334362015-08-23 13:18:14 +0000482 ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}}
Dmitry Vyukov7b0c73a2015-03-10 19:40:09 +0300483 g.evCreate = nil
484 }
485
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300486 if g.ev != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300487 g.ev.Link = ev
488 g.ev = nil
489 }
490 case EvGoEnd, EvGoStop:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700491 if err := checkRunning(p, g, ev, false); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300492 return err
493 }
494 g.evStart.Link = ev
495 g.evStart = nil
496 g.state = gDead
497 p.g = 0
498 case EvGoSched, EvGoPreempt:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700499 if err := checkRunning(p, g, ev, false); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300500 return err
501 }
502 g.state = gRunnable
503 g.evStart.Link = ev
504 g.evStart = nil
505 p.g = 0
506 g.ev = ev
507 case EvGoUnblock:
508 if g.state != gRunning {
509 return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
510 }
511 if ev.P != TimerP && p.g != ev.G {
512 return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts)
513 }
514 g1 := gs[ev.Args[0]]
515 if g1.state != gWaiting {
516 return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
517 }
518 if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP {
519 ev.P = NetpollP
520 }
521 if g1.ev != nil {
522 g1.ev.Link = ev
523 }
524 g1.state = gRunnable
525 g1.ev = ev
526 gs[ev.Args[0]] = g1
527 case EvGoSysCall:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700528 if err := checkRunning(p, g, ev, false); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300529 return err
530 }
531 g.ev = ev
532 case EvGoSysBlock:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700533 if err := checkRunning(p, g, ev, false); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300534 return err
535 }
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300536 g.state = gWaiting
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300537 g.evStart.Link = ev
538 g.evStart = nil
539 p.g = 0
540 case EvGoSysExit:
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300541 if g.state != gWaiting {
542 return fmt.Errorf("g %v is not waiting during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300543 }
544 if g.ev != nil && g.ev.Type == EvGoSysCall {
545 g.ev.Link = ev
546 }
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300547 g.state = gRunnable
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300548 g.ev = ev
549 case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
550 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet:
Dmitry Vyukove1ee3142015-07-17 17:53:48 -0700551 if err := checkRunning(p, g, ev, false); err != nil {
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300552 return err
553 }
554 g.state = gWaiting
555 g.ev = ev
556 g.evStart.Link = ev
557 g.evStart = nil
558 p.g = 0
559 }
560
561 gs[ev.G] = g
562 ps[ev.P] = p
563 }
564
565 // TODO(dvyukov): restore stacks for EvGoStart events.
566 // TODO(dvyukov): test that all EvGoStart events has non-nil Link.
567
Russ Cox80c98fa2015-07-23 14:01:03 -0400568 // Last, after all the other consistency checks,
569 // make sure time stamps respect sequence numbers.
570 // The tests will skip (not fail) the test case if they see this error,
571 // so check everything else that could possibly be wrong first.
572 lastTs := int64(0)
573 for _, ev := range events {
574 if ev.Ts < lastTs {
575 return ErrTimeOrder
576 }
577 lastTs = ev.Ts
578 }
579
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300580 return nil
581}
582
583// symbolizeTrace attaches func/file/line info to stack traces.
584func Symbolize(events []*Event, bin string) error {
585 // First, collect and dedup all pcs.
586 pcs := make(map[uint64]*Frame)
587 for _, ev := range events {
588 for _, f := range ev.Stk {
589 pcs[f.PC] = nil
590 }
591 }
592
593 // Start addr2line.
594 cmd := exec.Command("go", "tool", "addr2line", bin)
595 in, err := cmd.StdinPipe()
596 if err != nil {
597 return fmt.Errorf("failed to pipe addr2line stdin: %v", err)
598 }
599 cmd.Stderr = os.Stderr
600 out, err := cmd.StdoutPipe()
601 if err != nil {
602 return fmt.Errorf("failed to pipe addr2line stdout: %v", err)
603 }
604 err = cmd.Start()
605 if err != nil {
606 return fmt.Errorf("failed to start addr2line: %v", err)
607 }
608 outb := bufio.NewReader(out)
609
610 // Write all pcs to addr2line.
611 // Need to copy pcs to an array, because map iteration order is non-deterministic.
612 var pcArray []uint64
613 for pc := range pcs {
614 pcArray = append(pcArray, pc)
615 _, err := fmt.Fprintf(in, "0x%x\n", pc-1)
616 if err != nil {
617 return fmt.Errorf("failed to write to addr2line: %v", err)
618 }
619 }
620 in.Close()
621
622 // Read in answers.
623 for _, pc := range pcArray {
624 fn, err := outb.ReadString('\n')
625 if err != nil {
626 return fmt.Errorf("failed to read from addr2line: %v", err)
627 }
628 file, err := outb.ReadString('\n')
629 if err != nil {
630 return fmt.Errorf("failed to read from addr2line: %v", err)
631 }
632 f := &Frame{PC: pc}
633 f.Fn = fn[:len(fn)-1]
634 f.File = file[:len(file)-1]
635 if colon := strings.LastIndex(f.File, ":"); colon != -1 {
636 ln, err := strconv.Atoi(f.File[colon+1:])
637 if err == nil {
638 f.File = f.File[:colon]
639 f.Line = ln
640 }
641 }
642 pcs[pc] = f
643 }
644 cmd.Wait()
645
646 // Replace frames in events array.
647 for _, ev := range events {
648 for i, f := range ev.Stk {
649 ev.Stk[i] = pcs[f.PC]
650 }
651 }
652
653 return nil
654}
655
656// readVal reads unsigned base-128 value from r.
657func readVal(r io.Reader, off0 int) (v uint64, off int, err error) {
658 off = off0
659 for i := 0; i < 10; i++ {
660 var buf [1]byte
661 var n int
662 n, err = r.Read(buf[:])
663 if err != nil || n != 1 {
Russ Cox80c98fa2015-07-23 14:01:03 -0400664 return 0, 0, fmt.Errorf("failed to read trace at offset %d: read %v, error %v", off0, n, err)
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300665 }
666 off++
667 v |= uint64(buf[0]&0x7f) << (uint(i) * 7)
668 if buf[0]&0x80 == 0 {
669 return
670 }
671 }
672 return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0)
673}
674
675type eventList []*Event
676
677func (l eventList) Len() int {
678 return len(l)
679}
680
681func (l eventList) Less(i, j int) bool {
Russ Cox80c98fa2015-07-23 14:01:03 -0400682 return l[i].Seq < l[j].Seq
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300683}
684
685func (l eventList) Swap(i, j int) {
686 l[i], l[j] = l[j], l[i]
687}
688
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300689// Print dumps events to stdout. For debugging.
690func Print(events []*Event) {
691 for _, ev := range events {
692 desc := EventDescriptions[ev.Type]
693 fmt.Printf("%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off)
694 for i, a := range desc.Args {
695 fmt.Printf(" %v=%v", a, ev.Args[i])
696 }
697 fmt.Printf("\n")
698 }
699}
700
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300701// Event types in the trace.
702// Verbatim copy from src/runtime/trace.go.
703const (
704 EvNone = 0 // unused
705 EvBatch = 1 // start of per-P batch of events [pid, timestamp]
706 EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)]
707 EvStack = 3 // stack [stack id, number of PCs, array of PCs]
708 EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id]
Dmitry Vyukov9d332a82015-03-10 20:38:32 +0300709 EvProcStart = 5 // start of P [timestamp, thread id]
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300710 EvProcStop = 6 // stop of P [timestamp]
711 EvGCStart = 7 // GC start [timestamp, stack id]
712 EvGCDone = 8 // GC done [timestamp]
713 EvGCScanStart = 9 // GC scan start [timestamp]
714 EvGCScanDone = 10 // GC scan done [timestamp]
715 EvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
716 EvGCSweepDone = 12 // GC sweep done [timestamp]
717 EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id]
718 EvGoStart = 14 // goroutine starts running [timestamp, goroutine id]
719 EvGoEnd = 15 // goroutine ends [timestamp]
720 EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack]
721 EvGoSched = 17 // goroutine calls Gosched [timestamp, stack]
722 EvGoPreempt = 18 // goroutine is preempted [timestamp, stack]
723 EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack]
724 EvGoBlock = 20 // goroutine blocks [timestamp, stack]
725 EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack]
726 EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack]
727 EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack]
728 EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack]
729 EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack]
730 EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack]
731 EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack]
732 EvGoSysCall = 28 // syscall enter [timestamp, stack]
Dmitry Vyukov089d3632015-04-10 18:32:40 +0300733 EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, real timestamp]
Dmitry Vyukov919fd242015-02-21 21:01:40 +0300734 EvGoSysBlock = 30 // syscall blocks [timestamp]
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300735 EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id]
736 EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
737 EvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc]
738 EvNextGC = 34 // memstats.next_gc change [timestamp, next_gc]
739 EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id]
Ainar Garipov7f9f70e2015-06-11 16:49:38 +0300740 EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp]
Dmitry Vyukov4396ea92015-03-11 18:29:12 +0300741 EvCount = 37
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300742)
743
744var EventDescriptions = [EvCount]struct {
745 Name string
746 Stack bool
747 Args []string
748}{
749 EvNone: {"None", false, []string{}},
Russ Cox80c98fa2015-07-23 14:01:03 -0400750 EvBatch: {"Batch", false, []string{"p", "seq", "ticks"}},
751 EvFrequency: {"Frequency", false, []string{"freq", "unused"}},
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300752 EvStack: {"Stack", false, []string{"id", "siz"}},
753 EvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}},
Dmitry Vyukov9d332a82015-03-10 20:38:32 +0300754 EvProcStart: {"ProcStart", false, []string{"thread"}},
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300755 EvProcStop: {"ProcStop", false, []string{}},
756 EvGCStart: {"GCStart", true, []string{}},
757 EvGCDone: {"GCDone", false, []string{}},
758 EvGCScanStart: {"GCScanStart", false, []string{}},
759 EvGCScanDone: {"GCScanDone", false, []string{}},
760 EvGCSweepStart: {"GCSweepStart", true, []string{}},
761 EvGCSweepDone: {"GCSweepDone", false, []string{}},
762 EvGoCreate: {"GoCreate", true, []string{"g", "pc"}},
763 EvGoStart: {"GoStart", false, []string{"g"}},
764 EvGoEnd: {"GoEnd", false, []string{}},
765 EvGoStop: {"GoStop", true, []string{}},
766 EvGoSched: {"GoSched", true, []string{}},
767 EvGoPreempt: {"GoPreempt", true, []string{}},
768 EvGoSleep: {"GoSleep", true, []string{}},
769 EvGoBlock: {"GoBlock", true, []string{}},
770 EvGoUnblock: {"GoUnblock", true, []string{"g"}},
771 EvGoBlockSend: {"GoBlockSend", true, []string{}},
772 EvGoBlockRecv: {"GoBlockRecv", true, []string{}},
773 EvGoBlockSelect: {"GoBlockSelect", true, []string{}},
774 EvGoBlockSync: {"GoBlockSync", true, []string{}},
775 EvGoBlockCond: {"GoBlockCond", true, []string{}},
776 EvGoBlockNet: {"GoBlockNet", true, []string{}},
777 EvGoSysCall: {"GoSysCall", true, []string{}},
Russ Cox80c98fa2015-07-23 14:01:03 -0400778 EvGoSysExit: {"GoSysExit", false, []string{"g", "seq", "ts"}},
Dmitry Vyukov919fd242015-02-21 21:01:40 +0300779 EvGoSysBlock: {"GoSysBlock", false, []string{}},
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300780 EvGoWaiting: {"GoWaiting", false, []string{"g"}},
781 EvGoInSyscall: {"GoInSyscall", false, []string{"g"}},
782 EvHeapAlloc: {"HeapAlloc", false, []string{"mem"}},
783 EvNextGC: {"NextGC", false, []string{"mem"}},
Russ Cox80c98fa2015-07-23 14:01:03 -0400784 EvTimerGoroutine: {"TimerGoroutine", false, []string{"g", "unused"}},
Dmitry Vyukov4396ea92015-03-11 18:29:12 +0300785 EvFutileWakeup: {"FutileWakeup", false, []string{}},
Dmitry Vyukovedadffa2015-01-30 13:31:43 +0300786}