diff options
Diffstat (limited to 'src/internal/trace/traceviewer/emitter.go')
-rw-r--r-- | src/internal/trace/traceviewer/emitter.go | 813 |
1 files changed, 813 insertions, 0 deletions
diff --git a/src/internal/trace/traceviewer/emitter.go b/src/internal/trace/traceviewer/emitter.go new file mode 100644 index 0000000..c91c743 --- /dev/null +++ b/src/internal/trace/traceviewer/emitter.go @@ -0,0 +1,813 @@ +// 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 traceviewer + +import ( + "encoding/json" + "fmt" + "internal/trace" + "internal/trace/traceviewer/format" + "io" + "strconv" + "time" +) + +type TraceConsumer struct { + ConsumeTimeUnit func(unit string) + ConsumeViewerEvent func(v *format.Event, required bool) + ConsumeViewerFrame func(key string, f format.Frame) + Flush func() +} + +// ViewerDataTraceConsumer returns a TraceConsumer that writes to w. The +// startIdx and endIdx are used for splitting large traces. They refer to +// indexes in the traceEvents output array, not the events in the trace input. +func ViewerDataTraceConsumer(w io.Writer, startIdx, endIdx int64) TraceConsumer { + allFrames := make(map[string]format.Frame) + requiredFrames := make(map[string]format.Frame) + enc := json.NewEncoder(w) + written := 0 + index := int64(-1) + + io.WriteString(w, "{") + return TraceConsumer{ + ConsumeTimeUnit: func(unit string) { + io.WriteString(w, `"displayTimeUnit":`) + enc.Encode(unit) + io.WriteString(w, ",") + }, + ConsumeViewerEvent: func(v *format.Event, required bool) { + index++ + if !required && (index < startIdx || index > endIdx) { + // not in the range. Skip! + return + } + WalkStackFrames(allFrames, v.Stack, func(id int) { + s := strconv.Itoa(id) + requiredFrames[s] = allFrames[s] + }) + WalkStackFrames(allFrames, v.EndStack, func(id int) { + s := strconv.Itoa(id) + requiredFrames[s] = allFrames[s] + }) + if written == 0 { + io.WriteString(w, `"traceEvents": [`) + } + if written > 0 { + io.WriteString(w, ",") + } + enc.Encode(v) + // TODO(mknyszek): get rid of the extra \n inserted by enc.Encode. + // Same should be applied to splittingTraceConsumer. + written++ + }, + ConsumeViewerFrame: func(k string, v format.Frame) { + allFrames[k] = v + }, + Flush: func() { + io.WriteString(w, `], "stackFrames":`) + enc.Encode(requiredFrames) + io.WriteString(w, `}`) + }, + } +} + +func SplittingTraceConsumer(max int) (*splitter, TraceConsumer) { + type eventSz struct { + Time float64 + Sz int + Frames []int + } + + var ( + // data.Frames contains only the frames for required events. + data = format.Data{Frames: make(map[string]format.Frame)} + + allFrames = make(map[string]format.Frame) + + sizes []eventSz + cw countingWriter + ) + + s := new(splitter) + + return s, TraceConsumer{ + ConsumeTimeUnit: func(unit string) { + data.TimeUnit = unit + }, + ConsumeViewerEvent: func(v *format.Event, required bool) { + if required { + // Store required events inside data so flush + // can include them in the required part of the + // trace. + data.Events = append(data.Events, v) + WalkStackFrames(allFrames, v.Stack, func(id int) { + s := strconv.Itoa(id) + data.Frames[s] = allFrames[s] + }) + WalkStackFrames(allFrames, v.EndStack, func(id int) { + s := strconv.Itoa(id) + data.Frames[s] = allFrames[s] + }) + return + } + enc := json.NewEncoder(&cw) + enc.Encode(v) + size := eventSz{Time: v.Time, Sz: cw.size + 1} // +1 for ",". + // Add referenced stack frames. Their size is computed + // in flush, where we can dedup across events. + WalkStackFrames(allFrames, v.Stack, func(id int) { + size.Frames = append(size.Frames, id) + }) + WalkStackFrames(allFrames, v.EndStack, func(id int) { + size.Frames = append(size.Frames, id) // This may add duplicates. We'll dedup later. + }) + sizes = append(sizes, size) + cw.size = 0 + }, + ConsumeViewerFrame: func(k string, v format.Frame) { + allFrames[k] = v + }, + Flush: func() { + // Calculate size of the mandatory part of the trace. + // This includes thread names and stack frames for + // required events. + cw.size = 0 + enc := json.NewEncoder(&cw) + enc.Encode(data) + requiredSize := cw.size + + // Then calculate size of each individual event and + // their stack frames, grouping them into ranges. We + // only include stack frames relevant to the events in + // the range to reduce overhead. + + var ( + start = 0 + + eventsSize = 0 + + frames = make(map[string]format.Frame) + framesSize = 0 + ) + for i, ev := range sizes { + eventsSize += ev.Sz + + // Add required stack frames. Note that they + // may already be in the map. + for _, id := range ev.Frames { + s := strconv.Itoa(id) + _, ok := frames[s] + if ok { + continue + } + f := allFrames[s] + frames[s] = f + framesSize += stackFrameEncodedSize(uint(id), f) + } + + total := requiredSize + framesSize + eventsSize + if total < max { + continue + } + + // Reached max size, commit this range and + // start a new range. + startTime := time.Duration(sizes[start].Time * 1000) + endTime := time.Duration(ev.Time * 1000) + s.Ranges = append(s.Ranges, Range{ + Name: fmt.Sprintf("%v-%v", startTime, endTime), + Start: start, + End: i + 1, + StartTime: int64(startTime), + EndTime: int64(endTime), + }) + start = i + 1 + frames = make(map[string]format.Frame) + framesSize = 0 + eventsSize = 0 + } + if len(s.Ranges) <= 1 { + s.Ranges = nil + return + } + + if end := len(sizes) - 1; start < end { + s.Ranges = append(s.Ranges, Range{ + Name: fmt.Sprintf("%v-%v", time.Duration(sizes[start].Time*1000), time.Duration(sizes[end].Time*1000)), + Start: start, + End: end, + StartTime: int64(sizes[start].Time * 1000), + EndTime: int64(sizes[end].Time * 1000), + }) + } + }, + } +} + +type splitter struct { + Ranges []Range +} + +type countingWriter struct { + size int +} + +func (cw *countingWriter) Write(data []byte) (int, error) { + cw.size += len(data) + return len(data), nil +} + +func stackFrameEncodedSize(id uint, f format.Frame) int { + // We want to know the marginal size of traceviewer.Data.Frames for + // each event. Running full JSON encoding of the map for each event is + // far too slow. + // + // Since the format is fixed, we can easily compute the size without + // encoding. + // + // A single entry looks like one of the following: + // + // "1":{"name":"main.main:30"}, + // "10":{"name":"pkg.NewSession:173","parent":9}, + // + // The parent is omitted if 0. The trailing comma is omitted from the + // last entry, but we don't need that much precision. + const ( + baseSize = len(`"`) + len(`":{"name":"`) + len(`"},`) + + // Don't count the trailing quote on the name, as that is + // counted in baseSize. + parentBaseSize = len(`,"parent":`) + ) + + size := baseSize + + size += len(f.Name) + + // Bytes for id (always positive). + for id > 0 { + size += 1 + id /= 10 + } + + if f.Parent > 0 { + size += parentBaseSize + // Bytes for parent (always positive). + for f.Parent > 0 { + size += 1 + f.Parent /= 10 + } + } + + return size +} + +// WalkStackFrames calls fn for id and all of its parent frames from allFrames. +func WalkStackFrames(allFrames map[string]format.Frame, id int, fn func(id int)) { + for id != 0 { + f, ok := allFrames[strconv.Itoa(id)] + if !ok { + break + } + fn(id) + id = f.Parent + } +} + +type Mode int + +const ( + ModeGoroutineOriented Mode = 1 << iota + ModeTaskOriented + ModeThreadOriented // Mutually exclusive with ModeGoroutineOriented. +) + +// NewEmitter returns a new Emitter that writes to c. The rangeStart and +// rangeEnd args are used for splitting large traces. +func NewEmitter(c TraceConsumer, rangeStart, rangeEnd time.Duration) *Emitter { + c.ConsumeTimeUnit("ns") + + return &Emitter{ + c: c, + rangeStart: rangeStart, + rangeEnd: rangeEnd, + frameTree: frameNode{children: make(map[uint64]frameNode)}, + resources: make(map[uint64]string), + tasks: make(map[uint64]task), + } +} + +type Emitter struct { + c TraceConsumer + rangeStart time.Duration + rangeEnd time.Duration + + heapStats, prevHeapStats heapStats + gstates, prevGstates [gStateCount]int64 + threadStats, prevThreadStats [threadStateCount]int64 + gomaxprocs uint64 + frameTree frameNode + frameSeq int + arrowSeq uint64 + filter func(uint64) bool + resourceType string + resources map[uint64]string + focusResource uint64 + tasks map[uint64]task + asyncSliceSeq uint64 +} + +type task struct { + name string + sortIndex int +} + +func (e *Emitter) Gomaxprocs(v uint64) { + if v > e.gomaxprocs { + e.gomaxprocs = v + } +} + +func (e *Emitter) Resource(id uint64, name string) { + if e.filter != nil && !e.filter(id) { + return + } + e.resources[id] = name +} + +func (e *Emitter) SetResourceType(name string) { + e.resourceType = name +} + +func (e *Emitter) SetResourceFilter(filter func(uint64) bool) { + e.filter = filter +} + +func (e *Emitter) Task(id uint64, name string, sortIndex int) { + e.tasks[id] = task{name, sortIndex} +} + +func (e *Emitter) Slice(s SliceEvent) { + if e.filter != nil && !e.filter(s.Resource) { + return + } + e.slice(s, format.ProcsSection, "") +} + +func (e *Emitter) TaskSlice(s SliceEvent) { + e.slice(s, format.TasksSection, pickTaskColor(s.Resource)) +} + +func (e *Emitter) slice(s SliceEvent, sectionID uint64, cname string) { + if !e.tsWithinRange(s.Ts) && !e.tsWithinRange(s.Ts+s.Dur) { + return + } + e.OptionalEvent(&format.Event{ + Name: s.Name, + Phase: "X", + Time: viewerTime(s.Ts), + Dur: viewerTime(s.Dur), + PID: sectionID, + TID: s.Resource, + Stack: s.Stack, + EndStack: s.EndStack, + Arg: s.Arg, + Cname: cname, + }) +} + +type SliceEvent struct { + Name string + Ts time.Duration + Dur time.Duration + Resource uint64 + Stack int + EndStack int + Arg any +} + +func (e *Emitter) AsyncSlice(s AsyncSliceEvent) { + if !e.tsWithinRange(s.Ts) && !e.tsWithinRange(s.Ts+s.Dur) { + return + } + if e.filter != nil && !e.filter(s.Resource) { + return + } + cname := "" + if s.TaskColorIndex != 0 { + cname = pickTaskColor(s.TaskColorIndex) + } + e.asyncSliceSeq++ + e.OptionalEvent(&format.Event{ + Category: s.Category, + Name: s.Name, + Phase: "b", + Time: viewerTime(s.Ts), + TID: s.Resource, + ID: e.asyncSliceSeq, + Scope: s.Scope, + Stack: s.Stack, + Cname: cname, + }) + e.OptionalEvent(&format.Event{ + Category: s.Category, + Name: s.Name, + Phase: "e", + Time: viewerTime(s.Ts + s.Dur), + TID: s.Resource, + ID: e.asyncSliceSeq, + Scope: s.Scope, + Stack: s.EndStack, + Arg: s.Arg, + Cname: cname, + }) +} + +type AsyncSliceEvent struct { + SliceEvent + Category string + Scope string + TaskColorIndex uint64 // Take on the same color as the task with this ID. +} + +func (e *Emitter) Instant(i InstantEvent) { + if !e.tsWithinRange(i.Ts) { + return + } + if e.filter != nil && !e.filter(i.Resource) { + return + } + cname := "" + e.OptionalEvent(&format.Event{ + Name: i.Name, + Category: i.Category, + Phase: "I", + Scope: "t", + Time: viewerTime(i.Ts), + PID: format.ProcsSection, + TID: i.Resource, + Stack: i.Stack, + Cname: cname, + Arg: i.Arg, + }) +} + +type InstantEvent struct { + Ts time.Duration + Name string + Category string + Resource uint64 + Stack int + Arg any +} + +func (e *Emitter) Arrow(a ArrowEvent) { + if e.filter != nil && (!e.filter(a.FromResource) || !e.filter(a.ToResource)) { + return + } + e.arrow(a, format.ProcsSection) +} + +func (e *Emitter) TaskArrow(a ArrowEvent) { + e.arrow(a, format.TasksSection) +} + +func (e *Emitter) arrow(a ArrowEvent, sectionID uint64) { + if !e.tsWithinRange(a.Start) || !e.tsWithinRange(a.End) { + return + } + e.arrowSeq++ + e.OptionalEvent(&format.Event{ + Name: a.Name, + Phase: "s", + TID: a.FromResource, + PID: sectionID, + ID: e.arrowSeq, + Time: viewerTime(a.Start), + Stack: a.FromStack, + }) + e.OptionalEvent(&format.Event{ + Name: a.Name, + Phase: "t", + TID: a.ToResource, + PID: sectionID, + ID: e.arrowSeq, + Time: viewerTime(a.End), + }) +} + +type ArrowEvent struct { + Name string + Start time.Duration + End time.Duration + FromResource uint64 + FromStack int + ToResource uint64 +} + +func (e *Emitter) Event(ev *format.Event) { + e.c.ConsumeViewerEvent(ev, true) +} + +func (e *Emitter) HeapAlloc(ts time.Duration, v uint64) { + e.heapStats.heapAlloc = v + e.emitHeapCounters(ts) +} + +func (e *Emitter) Focus(id uint64) { + e.focusResource = id +} + +func (e *Emitter) GoroutineTransition(ts time.Duration, from, to GState) { + e.gstates[from]-- + e.gstates[to]++ + if e.prevGstates == e.gstates { + return + } + if e.tsWithinRange(ts) { + e.OptionalEvent(&format.Event{ + Name: "Goroutines", + Phase: "C", + Time: viewerTime(ts), + PID: 1, + Arg: &format.GoroutineCountersArg{ + Running: uint64(e.gstates[GRunning]), + Runnable: uint64(e.gstates[GRunnable]), + GCWaiting: uint64(e.gstates[GWaitingGC]), + }, + }) + } + e.prevGstates = e.gstates +} + +func (e *Emitter) IncThreadStateCount(ts time.Duration, state ThreadState, delta int64) { + e.threadStats[state] += delta + if e.prevThreadStats == e.threadStats { + return + } + if e.tsWithinRange(ts) { + e.OptionalEvent(&format.Event{ + Name: "Threads", + Phase: "C", + Time: viewerTime(ts), + PID: 1, + Arg: &format.ThreadCountersArg{ + Running: int64(e.threadStats[ThreadStateRunning]), + InSyscall: int64(e.threadStats[ThreadStateInSyscall]), + // TODO(mknyszek): Why is InSyscallRuntime not included here? + }, + }) + } + e.prevThreadStats = e.threadStats +} + +func (e *Emitter) HeapGoal(ts time.Duration, v uint64) { + // This cutoff at 1 PiB is a Workaround for https://github.com/golang/go/issues/63864. + // + // TODO(mknyszek): Remove this once the problem has been fixed. + const PB = 1 << 50 + if v > PB { + v = 0 + } + e.heapStats.nextGC = v + e.emitHeapCounters(ts) +} + +func (e *Emitter) emitHeapCounters(ts time.Duration) { + if e.prevHeapStats == e.heapStats { + return + } + diff := uint64(0) + if e.heapStats.nextGC > e.heapStats.heapAlloc { + diff = e.heapStats.nextGC - e.heapStats.heapAlloc + } + if e.tsWithinRange(ts) { + e.OptionalEvent(&format.Event{ + Name: "Heap", + Phase: "C", + Time: viewerTime(ts), + PID: 1, + Arg: &format.HeapCountersArg{Allocated: e.heapStats.heapAlloc, NextGC: diff}, + }) + } + e.prevHeapStats = e.heapStats +} + +// Err returns an error if the emitter is in an invalid state. +func (e *Emitter) Err() error { + if e.gstates[GRunnable] < 0 || e.gstates[GRunning] < 0 || e.threadStats[ThreadStateInSyscall] < 0 || e.threadStats[ThreadStateInSyscallRuntime] < 0 { + return fmt.Errorf( + "runnable=%d running=%d insyscall=%d insyscallRuntime=%d", + e.gstates[GRunnable], + e.gstates[GRunning], + e.threadStats[ThreadStateInSyscall], + e.threadStats[ThreadStateInSyscallRuntime], + ) + } + return nil +} + +func (e *Emitter) tsWithinRange(ts time.Duration) bool { + return e.rangeStart <= ts && ts <= e.rangeEnd +} + +// OptionalEvent emits ev if it's within the time range of of the consumer, i.e. +// the selected trace split range. +func (e *Emitter) OptionalEvent(ev *format.Event) { + e.c.ConsumeViewerEvent(ev, false) +} + +func (e *Emitter) Flush() { + e.processMeta(format.StatsSection, "STATS", 0) + + if len(e.tasks) != 0 { + e.processMeta(format.TasksSection, "TASKS", 1) + } + for id, task := range e.tasks { + e.threadMeta(format.TasksSection, id, task.name, task.sortIndex) + } + + e.processMeta(format.ProcsSection, e.resourceType, 2) + + e.threadMeta(format.ProcsSection, trace.GCP, "GC", -6) + e.threadMeta(format.ProcsSection, trace.NetpollP, "Network", -5) + e.threadMeta(format.ProcsSection, trace.TimerP, "Timers", -4) + e.threadMeta(format.ProcsSection, trace.SyscallP, "Syscalls", -3) + + for id, name := range e.resources { + priority := int(id) + if e.focusResource != 0 && id == e.focusResource { + // Put the focus goroutine on top. + priority = -2 + } + e.threadMeta(format.ProcsSection, id, name, priority) + } + + e.c.Flush() +} + +func (e *Emitter) threadMeta(sectionID, tid uint64, name string, priority int) { + e.Event(&format.Event{ + Name: "thread_name", + Phase: "M", + PID: sectionID, + TID: tid, + Arg: &format.NameArg{Name: name}, + }) + e.Event(&format.Event{ + Name: "thread_sort_index", + Phase: "M", + PID: sectionID, + TID: tid, + Arg: &format.SortIndexArg{Index: priority}, + }) +} + +func (e *Emitter) processMeta(sectionID uint64, name string, priority int) { + e.Event(&format.Event{ + Name: "process_name", + Phase: "M", + PID: sectionID, + Arg: &format.NameArg{Name: name}, + }) + e.Event(&format.Event{ + Name: "process_sort_index", + Phase: "M", + PID: sectionID, + Arg: &format.SortIndexArg{Index: priority}, + }) +} + +// Stack emits the given frames and returns a unique id for the stack. No +// pointers to the given data are being retained beyond the call to Stack. +func (e *Emitter) Stack(stk []*trace.Frame) int { + return e.buildBranch(e.frameTree, stk) +} + +// buildBranch builds one branch in the prefix tree rooted at ctx.frameTree. +func (e *Emitter) buildBranch(parent frameNode, stk []*trace.Frame) int { + if len(stk) == 0 { + return parent.id + } + last := len(stk) - 1 + frame := stk[last] + stk = stk[:last] + + node, ok := parent.children[frame.PC] + if !ok { + e.frameSeq++ + node.id = e.frameSeq + node.children = make(map[uint64]frameNode) + parent.children[frame.PC] = node + e.c.ConsumeViewerFrame(strconv.Itoa(node.id), format.Frame{Name: fmt.Sprintf("%v:%v", frame.Fn, frame.Line), Parent: parent.id}) + } + return e.buildBranch(node, stk) +} + +type heapStats struct { + heapAlloc uint64 + nextGC uint64 +} + +func viewerTime(t time.Duration) float64 { + return float64(t) / float64(time.Microsecond) +} + +type GState int + +const ( + GDead GState = iota + GRunnable + GRunning + GWaiting + GWaitingGC + + gStateCount +) + +type ThreadState int + +const ( + ThreadStateInSyscall ThreadState = iota + ThreadStateInSyscallRuntime + ThreadStateRunning + + threadStateCount +) + +type frameNode struct { + id int + children map[uint64]frameNode +} + +// Mapping from more reasonable color names to the reserved color names in +// https://github.com/catapult-project/catapult/blob/master/tracing/tracing/base/color_scheme.html#L50 +// The chrome trace viewer allows only those as cname values. +const ( + colorLightMauve = "thread_state_uninterruptible" // 182, 125, 143 + colorOrange = "thread_state_iowait" // 255, 140, 0 + colorSeafoamGreen = "thread_state_running" // 126, 200, 148 + colorVistaBlue = "thread_state_runnable" // 133, 160, 210 + colorTan = "thread_state_unknown" // 199, 155, 125 + colorIrisBlue = "background_memory_dump" // 0, 180, 180 + colorMidnightBlue = "light_memory_dump" // 0, 0, 180 + colorDeepMagenta = "detailed_memory_dump" // 180, 0, 180 + colorBlue = "vsync_highlight_color" // 0, 0, 255 + colorGrey = "generic_work" // 125, 125, 125 + colorGreen = "good" // 0, 125, 0 + colorDarkGoldenrod = "bad" // 180, 125, 0 + colorPeach = "terrible" // 180, 0, 0 + colorBlack = "black" // 0, 0, 0 + colorLightGrey = "grey" // 221, 221, 221 + colorWhite = "white" // 255, 255, 255 + colorYellow = "yellow" // 255, 255, 0 + colorOlive = "olive" // 100, 100, 0 + colorCornflowerBlue = "rail_response" // 67, 135, 253 + colorSunsetOrange = "rail_animation" // 244, 74, 63 + colorTangerine = "rail_idle" // 238, 142, 0 + colorShamrockGreen = "rail_load" // 13, 168, 97 + colorGreenishYellow = "startup" // 230, 230, 0 + colorDarkGrey = "heap_dump_stack_frame" // 128, 128, 128 + colorTawny = "heap_dump_child_node_arrow" // 204, 102, 0 + colorLemon = "cq_build_running" // 255, 255, 119 + colorLime = "cq_build_passed" // 153, 238, 102 + colorPink = "cq_build_failed" // 238, 136, 136 + colorSilver = "cq_build_abandoned" // 187, 187, 187 + colorManzGreen = "cq_build_attempt_runnig" // 222, 222, 75 + colorKellyGreen = "cq_build_attempt_passed" // 108, 218, 35 + colorAnotherGrey = "cq_build_attempt_failed" // 187, 187, 187 +) + +var colorForTask = []string{ + colorLightMauve, + colorOrange, + colorSeafoamGreen, + colorVistaBlue, + colorTan, + colorMidnightBlue, + colorIrisBlue, + colorDeepMagenta, + colorGreen, + colorDarkGoldenrod, + colorPeach, + colorOlive, + colorCornflowerBlue, + colorSunsetOrange, + colorTangerine, + colorShamrockGreen, + colorTawny, + colorLemon, + colorLime, + colorPink, + colorSilver, + colorManzGreen, + colorKellyGreen, +} + +func pickTaskColor(id uint64) string { + idx := id % uint64(len(colorForTask)) + return colorForTask[idx] +} |