// 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 main import ( "cmd/internal/traceviewer" "embed" "encoding/json" "fmt" "internal/trace" "io" "log" "math" "net/http" "runtime/debug" "sort" "strconv" "strings" "time" ) //go:embed static/trace_viewer_full.html static/webcomponents.min.js var staticContent embed.FS func init() { http.HandleFunc("/trace", httpTrace) http.HandleFunc("/jsontrace", httpJsonTrace) http.Handle("/static/", http.FileServer(http.FS(staticContent))) } // httpTrace serves either whole trace (goid==0) or trace for goid goroutine. func httpTrace(w http.ResponseWriter, r *http.Request) { _, err := parseTrace() if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) return } if err := r.ParseForm(); err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) return } html := strings.ReplaceAll(templTrace, "{{PARAMS}}", r.Form.Encode()) w.Write([]byte(html)) } // https://chromium.googlesource.com/catapult/+/9508452e18f130c98499cb4c4f1e1efaedee8962/tracing/docs/embedding-trace-viewer.md // This is almost verbatim copy of https://chromium-review.googlesource.com/c/catapult/+/2062938/2/tracing/bin/index.html var templTrace = ` ` // httpJsonTrace serves json trace, requested from within templTrace HTML. func httpJsonTrace(w http.ResponseWriter, r *http.Request) { defer debug.FreeOSMemory() defer reportMemoryUsage("after httpJsonTrace") // This is an AJAX handler, so instead of http.Error we use log.Printf to log errors. res, err := parseTrace() if err != nil { log.Printf("failed to parse trace: %v", err) return } params := &traceParams{ parsed: res, endTime: math.MaxInt64, } if goids := r.FormValue("goid"); goids != "" { // If goid argument is present, we are rendering a trace for this particular goroutine. goid, err := strconv.ParseUint(goids, 10, 64) if err != nil { log.Printf("failed to parse goid parameter %q: %v", goids, err) return } analyzeGoroutines(res.Events) g, ok := gs[goid] if !ok { log.Printf("failed to find goroutine %d", goid) return } params.mode = modeGoroutineOriented params.startTime = g.StartTime if g.EndTime != 0 { params.endTime = g.EndTime } else { // The goroutine didn't end. params.endTime = lastTimestamp() } params.maing = goid params.gs = trace.RelatedGoroutines(res.Events, goid) } else if taskids := r.FormValue("taskid"); taskids != "" { taskid, err := strconv.ParseUint(taskids, 10, 64) if err != nil { log.Printf("failed to parse taskid parameter %q: %v", taskids, err) return } annotRes, _ := analyzeAnnotations() task, ok := annotRes.tasks[taskid] if !ok || len(task.events) == 0 { log.Printf("failed to find task with id %d", taskid) return } goid := task.events[0].G params.mode = modeGoroutineOriented | modeTaskOriented params.startTime = task.firstTimestamp() - 1 params.endTime = task.lastTimestamp() + 1 params.maing = goid params.tasks = task.descendants() gs := map[uint64]bool{} for _, t := range params.tasks { // find only directly involved goroutines for k, v := range t.RelatedGoroutines(res.Events, 0) { gs[k] = v } } params.gs = gs } else if taskids := r.FormValue("focustask"); taskids != "" { taskid, err := strconv.ParseUint(taskids, 10, 64) if err != nil { log.Printf("failed to parse focustask parameter %q: %v", taskids, err) return } annotRes, _ := analyzeAnnotations() task, ok := annotRes.tasks[taskid] if !ok || len(task.events) == 0 { log.Printf("failed to find task with id %d", taskid) return } params.mode = modeTaskOriented params.startTime = task.firstTimestamp() - 1 params.endTime = task.lastTimestamp() + 1 params.tasks = task.descendants() } start := int64(0) end := int64(math.MaxInt64) if startStr, endStr := r.FormValue("start"), r.FormValue("end"); startStr != "" && endStr != "" { // If start/end arguments are present, we are rendering a range of the trace. start, err = strconv.ParseInt(startStr, 10, 64) if err != nil { log.Printf("failed to parse start parameter %q: %v", startStr, err) return } end, err = strconv.ParseInt(endStr, 10, 64) if err != nil { log.Printf("failed to parse end parameter %q: %v", endStr, err) return } } c := viewerDataTraceConsumer(w, start, end) if err := generateTrace(params, c); err != nil { log.Printf("failed to generate trace: %v", err) return } } type Range struct { Name string Start int End int StartTime int64 EndTime int64 } func (r Range) URL() string { return fmt.Sprintf("/trace?start=%d&end=%d", r.Start, r.End) } // splitTrace splits the trace into a number of ranges, // each resulting in approx 100MB of json output // (trace viewer can hardly handle more). func splitTrace(res trace.ParseResult) []Range { params := &traceParams{ parsed: res, endTime: math.MaxInt64, } s, c := splittingTraceConsumer(100 << 20) // 100M if err := generateTrace(params, c); err != nil { dief("%v\n", err) } return s.Ranges } type splitter struct { Ranges []Range } // walkStackFrames calls fn for id and all of its parent frames from allFrames. func walkStackFrames(allFrames map[string]traceviewer.Frame, id int, fn func(id int)) { for id != 0 { f, ok := allFrames[strconv.Itoa(id)] if !ok { break } fn(id) id = f.Parent } } func stackFrameEncodedSize(id uint, f traceviewer.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 } 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 = traceviewer.Data{Frames: make(map[string]traceviewer.Frame)} allFrames = make(map[string]traceviewer.Frame) sizes []eventSz cw countingWriter ) s := new(splitter) return s, traceConsumer{ consumeTimeUnit: func(unit string) { data.TimeUnit = unit }, consumeViewerEvent: func(v *traceviewer.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 traceviewer.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]traceviewer.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) ranges = append(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]traceviewer.Frame) framesSize = 0 eventsSize = 0 } if len(ranges) <= 1 { s.Ranges = nil return } if end := len(sizes) - 1; start < end { ranges = append(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), }) } s.Ranges = ranges }, } } type countingWriter struct { size int } func (cw *countingWriter) Write(data []byte) (int, error) { cw.size += len(data) return len(data), nil } type traceParams struct { parsed trace.ParseResult mode traceviewMode startTime int64 endTime int64 maing uint64 // for goroutine-oriented view, place this goroutine on the top row gs map[uint64]bool // Goroutines to be displayed for goroutine-oriented or task-oriented view tasks []*taskDesc // Tasks to be displayed. tasks[0] is the top-most task } type traceviewMode uint const ( modeGoroutineOriented traceviewMode = 1 << iota modeTaskOriented ) type traceContext struct { *traceParams consumer traceConsumer frameTree frameNode frameSeq int arrowSeq uint64 gcount uint64 heapStats, prevHeapStats heapStats threadStats, prevThreadStats threadStats gstates, prevGstates [gStateCount]int64 regionID int // last emitted region id. incremented in each emitRegion call. } type heapStats struct { heapAlloc uint64 nextGC uint64 } type threadStats struct { insyscallRuntime int64 // system goroutine in syscall insyscall int64 // user goroutine in syscall prunning int64 // thread running P } type frameNode struct { id int children map[uint64]frameNode } type gState int const ( gDead gState = iota gRunnable gRunning gWaiting gWaitingGC gStateCount ) type gInfo struct { state gState // current state name string // name chosen for this goroutine at first EvGoStart isSystemG bool start *trace.Event // most recent EvGoStart markAssist *trace.Event // if non-nil, the mark assist currently running. } type NameArg struct { Name string `json:"name"` } type TaskArg struct { ID uint64 `json:"id"` StartG uint64 `json:"start_g,omitempty"` EndG uint64 `json:"end_g,omitempty"` } type RegionArg struct { TaskID uint64 `json:"taskid,omitempty"` } type SortIndexArg struct { Index int `json:"sort_index"` } type traceConsumer struct { consumeTimeUnit func(unit string) consumeViewerEvent func(v *traceviewer.Event, required bool) consumeViewerFrame func(key string, f traceviewer.Frame) flush func() } const ( procsSection = 0 // where Goroutines or per-P timelines are presented. statsSection = 1 // where counters are presented. tasksSection = 2 // where Task hierarchy & timeline is presented. ) // generateTrace generates json trace for trace-viewer: // https://github.com/google/trace-viewer // Trace format is described at: // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view // If mode==goroutineMode, generate trace for goroutine goid, otherwise whole trace. // startTime, endTime determine part of the trace that we are interested in. // gset restricts goroutines that are included in the resulting trace. func generateTrace(params *traceParams, consumer traceConsumer) error { defer consumer.flush() ctx := &traceContext{traceParams: params} ctx.frameTree.children = make(map[uint64]frameNode) ctx.consumer = consumer ctx.consumer.consumeTimeUnit("ns") maxProc := 0 ginfos := make(map[uint64]*gInfo) stacks := params.parsed.Stacks getGInfo := func(g uint64) *gInfo { info, ok := ginfos[g] if !ok { info = &gInfo{} ginfos[g] = info } return info } // Since we make many calls to setGState, we record a sticky // error in setGStateErr and check it after every event. var setGStateErr error setGState := func(ev *trace.Event, g uint64, oldState, newState gState) { info := getGInfo(g) if oldState == gWaiting && info.state == gWaitingGC { // For checking, gWaiting counts as any gWaiting*. oldState = info.state } if info.state != oldState && setGStateErr == nil { setGStateErr = fmt.Errorf("expected G %d to be in state %d, but got state %d", g, oldState, info.state) } ctx.gstates[info.state]-- ctx.gstates[newState]++ info.state = newState } for _, ev := range ctx.parsed.Events { // Handle state transitions before we filter out events. switch ev.Type { case trace.EvGoStart, trace.EvGoStartLabel: setGState(ev, ev.G, gRunnable, gRunning) info := getGInfo(ev.G) info.start = ev case trace.EvProcStart: ctx.threadStats.prunning++ case trace.EvProcStop: ctx.threadStats.prunning-- case trace.EvGoCreate: newG := ev.Args[0] info := getGInfo(newG) if info.name != "" { return fmt.Errorf("duplicate go create event for go id=%d detected at offset %d", newG, ev.Off) } stk, ok := stacks[ev.Args[1]] if !ok || len(stk) == 0 { return fmt.Errorf("invalid go create event: missing stack information for go id=%d at offset %d", newG, ev.Off) } fname := stk[0].Fn info.name = fmt.Sprintf("G%v %s", newG, fname) info.isSystemG = trace.IsSystemGoroutine(fname) ctx.gcount++ setGState(ev, newG, gDead, gRunnable) case trace.EvGoEnd: ctx.gcount-- setGState(ev, ev.G, gRunning, gDead) case trace.EvGoUnblock: setGState(ev, ev.Args[0], gWaiting, gRunnable) case trace.EvGoSysExit: setGState(ev, ev.G, gWaiting, gRunnable) if getGInfo(ev.G).isSystemG { ctx.threadStats.insyscallRuntime-- } else { ctx.threadStats.insyscall-- } case trace.EvGoSysBlock: setGState(ev, ev.G, gRunning, gWaiting) if getGInfo(ev.G).isSystemG { ctx.threadStats.insyscallRuntime++ } else { ctx.threadStats.insyscall++ } case trace.EvGoSched, trace.EvGoPreempt: setGState(ev, ev.G, gRunning, gRunnable) case trace.EvGoStop, trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet: setGState(ev, ev.G, gRunning, gWaiting) case trace.EvGoBlockGC: setGState(ev, ev.G, gRunning, gWaitingGC) case trace.EvGCMarkAssistStart: getGInfo(ev.G).markAssist = ev case trace.EvGCMarkAssistDone: getGInfo(ev.G).markAssist = nil case trace.EvGoWaiting: setGState(ev, ev.G, gRunnable, gWaiting) case trace.EvGoInSyscall: // Cancel out the effect of EvGoCreate at the beginning. setGState(ev, ev.G, gRunnable, gWaiting) if getGInfo(ev.G).isSystemG { ctx.threadStats.insyscallRuntime++ } else { ctx.threadStats.insyscall++ } case trace.EvHeapAlloc: ctx.heapStats.heapAlloc = ev.Args[0] case trace.EvHeapGoal: ctx.heapStats.nextGC = ev.Args[0] } if setGStateErr != nil { return setGStateErr } if ctx.gstates[gRunnable] < 0 || ctx.gstates[gRunning] < 0 || ctx.threadStats.insyscall < 0 || ctx.threadStats.insyscallRuntime < 0 { return fmt.Errorf("invalid state after processing %v: runnable=%d running=%d insyscall=%d insyscallRuntime=%d", ev, ctx.gstates[gRunnable], ctx.gstates[gRunning], ctx.threadStats.insyscall, ctx.threadStats.insyscallRuntime) } // Ignore events that are from uninteresting goroutines // or outside of the interesting timeframe. if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] { continue } if !withinTimeRange(ev, ctx.startTime, ctx.endTime) { continue } if ev.P < trace.FakeP && ev.P > maxProc { maxProc = ev.P } // Emit trace objects. switch ev.Type { case trace.EvProcStart: if ctx.mode&modeGoroutineOriented != 0 { continue } ctx.emitInstant(ev, "proc start", "") case trace.EvProcStop: if ctx.mode&modeGoroutineOriented != 0 { continue } ctx.emitInstant(ev, "proc stop", "") case trace.EvGCStart: ctx.emitSlice(ev, "GC") case trace.EvGCDone: case trace.EvSTWStart: if ctx.mode&modeGoroutineOriented != 0 { continue } ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0])) case trace.EvSTWDone: case trace.EvGCMarkAssistStart: // Mark assists can continue past preemptions, so truncate to the // whichever comes first. We'll synthesize another slice if // necessary in EvGoStart. markFinish := ev.Link goFinish := getGInfo(ev.G).start.Link fakeMarkStart := *ev text := "MARK ASSIST" if markFinish == nil || markFinish.Ts > goFinish.Ts { fakeMarkStart.Link = goFinish text = "MARK ASSIST (unfinished)" } ctx.emitSlice(&fakeMarkStart, text) case trace.EvGCSweepStart: slice := ctx.makeSlice(ev, "SWEEP") if done := ev.Link; done != nil && done.Args[0] != 0 { slice.Arg = struct { Swept uint64 `json:"Swept bytes"` Reclaimed uint64 `json:"Reclaimed bytes"` }{done.Args[0], done.Args[1]} } ctx.emit(slice) case trace.EvGoStart, trace.EvGoStartLabel: info := getGInfo(ev.G) if ev.Type == trace.EvGoStartLabel { ctx.emitSlice(ev, ev.SArgs[0]) } else { ctx.emitSlice(ev, info.name) } if info.markAssist != nil { // If we're in a mark assist, synthesize a new slice, ending // either when the mark assist ends or when we're descheduled. markFinish := info.markAssist.Link goFinish := ev.Link fakeMarkStart := *ev text := "MARK ASSIST (resumed, unfinished)" if markFinish != nil && markFinish.Ts < goFinish.Ts { fakeMarkStart.Link = markFinish text = "MARK ASSIST (resumed)" } ctx.emitSlice(&fakeMarkStart, text) } case trace.EvGoCreate: ctx.emitArrow(ev, "go") case trace.EvGoUnblock: ctx.emitArrow(ev, "unblock") case trace.EvGoSysCall: ctx.emitInstant(ev, "syscall", "") case trace.EvGoSysExit: ctx.emitArrow(ev, "sysexit") case trace.EvUserLog: ctx.emitInstant(ev, formatUserLog(ev), "user event") case trace.EvUserTaskCreate: ctx.emitInstant(ev, "task start", "user event") case trace.EvUserTaskEnd: ctx.emitInstant(ev, "task end", "user event") case trace.EvCPUSample: if ev.P >= 0 { // only show in this UI when there's an associated P ctx.emitInstant(ev, "CPU profile sample", "") } } // Emit any counter updates. ctx.emitThreadCounters(ev) ctx.emitHeapCounters(ev) ctx.emitGoroutineCounters(ev) } ctx.emitSectionFooter(statsSection, "STATS", 0) if ctx.mode&modeTaskOriented != 0 { ctx.emitSectionFooter(tasksSection, "TASKS", 1) } if ctx.mode&modeGoroutineOriented != 0 { ctx.emitSectionFooter(procsSection, "G", 2) } else { ctx.emitSectionFooter(procsSection, "PROCS", 2) } ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: trace.GCP, Arg: &NameArg{"GC"}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: trace.GCP, Arg: &SortIndexArg{-6}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: trace.NetpollP, Arg: &NameArg{"Network"}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: trace.NetpollP, Arg: &SortIndexArg{-5}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: trace.TimerP, Arg: &NameArg{"Timers"}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: trace.TimerP, Arg: &SortIndexArg{-4}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: trace.SyscallP, Arg: &NameArg{"Syscalls"}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: trace.SyscallP, Arg: &SortIndexArg{-3}}) // Display rows for Ps if we are in the default trace view mode (not goroutine-oriented presentation) if ctx.mode&modeGoroutineOriented == 0 { for i := 0; i <= maxProc; i++ { ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}}) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: uint64(i), Arg: &SortIndexArg{i}}) } } // Display task and its regions if we are in task-oriented presentation mode. if ctx.mode&modeTaskOriented != 0 { // sort tasks based on the task start time. sortedTask := make([]*taskDesc, len(ctx.tasks)) copy(sortedTask, ctx.tasks) sort.SliceStable(sortedTask, func(i, j int) bool { ti, tj := sortedTask[i], sortedTask[j] if ti.firstTimestamp() == tj.firstTimestamp() { return ti.lastTimestamp() < tj.lastTimestamp() } return ti.firstTimestamp() < tj.firstTimestamp() }) for i, task := range sortedTask { ctx.emitTask(task, i) // If we are in goroutine-oriented mode, we draw regions. // TODO(hyangah): add this for task/P-oriented mode (i.e., focustask view) too. if ctx.mode&modeGoroutineOriented != 0 { for _, s := range task.regions { ctx.emitRegion(s) } } } } // Display goroutine rows if we are either in goroutine-oriented mode. if ctx.mode&modeGoroutineOriented != 0 { for k, v := range ginfos { if !ctx.gs[k] { continue } ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: procsSection, TID: k, Arg: &NameArg{v.name}}) } // Row for the main goroutine (maing) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: ctx.maing, Arg: &SortIndexArg{-2}}) // Row for GC or global state (specified with G=0) ctx.emitFooter(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: procsSection, TID: 0, Arg: &SortIndexArg{-1}}) } return nil } func (ctx *traceContext) emit(e *traceviewer.Event) { ctx.consumer.consumeViewerEvent(e, false) } func (ctx *traceContext) emitFooter(e *traceviewer.Event) { ctx.consumer.consumeViewerEvent(e, true) } func (ctx *traceContext) emitSectionFooter(sectionID uint64, name string, priority int) { ctx.emitFooter(&traceviewer.Event{Name: "process_name", Phase: "M", PID: sectionID, Arg: &NameArg{name}}) ctx.emitFooter(&traceviewer.Event{Name: "process_sort_index", Phase: "M", PID: sectionID, Arg: &SortIndexArg{priority}}) } func (ctx *traceContext) time(ev *trace.Event) float64 { // Trace viewer wants timestamps in microseconds. return float64(ev.Ts) / 1000 } func withinTimeRange(ev *trace.Event, s, e int64) bool { if evEnd := ev.Link; evEnd != nil { return ev.Ts <= e && evEnd.Ts >= s } return ev.Ts >= s && ev.Ts <= e } func tsWithinRange(ts, s, e int64) bool { return s <= ts && ts <= e } func (ctx *traceContext) proc(ev *trace.Event) uint64 { if ctx.mode&modeGoroutineOriented != 0 && ev.P < trace.FakeP { return ev.G } else { return uint64(ev.P) } } func (ctx *traceContext) emitSlice(ev *trace.Event, name string) { ctx.emit(ctx.makeSlice(ev, name)) } func (ctx *traceContext) makeSlice(ev *trace.Event, name string) *traceviewer.Event { // If ViewerEvent.Dur is not a positive value, // trace viewer handles it as a non-terminating time interval. // Avoid it by setting the field with a small value. durationUsec := ctx.time(ev.Link) - ctx.time(ev) if ev.Link.Ts-ev.Ts <= 0 { durationUsec = 0.0001 // 0.1 nanoseconds } sl := &traceviewer.Event{ Name: name, Phase: "X", Time: ctx.time(ev), Dur: durationUsec, TID: ctx.proc(ev), Stack: ctx.stack(ev.Stk), EndStack: ctx.stack(ev.Link.Stk), } // grey out non-overlapping events if the event is not a global event (ev.G == 0) if ctx.mode&modeTaskOriented != 0 && ev.G != 0 { // include P information. if t := ev.Type; t == trace.EvGoStart || t == trace.EvGoStartLabel { type Arg struct { P int } sl.Arg = &Arg{P: ev.P} } // grey out non-overlapping events. overlapping := false for _, task := range ctx.tasks { if _, overlapped := task.overlappingDuration(ev); overlapped { overlapping = true break } } if !overlapping { sl.Cname = colorLightGrey } } return sl } func (ctx *traceContext) emitTask(task *taskDesc, sortIndex int) { taskRow := uint64(task.id) taskName := task.name durationUsec := float64(task.lastTimestamp()-task.firstTimestamp()) / 1e3 ctx.emitFooter(&traceviewer.Event{Name: "thread_name", Phase: "M", PID: tasksSection, TID: taskRow, Arg: &NameArg{fmt.Sprintf("T%d %s", task.id, taskName)}}) ctx.emit(&traceviewer.Event{Name: "thread_sort_index", Phase: "M", PID: tasksSection, TID: taskRow, Arg: &SortIndexArg{sortIndex}}) ts := float64(task.firstTimestamp()) / 1e3 sl := &traceviewer.Event{ Name: taskName, Phase: "X", Time: ts, Dur: durationUsec, PID: tasksSection, TID: taskRow, Cname: pickTaskColor(task.id), } targ := TaskArg{ID: task.id} if task.create != nil { sl.Stack = ctx.stack(task.create.Stk) targ.StartG = task.create.G } if task.end != nil { sl.EndStack = ctx.stack(task.end.Stk) targ.EndG = task.end.G } sl.Arg = targ ctx.emit(sl) if task.create != nil && task.create.Type == trace.EvUserTaskCreate && task.create.Args[1] != 0 { ctx.arrowSeq++ ctx.emit(&traceviewer.Event{Name: "newTask", Phase: "s", TID: task.create.Args[1], ID: ctx.arrowSeq, Time: ts, PID: tasksSection}) ctx.emit(&traceviewer.Event{Name: "newTask", Phase: "t", TID: taskRow, ID: ctx.arrowSeq, Time: ts, PID: tasksSection}) } } func (ctx *traceContext) emitRegion(s regionDesc) { if s.Name == "" { return } if !tsWithinRange(s.firstTimestamp(), ctx.startTime, ctx.endTime) && !tsWithinRange(s.lastTimestamp(), ctx.startTime, ctx.endTime) { return } ctx.regionID++ regionID := ctx.regionID id := s.TaskID scopeID := fmt.Sprintf("%x", id) name := s.Name sl0 := &traceviewer.Event{ Category: "Region", Name: name, Phase: "b", Time: float64(s.firstTimestamp()) / 1e3, TID: s.G, // only in goroutine-oriented view ID: uint64(regionID), Scope: scopeID, Cname: pickTaskColor(s.TaskID), } if s.Start != nil { sl0.Stack = ctx.stack(s.Start.Stk) } ctx.emit(sl0) sl1 := &traceviewer.Event{ Category: "Region", Name: name, Phase: "e", Time: float64(s.lastTimestamp()) / 1e3, TID: s.G, ID: uint64(regionID), Scope: scopeID, Cname: pickTaskColor(s.TaskID), Arg: RegionArg{TaskID: s.TaskID}, } if s.End != nil { sl1.Stack = ctx.stack(s.End.Stk) } ctx.emit(sl1) } type heapCountersArg struct { Allocated uint64 NextGC uint64 } func (ctx *traceContext) emitHeapCounters(ev *trace.Event) { if ctx.prevHeapStats == ctx.heapStats { return } diff := uint64(0) if ctx.heapStats.nextGC > ctx.heapStats.heapAlloc { diff = ctx.heapStats.nextGC - ctx.heapStats.heapAlloc } if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) { ctx.emit(&traceviewer.Event{Name: "Heap", Phase: "C", Time: ctx.time(ev), PID: 1, Arg: &heapCountersArg{ctx.heapStats.heapAlloc, diff}}) } ctx.prevHeapStats = ctx.heapStats } type goroutineCountersArg struct { Running uint64 Runnable uint64 GCWaiting uint64 } func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) { if ctx.prevGstates == ctx.gstates { return } if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) { ctx.emit(&traceviewer.Event{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), PID: 1, Arg: &goroutineCountersArg{uint64(ctx.gstates[gRunning]), uint64(ctx.gstates[gRunnable]), uint64(ctx.gstates[gWaitingGC])}}) } ctx.prevGstates = ctx.gstates } type threadCountersArg struct { Running int64 InSyscall int64 } func (ctx *traceContext) emitThreadCounters(ev *trace.Event) { if ctx.prevThreadStats == ctx.threadStats { return } if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) { ctx.emit(&traceviewer.Event{Name: "Threads", Phase: "C", Time: ctx.time(ev), PID: 1, Arg: &threadCountersArg{ Running: ctx.threadStats.prunning, InSyscall: ctx.threadStats.insyscall}}) } ctx.prevThreadStats = ctx.threadStats } func (ctx *traceContext) emitInstant(ev *trace.Event, name, category string) { if !tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) { return } cname := "" if ctx.mode&modeTaskOriented != 0 { taskID, isUserAnnotation := isUserAnnotationEvent(ev) show := false for _, task := range ctx.tasks { if isUserAnnotation && task.id == taskID || task.overlappingInstant(ev) { show = true break } } // grey out or skip if non-overlapping instant. if !show { if isUserAnnotation { return // don't display unrelated user annotation events. } cname = colorLightGrey } } var arg any if ev.Type == trace.EvProcStart { type Arg struct { ThreadID uint64 } arg = &Arg{ev.Args[0]} } ctx.emit(&traceviewer.Event{ Name: name, Category: category, Phase: "I", Scope: "t", Time: ctx.time(ev), TID: ctx.proc(ev), Stack: ctx.stack(ev.Stk), Cname: cname, Arg: arg}) } func (ctx *traceContext) emitArrow(ev *trace.Event, name string) { if ev.Link == nil { // The other end of the arrow is not captured in the trace. // For example, a goroutine was unblocked but was not scheduled before trace stop. return } if ctx.mode&modeGoroutineOriented != 0 && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) { return } if ev.P == trace.NetpollP || ev.P == trace.TimerP || ev.P == trace.SyscallP { // Trace-viewer discards arrows if they don't start/end inside of a slice or instant. // So emit a fake instant at the start of the arrow. ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock", "") } color := "" if ctx.mode&modeTaskOriented != 0 { overlapping := false // skip non-overlapping arrows. for _, task := range ctx.tasks { if _, overlapped := task.overlappingDuration(ev); overlapped { overlapping = true break } } if !overlapping { return } } ctx.arrowSeq++ ctx.emit(&traceviewer.Event{Name: name, Phase: "s", TID: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk), Cname: color}) ctx.emit(&traceviewer.Event{Name: name, Phase: "t", TID: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link), Cname: color}) } func (ctx *traceContext) stack(stk []*trace.Frame) int { return ctx.buildBranch(ctx.frameTree, stk) } // buildBranch builds one branch in the prefix tree rooted at ctx.frameTree. func (ctx *traceContext) 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 { ctx.frameSeq++ node.id = ctx.frameSeq node.children = make(map[uint64]frameNode) parent.children[frame.PC] = node ctx.consumer.consumeViewerFrame(strconv.Itoa(node.id), traceviewer.Frame{Name: fmt.Sprintf("%v:%v", frame.Fn, frame.Line), Parent: parent.id}) } return ctx.buildBranch(node, stk) } // firstTimestamp returns the timestamp of the first event record. func firstTimestamp() int64 { res, _ := parseTrace() if len(res.Events) > 0 { return res.Events[0].Ts } return 0 } // lastTimestamp returns the timestamp of the last event record. func lastTimestamp() int64 { res, _ := parseTrace() if n := len(res.Events); n > 1 { return res.Events[n-1].Ts } return 0 } type jsonWriter struct { w io.Writer enc *json.Encoder } func viewerDataTraceConsumer(w io.Writer, start, end int64) traceConsumer { allFrames := make(map[string]traceviewer.Frame) requiredFrames := make(map[string]traceviewer.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 *traceviewer.Event, required bool) { index++ if !required && (index < start || index > end) { // 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: get rid of the extra \n inserted by enc.Encode. // Same should be applied to splittingTraceConsumer. written++ }, consumeViewerFrame: func(k string, v traceviewer.Frame) { allFrames[k] = v }, flush: func() { io.WriteString(w, `], "stackFrames":`) enc.Encode(requiredFrames) io.WriteString(w, `}`) }, } } // 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] }