From 2059ffbc8db0dff3fd9780a817f76e95559193ba Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Tue, 23 Dec 2014 22:22:56 +0300 Subject: [PATCH] runtime/pprof: add tests for tracer Change-Id: I832a433f0f2fc10b0a2fea0bfb003a988fc2c81b Reviewed-on: https://go-review.googlesource.com/2039 Reviewed-by: Russ Cox --- src/runtime/pprof/trace_parser_test.go | 651 +++++++++++++++++++++++++ src/runtime/pprof/trace_test.go | 223 +++++++++ 2 files changed, 874 insertions(+) create mode 100644 src/runtime/pprof/trace_parser_test.go create mode 100644 src/runtime/pprof/trace_test.go diff --git a/src/runtime/pprof/trace_parser_test.go b/src/runtime/pprof/trace_parser_test.go new file mode 100644 index 0000000000..220cfd9f8b --- /dev/null +++ b/src/runtime/pprof/trace_parser_test.go @@ -0,0 +1,651 @@ +// Copyright 2014 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 pprof_test + +import ( + "bufio" + "bytes" + "fmt" + "io" + "os/exec" + "sort" + "strconv" + "strings" +) + +// Event describes one event in the trace. +type Event struct { + off int // offset in input file (for debugging and error reporting) + typ byte // one of traceEv* + ts int64 // timestamp in nanoseconds + p int // P on which the event happened (can be one of timerP, netpollP, syscallP) + g uint64 // G on which the event happened + stkID uint64 // unique stack ID + stk []*Frame // stack trace (can be empty) + args [2]uint64 // event-type-specific arguments + // linked event (can be nil), depends on event type: + // for GCStart: the GCStop + // for GCScanStart: the GCScanDone + // for GCSweepStart: the GCSweepDone + // for GoCreate: first GoStart of the created goroutine + // for GoStart: the associated GoEnd, GoBlock or other blocking event + // for GoSched/GoPreempt: the next GoStart + // for GoBlock and other blocking events: the unblock event + // for GoUnblock: the associated GoStart + // for blocking GoSysCall: the associated GoSysExit + // for GoSysExit: the next GoStart + link *Event +} + +// Frame is a frame in stack traces. +type Frame struct { + pc uint64 + fn string + file string + line int +} + +const ( + // Special P identifiers: + timerP = 1000000 + iota // depicts timer unblocks + netpollP // depicts network unblocks + syscallP // depicts returns from syscalls +) + +// parseTrace parses, post-processes and verifies the trace. +func parseTrace(r io.Reader) ([]*Event, error) { + rawEvents, err := readTrace(r) + if err != nil { + return nil, err + } + events, err := parseEvents(rawEvents) + if err != nil { + return nil, err + } + err = postProcessTrace(events) + if err != nil { + return nil, err + } + return events, nil +} + +// RawEvent is a helper type used during parsing. +type RawEvent struct { + off int + typ byte + args []uint64 +} + +// readTrace does wire-format parsing and verification. +// It does not care about specific event types and argument meaning. +func readTrace(r io.Reader) ([]RawEvent, error) { + // Read and validate trace header. + var buf [8]byte + off, err := r.Read(buf[:]) + if off != 8 || err != nil { + return nil, fmt.Errorf("failed to read header: read %v, err %v", off, err) + } + if bytes.Compare(buf[:], []byte("gotrace\x00")) != 0 { + return nil, fmt.Errorf("not a trace file") + } + + // Read events. + var events []RawEvent + for { + // Read event type and number of arguments (1 byte). + off0 := off + n, err := r.Read(buf[:1]) + if err == io.EOF { + break + } + if err != nil || n != 1 { + return nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err) + } + off += n + typ := buf[0] << 2 >> 2 + narg := buf[0]>>6 + 1 + ev := RawEvent{typ: typ, off: off0} + if narg <= 3 { + for i := 0; i < int(narg); i++ { + var v uint64 + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + ev.args = append(ev.args, v) + } + } else { + // If narg == 4, the first value is length of the event in bytes. + var v uint64 + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + evLen := v + off1 := off + for evLen > uint64(off-off1) { + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + ev.args = append(ev.args, v) + } + if evLen != uint64(off-off1) { + return nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) + } + } + events = append(events, ev) + } + return events, nil +} + +// Parse events transforms raw events into events. +// It does analyze and verify per-event-type arguments. +func parseEvents(rawEvents []RawEvent) (events []*Event, err error) { + var ticksPerSec, lastTs int64 + var lastG, timerGoid uint64 + var lastP int + lastGs := make(map[int]uint64) // last goroutine running on P + stacks := make(map[uint64][]*Frame) + for _, raw := range rawEvents { + if raw.typ == traceEvNone || raw.typ >= traceEvCount { + err = fmt.Errorf("unknown event type %v at offset 0x%x", raw.typ, raw.off) + return + } + desc := evDescriptions[raw.typ] + if desc.name == "" { + err = fmt.Errorf("missing description for event type %v", raw.typ) + return + } + if raw.typ != traceEvStack { + narg := len(desc.args) + if desc.stack { + narg++ + } + if raw.typ != traceEvBatch && raw.typ != traceEvFrequency && raw.typ != traceEvTimerGoroutine { + narg++ // timestamp + } + if len(raw.args) != narg { + err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v", + desc.name, raw.off, narg, len(raw.args)) + return + } + } + switch raw.typ { + case traceEvBatch: + lastGs[lastP] = lastG + lastP = int(raw.args[0]) + lastG = lastGs[lastP] + lastTs = int64(raw.args[1]) + case traceEvFrequency: + ticksPerSec = int64(raw.args[0]) + case traceEvTimerGoroutine: + timerGoid = raw.args[0] + case traceEvStack: + if len(raw.args) < 2 { + err = fmt.Errorf("traceEvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v", + raw.off, len(raw.args)) + return + } + size := raw.args[1] + if size > 1000 { + err = fmt.Errorf("traceEvStack has bad number of frames at offset 0x%x: %v", + raw.off, size) + return + } + id := raw.args[0] + if id != 0 && size > 0 { + stk := make([]*Frame, size) + for i := 0; i < int(size); i++ { + stk[i] = &Frame{pc: raw.args[i+2]} + } + stacks[id] = stk + } + default: + e := &Event{off: raw.off, typ: raw.typ, p: lastP, g: lastG} + e.ts = lastTs + int64(raw.args[0]) + lastTs = e.ts + for i := range desc.args { + e.args[i] = raw.args[i+1] + } + if desc.stack { + e.stkID = raw.args[len(desc.args)+1] + } + switch raw.typ { + case traceEvGoStart: + lastG = e.args[0] + e.g = lastG + case traceEvGCStart, traceEvGCDone, traceEvGCScanStart, traceEvGCScanDone: + e.g = 0 + case traceEvGoEnd, traceEvGoStop, traceEvGoSched, traceEvGoPreempt, + traceEvGoSleep, traceEvGoBlock, traceEvGoBlockSend, traceEvGoBlockRecv, + traceEvGoBlockSelect, traceEvGoBlockSync, traceEvGoBlockCond, traceEvGoBlockNet, + traceEvGoSysBlock: + lastG = 0 + } + events = append(events, e) + } + } + + // Attach stack traces. + for _, ev := range events { + if ev.stkID != 0 { + ev.stk = stacks[ev.stkID] + } + } + + // Sort by time and translate cpu ticks to real time. + sort.Sort(EventList(events)) + if ticksPerSec == 0 { + err = fmt.Errorf("no traceEvFrequency event") + return + } + minTs := events[0].ts + for _, ev := range events { + ev.ts = (ev.ts - minTs) * 1e9 / ticksPerSec + // Move timers and syscalls to separate fake Ps. + if timerGoid != 0 && ev.g == timerGoid && ev.typ == traceEvGoUnblock { + ev.p = timerP + } + if ev.typ == traceEvGoSysExit { + ev.p = syscallP + ev.g = ev.args[0] + } + } + + return +} + +// postProcessTrace does inter-event verification and information restoration. +// The resulting trace is guaranteed to be consistent +// (for example, a P does not run two Gs at the same time, or a G is indeed +// blocked before an unblock event). +func postProcessTrace(events []*Event) error { + const ( + gDead = iota + gRunnable + gRunning + gWaiting + ) + type gdesc struct { + state int + ev *Event + evStart *Event + } + type pdesc struct { + running bool + g uint64 + evGC *Event + evScan *Event + evSweep *Event + } + + gs := make(map[uint64]gdesc) + ps := make(map[int]pdesc) + gs[0] = gdesc{state: gRunning} + + checkRunning := func(p pdesc, g gdesc, ev *Event) error { + name := evDescriptions[ev.typ].name + if g.state != gRunning { + return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.g, name, ev.off, ev.ts) + } + if p.g != ev.g { + 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) + } + return nil + } + + for _, ev := range events { + g := gs[ev.g] + p := ps[ev.p] + + switch ev.typ { + case traceEvProcStart: + if p.running { + return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.p, ev.off, ev.ts) + } + p.running = true + case traceEvProcStop: + if !p.running { + return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.p, ev.off, ev.ts) + } + if p.g != 0 { + return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.p, p.g, ev.off, ev.ts) + } + p.running = false + case traceEvGCStart: + if p.evGC != nil { + return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.off, ev.ts) + } + p.evGC = ev + case traceEvGCDone: + if p.evGC == nil { + return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.off, ev.ts) + } + p.evGC.link = ev + p.evGC = nil + case traceEvGCScanStart: + if p.evScan != nil { + return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.off, ev.ts) + } + p.evScan = ev + case traceEvGCScanDone: + if p.evScan == nil { + return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.off, ev.ts) + } + p.evScan.link = ev + p.evScan = nil + case traceEvGCSweepStart: + if p.evSweep != nil { + return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.off, ev.ts) + } + p.evSweep = ev + case traceEvGCSweepDone: + if p.evSweep == nil { + return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.off, ev.ts) + } + p.evSweep.link = ev + p.evSweep = nil + case traceEvGoWaiting: + g1 := gs[ev.args[0]] + if g1.state != gRunnable { + return fmt.Errorf("g %v is not runnable before traceEvGoWaiting (offset %v, time %v)", ev.args[0], ev.off, ev.ts) + } + g1.state = gWaiting + gs[ev.args[0]] = g1 + case traceEvGoInSyscall: + // this case is intentionally left blank + case traceEvGoCreate: + if err := checkRunning(p, g, ev); err != nil { + return err + } + if _, ok := gs[ev.args[0]]; ok { + return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.args[0], ev.off, ev.ts) + } + gs[ev.args[0]] = gdesc{state: gRunnable, ev: ev} + case traceEvGoStart: + if g.state != gRunnable { + return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.g, ev.off, ev.ts) + } + if p.g != 0 { + 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) + } + g.state = gRunning + g.evStart = ev + p.g = ev.g + if g.ev != nil { + if g.ev.typ == traceEvGoCreate { + // +1 because symblizer expects return pc. + ev.stk = []*Frame{&Frame{pc: g.ev.args[1] + 1}} + } + g.ev.link = ev + g.ev = nil + } + case traceEvGoEnd, traceEvGoStop: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.evStart.link = ev + g.evStart = nil + g.state = gDead + p.g = 0 + case traceEvGoSched, traceEvGoPreempt: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gRunnable + g.evStart.link = ev + g.evStart = nil + p.g = 0 + g.ev = ev + case traceEvGoUnblock: + if g.state != gRunning { + return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.g, ev.off, ev.ts) + } + if ev.p != timerP && p.g != ev.g { + return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.p, ev.g, ev.off, ev.ts) + } + g1 := gs[ev.args[0]] + if g1.state != gWaiting { + return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.args[0], ev.off, ev.ts) + } + if g1.ev != nil && g1.ev.typ == traceEvGoBlockNet && ev.p != timerP { + ev.p = netpollP + } + if g1.ev != nil { + g1.ev.link = ev + } + g1.state = gRunnable + g1.ev = ev + gs[ev.args[0]] = g1 + case traceEvGoSysCall: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.ev = ev + case traceEvGoSysBlock: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gRunnable + g.evStart.link = ev + g.evStart = nil + p.g = 0 + case traceEvGoSysExit: + if g.state != gRunnable { + return fmt.Errorf("g %v is not runnable during syscall exit (offset %v, time %v)", ev.g, ev.off, ev.ts) + } + if g.ev != nil && g.ev.typ == traceEvGoSysCall { + g.ev.link = ev + } + g.ev = ev + case traceEvGoSleep, traceEvGoBlock, traceEvGoBlockSend, traceEvGoBlockRecv, + traceEvGoBlockSelect, traceEvGoBlockSync, traceEvGoBlockCond, traceEvGoBlockNet: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gWaiting + g.ev = ev + g.evStart.link = ev + g.evStart = nil + p.g = 0 + } + + gs[ev.g] = g + ps[ev.p] = p + } + + return nil +} + +// symbolizeTrace attaches func/file/line info to stack traces. +func symbolizeTrace(events []*Event, bin string) error { + // First, collect and dedup all pcs. + pcs := make(map[uint64]*Frame) + for _, ev := range events { + for _, f := range ev.stk { + pcs[f.pc] = nil + } + } + + // Start addr2line. + cmd := exec.Command("go", "tool", "addr2line", bin) + in, err := cmd.StdinPipe() + if err != nil { + return fmt.Errorf("failed to pipe addr2line stdin: %v", err) + } + out, err := cmd.StdoutPipe() + if err != nil { + return fmt.Errorf("failed to pipe addr2line stdout: %v", err) + } + err = cmd.Start() + if err != nil { + return fmt.Errorf("failed to start addr2line: %v", err) + } + outb := bufio.NewReader(out) + + // Write all pcs to addr2line. + // Need to copy pcs to an array, because map iteration order is non-deterministic. + var pcArray []uint64 + for pc := range pcs { + pcArray = append(pcArray, pc) + _, err := fmt.Fprintf(in, "0x%x\n", pc-1) + if err != nil { + return fmt.Errorf("failed to write to addr2line: %v", err) + } + } + in.Close() + + // Read in answers. + for _, pc := range pcArray { + fn, err := outb.ReadString('\n') + if err != nil { + return fmt.Errorf("failed to read from addr2line: %v", err) + } + file, err := outb.ReadString('\n') + if err != nil { + return fmt.Errorf("failed to read from addr2line: %v", err) + } + f := &Frame{pc: pc} + f.fn = fn[:len(fn)-1] + f.file = file[:len(file)-1] + if colon := strings.LastIndex(f.file, ":"); colon != -1 { + ln, err := strconv.Atoi(f.file[colon+1:]) + if err == nil { + f.file = f.file[:colon] + f.line = ln + } + } + pcs[pc] = f + } + cmd.Wait() + + // Replace frames in events array. + for _, ev := range events { + for i, f := range ev.stk { + ev.stk[i] = pcs[f.pc] + } + } + + return nil +} + +// readVal reads unsigned base-128 value from r. +func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { + off = off0 + for i := 0; i < 10; i++ { + var buf [1]byte + var n int + n, err = r.Read(buf[:]) + if err != nil || n != 1 { + return 0, 0, fmt.Errorf("failed to read trace at offset: read %v, error %v", off0, n, err) + } + off++ + v |= uint64(buf[0]&0x7f) << (uint(i) * 7) + if buf[0]&0x80 == 0 { + return + } + } + return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0) +} + +type EventList []*Event + +func (l EventList) Len() int { + return len(l) +} + +func (l EventList) Less(i, j int) bool { + return l[i].ts < l[j].ts +} + +func (l EventList) Swap(i, j int) { + l[i], l[j] = l[j], l[i] +} + +// Event types in the trace. +// Verbatim copy from src/runtime/trace.go. +const ( + traceEvNone = 0 // unused + traceEvBatch = 1 // start of per-P batch of events [pid, timestamp] + traceEvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] + traceEvStack = 3 // stack [stack id, number of PCs, array of PCs] + traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] + traceEvProcStart = 5 // start of P [timestamp] + traceEvProcStop = 6 // stop of P [timestamp] + traceEvGCStart = 7 // GC start [timestamp, stack id] + traceEvGCDone = 8 // GC done [timestamp] + traceEvGCScanStart = 9 // GC scan start [timestamp] + traceEvGCScanDone = 10 // GC scan done [timestamp] + traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id] + traceEvGCSweepDone = 12 // GC sweep done [timestamp] + traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id] + traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id] + traceEvGoEnd = 15 // goroutine ends [timestamp] + traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] + traceEvGoSched = 17 // goroutine calls Gosched [timestamp, stack] + traceEvGoPreempt = 18 // goroutine is preempted [timestamp, stack] + traceEvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] + traceEvGoBlock = 20 // goroutine blocks [timestamp, stack] + traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack] + traceEvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] + traceEvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] + traceEvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] + traceEvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] + traceEvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] + traceEvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] + traceEvGoSysCall = 28 // syscall enter [timestamp, stack] + traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id] + traceEvGoSysBlock = 30 // syscall blocks [timestamp, stack] + traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id] + traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id] + traceEvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc] + traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] + traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] + traceEvCount = 36 +) + +var evDescriptions = [traceEvCount]struct { + name string + stack bool + args []string +}{ + traceEvNone: {"None", false, []string{}}, + traceEvBatch: {"Batch", false, []string{"p", "ticks"}}, + traceEvFrequency: {"Frequency", false, []string{"freq"}}, + traceEvStack: {"Stack", false, []string{"id", "siz"}}, + traceEvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}}, + traceEvProcStart: {"ProcStart", false, []string{}}, + traceEvProcStop: {"ProcStop", false, []string{}}, + traceEvGCStart: {"GCStart", true, []string{}}, + traceEvGCDone: {"GCDone", false, []string{}}, + traceEvGCScanStart: {"GCScanStart", false, []string{}}, + traceEvGCScanDone: {"GCScanDone", false, []string{}}, + traceEvGCSweepStart: {"GCSweepStart", true, []string{}}, + traceEvGCSweepDone: {"GCSweepDone", false, []string{}}, + traceEvGoCreate: {"GoCreate", true, []string{"g", "pc"}}, + traceEvGoStart: {"GoStart", false, []string{"g"}}, + traceEvGoEnd: {"GoEnd", false, []string{}}, + traceEvGoStop: {"GoStop", true, []string{}}, + traceEvGoSched: {"GoSched", true, []string{}}, + traceEvGoPreempt: {"GoPreempt", true, []string{}}, + traceEvGoSleep: {"GoSleep", true, []string{}}, + traceEvGoBlock: {"GoBlock", true, []string{}}, + traceEvGoUnblock: {"GoUnblock", true, []string{"g"}}, + traceEvGoBlockSend: {"GoBlockSend", true, []string{}}, + traceEvGoBlockRecv: {"GoBlockRecv", true, []string{}}, + traceEvGoBlockSelect: {"GoBlockSelect", true, []string{}}, + traceEvGoBlockSync: {"GoBlockSync", true, []string{}}, + traceEvGoBlockCond: {"GoBlockCond", true, []string{}}, + traceEvGoBlockNet: {"GoBlockNet", true, []string{}}, + traceEvGoSysCall: {"GoSysCall", true, []string{}}, + traceEvGoSysExit: {"GoSysExit", false, []string{"g"}}, + traceEvGoSysBlock: {"GoSysBlock", true, []string{}}, + traceEvGoWaiting: {"GoWaiting", false, []string{"g"}}, + traceEvGoInSyscall: {"GoInSyscall", false, []string{"g"}}, + traceEvHeapAlloc: {"HeapAlloc", false, []string{"mem"}}, + traceEvNextGC: {"NextGC", false, []string{"mem"}}, + traceEvTimerGoroutine: {"TimerGoroutine", false, []string{"g"}}, +} diff --git a/src/runtime/pprof/trace_test.go b/src/runtime/pprof/trace_test.go new file mode 100644 index 0000000000..3a2cd15dfa --- /dev/null +++ b/src/runtime/pprof/trace_test.go @@ -0,0 +1,223 @@ +// Copyright 2014 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 pprof_test + +import ( + "bytes" + "net" + "os" + "runtime" + . "runtime/pprof" + "strings" + "sync" + "testing" + "time" +) + +func TestTraceStartStop(t *testing.T) { + buf := new(bytes.Buffer) + if err := StartTrace(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + StopTrace() + size := buf.Len() + if size == 0 { + t.Fatalf("trace is empty") + } + time.Sleep(100 * time.Millisecond) + if size != buf.Len() { + t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len()) + } +} + +func TestTraceDoubleStart(t *testing.T) { + StopTrace() + buf := new(bytes.Buffer) + if err := StartTrace(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + if err := StartTrace(buf); err == nil { + t.Fatalf("succeed to start tracing second time") + } + StopTrace() + StopTrace() +} + +func TestTrace(t *testing.T) { + buf := new(bytes.Buffer) + if err := StartTrace(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + StopTrace() + _, err := parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } +} + +func TestTraceStress(t *testing.T) { + var wg sync.WaitGroup + done := make(chan bool) + + // Create a goroutine blocked before tracing. + wg.Add(1) + go func() { + <-done + wg.Done() + }() + + // Create a goroutine blocked in syscall before tracing. + rp, wp, err := os.Pipe() + if err != nil { + t.Fatalf("failed to create pipe: %v", err) + } + defer func() { + rp.Close() + wp.Close() + }() + wg.Add(1) + go func() { + var tmp [1]byte + rp.Read(tmp[:]) + <-done + wg.Done() + }() + time.Sleep(time.Millisecond) + + buf := new(bytes.Buffer) + if err := StartTrace(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + + procs := runtime.GOMAXPROCS(10) + + go func() { + runtime.LockOSThread() + for { + select { + case <-done: + return + default: + runtime.Gosched() + } + } + }() + + runtime.GC() + // Trigger GC from malloc. + for i := 0; i < 1e3; i++ { + _ = make([]byte, 1<<20) + } + + // Create a bunch of busy goroutines to load all Ps. + for p := 0; p < 10; p++ { + wg.Add(1) + go func() { + // Do something useful. + tmp := make([]byte, 1<<16) + for i := range tmp { + tmp[i]++ + } + _ = tmp + <-done + wg.Done() + }() + } + + // Block in syscall. + wg.Add(1) + go func() { + var tmp [1]byte + rp.Read(tmp[:]) + <-done + wg.Done() + }() + + // Test timers. + timerDone := make(chan bool) + go func() { + time.Sleep(time.Millisecond) + timerDone <- true + }() + <-timerDone + + // A bit of network. + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen failed: %v", err) + } + defer ln.Close() + go func() { + c, err := ln.Accept() + if err != nil { + return + } + time.Sleep(time.Millisecond) + var buf [1]byte + c.Write(buf[:]) + c.Close() + }() + c, err := net.Dial("tcp", ln.Addr().String()) + if err != nil { + t.Fatalf("dial failed: %v", err) + } + var tmp [1]byte + c.Read(tmp[:]) + c.Close() + + go func() { + runtime.Gosched() + select {} + }() + + // Unblock helper goroutines and wait them to finish. + wp.Write(tmp[:]) + wp.Write(tmp[:]) + close(done) + wg.Wait() + + runtime.GOMAXPROCS(procs) + + StopTrace() + _, err = parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } +} + +func TestTraceSymbolize(t *testing.T) { + buf := new(bytes.Buffer) + if err := StartTrace(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + runtime.GC() + StopTrace() + events, err := parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + err = symbolizeTrace(events, os.Args[0]) + if err != nil { + t.Fatalf("failed to symbolize trace: %v", err) + } + found := false +eventLoop: + for _, ev := range events { + if ev.typ != traceEvGCStart { + continue + } + for _, f := range ev.stk { + if strings.HasSuffix(f.file, "trace_test.go") && + strings.HasSuffix(f.fn, "pprof_test.TestTraceSymbolize") && + f.line == 195 { + found = true + break eventLoop + } + } + } + if !found { + t.Fatalf("the trace does not contain GC event") + } +} -- 2.48.1