Source file src/cmd/trace/trace.go

Documentation: cmd/trace

     1  // Copyright 2014 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package main
     6  
     7  import (
     8  	"fmt"
     9  	"internal/trace"
    10  	"internal/trace/traceviewer"
    11  	"log"
    12  	"math"
    13  	"net/http"
    14  	"runtime/debug"
    15  	"sort"
    16  	"strconv"
    17  	"time"
    18  
    19  	"internal/trace/traceviewer/format"
    20  )
    21  
    22  func init() {
    23  	http.HandleFunc("/trace", httpTrace)
    24  	http.HandleFunc("/jsontrace", httpJsonTrace)
    25  	http.Handle("/static/", traceviewer.StaticHandler())
    26  }
    27  
    28  // httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
    29  func httpTrace(w http.ResponseWriter, r *http.Request) {
    30  	_, err := parseTrace()
    31  	if err != nil {
    32  		http.Error(w, err.Error(), http.StatusInternalServerError)
    33  		return
    34  	}
    35  	traceviewer.TraceHandler().ServeHTTP(w, r)
    36  }
    37  
    38  // httpJsonTrace serves json trace, requested from within templTrace HTML.
    39  func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
    40  	defer debug.FreeOSMemory()
    41  	defer reportMemoryUsage("after httpJsonTrace")
    42  	// This is an AJAX handler, so instead of http.Error we use log.Printf to log errors.
    43  	res, err := parseTrace()
    44  	if err != nil {
    45  		log.Printf("failed to parse trace: %v", err)
    46  		return
    47  	}
    48  
    49  	params := &traceParams{
    50  		parsed:  res,
    51  		endTime: math.MaxInt64,
    52  	}
    53  
    54  	if goids := r.FormValue("goid"); goids != "" {
    55  		// If goid argument is present, we are rendering a trace for this particular goroutine.
    56  		goid, err := strconv.ParseUint(goids, 10, 64)
    57  		if err != nil {
    58  			log.Printf("failed to parse goid parameter %q: %v", goids, err)
    59  			return
    60  		}
    61  		analyzeGoroutines(res.Events)
    62  		g, ok := gs[goid]
    63  		if !ok {
    64  			log.Printf("failed to find goroutine %d", goid)
    65  			return
    66  		}
    67  		params.mode = traceviewer.ModeGoroutineOriented
    68  		params.startTime = g.StartTime
    69  		if g.EndTime != 0 {
    70  			params.endTime = g.EndTime
    71  		} else { // The goroutine didn't end.
    72  			params.endTime = lastTimestamp()
    73  		}
    74  		params.maing = goid
    75  		params.gs = trace.RelatedGoroutines(res.Events, goid)
    76  	} else if taskids := r.FormValue("taskid"); taskids != "" {
    77  		taskid, err := strconv.ParseUint(taskids, 10, 64)
    78  		if err != nil {
    79  			log.Printf("failed to parse taskid parameter %q: %v", taskids, err)
    80  			return
    81  		}
    82  		annotRes, _ := analyzeAnnotations()
    83  		task, ok := annotRes.tasks[taskid]
    84  		if !ok || len(task.events) == 0 {
    85  			log.Printf("failed to find task with id %d", taskid)
    86  			return
    87  		}
    88  		goid := task.events[0].G
    89  		params.mode = traceviewer.ModeGoroutineOriented | traceviewer.ModeTaskOriented
    90  		params.startTime = task.firstTimestamp() - 1
    91  		params.endTime = task.lastTimestamp() + 1
    92  		params.maing = goid
    93  		params.tasks = task.descendants()
    94  		gs := map[uint64]bool{}
    95  		for _, t := range params.tasks {
    96  			// find only directly involved goroutines
    97  			for k, v := range t.RelatedGoroutines(res.Events, 0) {
    98  				gs[k] = v
    99  			}
   100  		}
   101  		params.gs = gs
   102  	} else if taskids := r.FormValue("focustask"); taskids != "" {
   103  		taskid, err := strconv.ParseUint(taskids, 10, 64)
   104  		if err != nil {
   105  			log.Printf("failed to parse focustask parameter %q: %v", taskids, err)
   106  			return
   107  		}
   108  		annotRes, _ := analyzeAnnotations()
   109  		task, ok := annotRes.tasks[taskid]
   110  		if !ok || len(task.events) == 0 {
   111  			log.Printf("failed to find task with id %d", taskid)
   112  			return
   113  		}
   114  		params.mode = traceviewer.ModeTaskOriented
   115  		params.startTime = task.firstTimestamp() - 1
   116  		params.endTime = task.lastTimestamp() + 1
   117  		params.tasks = task.descendants()
   118  	}
   119  
   120  	start := int64(0)
   121  	end := int64(math.MaxInt64)
   122  	if startStr, endStr := r.FormValue("start"), r.FormValue("end"); startStr != "" && endStr != "" {
   123  		// If start/end arguments are present, we are rendering a range of the trace.
   124  		start, err = strconv.ParseInt(startStr, 10, 64)
   125  		if err != nil {
   126  			log.Printf("failed to parse start parameter %q: %v", startStr, err)
   127  			return
   128  		}
   129  		end, err = strconv.ParseInt(endStr, 10, 64)
   130  		if err != nil {
   131  			log.Printf("failed to parse end parameter %q: %v", endStr, err)
   132  			return
   133  		}
   134  	}
   135  
   136  	c := traceviewer.ViewerDataTraceConsumer(w, start, end)
   137  	if err := generateTrace(params, c); err != nil {
   138  		log.Printf("failed to generate trace: %v", err)
   139  		return
   140  	}
   141  }
   142  
   143  // splitTrace splits the trace into a number of ranges,
   144  // each resulting in approx 100MB of json output
   145  // (trace viewer can hardly handle more).
   146  func splitTrace(res trace.ParseResult) []traceviewer.Range {
   147  	params := &traceParams{
   148  		parsed:  res,
   149  		endTime: math.MaxInt64,
   150  	}
   151  	s, c := traceviewer.SplittingTraceConsumer(100 << 20) // 100M
   152  	if err := generateTrace(params, c); err != nil {
   153  		dief("%v\n", err)
   154  	}
   155  	return s.Ranges
   156  }
   157  
   158  type traceParams struct {
   159  	parsed    trace.ParseResult
   160  	mode      traceviewer.Mode
   161  	startTime int64
   162  	endTime   int64
   163  	maing     uint64          // for goroutine-oriented view, place this goroutine on the top row
   164  	gs        map[uint64]bool // Goroutines to be displayed for goroutine-oriented or task-oriented view
   165  	tasks     []*taskDesc     // Tasks to be displayed. tasks[0] is the top-most task
   166  }
   167  
   168  type traceContext struct {
   169  	*traceParams
   170  	consumer traceviewer.TraceConsumer
   171  	emitter  *traceviewer.Emitter
   172  	arrowSeq uint64
   173  	gcount   uint64
   174  	regionID int // last emitted region id. incremented in each emitRegion call.
   175  }
   176  
   177  type gInfo struct {
   178  	state      traceviewer.GState // current state
   179  	name       string             // name chosen for this goroutine at first EvGoStart
   180  	isSystemG  bool
   181  	start      *trace.Event // most recent EvGoStart
   182  	markAssist *trace.Event // if non-nil, the mark assist currently running.
   183  }
   184  
   185  type NameArg struct {
   186  	Name string `json:"name"`
   187  }
   188  
   189  type TaskArg struct {
   190  	ID     uint64 `json:"id"`
   191  	StartG uint64 `json:"start_g,omitempty"`
   192  	EndG   uint64 `json:"end_g,omitempty"`
   193  }
   194  
   195  type RegionArg struct {
   196  	TaskID uint64 `json:"taskid,omitempty"`
   197  }
   198  
   199  type SortIndexArg struct {
   200  	Index int `json:"sort_index"`
   201  }
   202  
   203  // generateTrace generates json trace for trace-viewer:
   204  // https://github.com/google/trace-viewer
   205  // Trace format is described at:
   206  // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view
   207  // If mode==goroutineMode, generate trace for goroutine goid, otherwise whole trace.
   208  // startTime, endTime determine part of the trace that we are interested in.
   209  // gset restricts goroutines that are included in the resulting trace.
   210  func generateTrace(params *traceParams, consumer traceviewer.TraceConsumer) error {
   211  	emitter := traceviewer.NewEmitter(
   212  		consumer,
   213  		time.Duration(params.startTime),
   214  		time.Duration(params.endTime),
   215  	)
   216  	if params.mode&traceviewer.ModeGoroutineOriented != 0 {
   217  		emitter.SetResourceType("G")
   218  	} else {
   219  		emitter.SetResourceType("PROCS")
   220  	}
   221  	defer emitter.Flush()
   222  
   223  	ctx := &traceContext{traceParams: params, emitter: emitter}
   224  	ctx.consumer = consumer
   225  
   226  	maxProc := 0
   227  	ginfos := make(map[uint64]*gInfo)
   228  	stacks := params.parsed.Stacks
   229  
   230  	getGInfo := func(g uint64) *gInfo {
   231  		info, ok := ginfos[g]
   232  		if !ok {
   233  			info = &gInfo{}
   234  			ginfos[g] = info
   235  		}
   236  		return info
   237  	}
   238  
   239  	// Since we make many calls to setGState, we record a sticky
   240  	// error in setGStateErr and check it after every event.
   241  	var setGStateErr error
   242  	setGState := func(ev *trace.Event, g uint64, oldState, newState traceviewer.GState) {
   243  		info := getGInfo(g)
   244  		if oldState == traceviewer.GWaiting && info.state == traceviewer.GWaitingGC {
   245  			// For checking, traceviewer.GWaiting counts as any traceviewer.GWaiting*.
   246  			oldState = info.state
   247  		}
   248  		if info.state != oldState && setGStateErr == nil {
   249  			setGStateErr = fmt.Errorf("expected G %d to be in state %d, but got state %d", g, oldState, info.state)
   250  		}
   251  
   252  		emitter.GoroutineTransition(time.Duration(ev.Ts), info.state, newState)
   253  		info.state = newState
   254  	}
   255  
   256  	for _, ev := range ctx.parsed.Events {
   257  		// Handle state transitions before we filter out events.
   258  		switch ev.Type {
   259  		case trace.EvGoStart, trace.EvGoStartLabel:
   260  			setGState(ev, ev.G, traceviewer.GRunnable, traceviewer.GRunning)
   261  			info := getGInfo(ev.G)
   262  			info.start = ev
   263  		case trace.EvProcStart:
   264  			emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateRunning, 1)
   265  		case trace.EvProcStop:
   266  			emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateRunning, -1)
   267  		case trace.EvGoCreate:
   268  			newG := ev.Args[0]
   269  			info := getGInfo(newG)
   270  			if info.name != "" {
   271  				return fmt.Errorf("duplicate go create event for go id=%d detected at offset %d", newG, ev.Off)
   272  			}
   273  
   274  			stk, ok := stacks[ev.Args[1]]
   275  			if !ok || len(stk) == 0 {
   276  				return fmt.Errorf("invalid go create event: missing stack information for go id=%d at offset %d", newG, ev.Off)
   277  			}
   278  
   279  			fname := stk[0].Fn
   280  			info.name = fmt.Sprintf("G%v %s", newG, fname)
   281  			info.isSystemG = trace.IsSystemGoroutine(fname)
   282  
   283  			ctx.gcount++
   284  			setGState(ev, newG, traceviewer.GDead, traceviewer.GRunnable)
   285  		case trace.EvGoEnd:
   286  			ctx.gcount--
   287  			setGState(ev, ev.G, traceviewer.GRunning, traceviewer.GDead)
   288  		case trace.EvGoUnblock:
   289  			setGState(ev, ev.Args[0], traceviewer.GWaiting, traceviewer.GRunnable)
   290  		case trace.EvGoSysExit:
   291  			setGState(ev, ev.G, traceviewer.GWaiting, traceviewer.GRunnable)
   292  			if getGInfo(ev.G).isSystemG {
   293  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscallRuntime, -1)
   294  			} else {
   295  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscall, -1)
   296  			}
   297  		case trace.EvGoSysBlock:
   298  			setGState(ev, ev.G, traceviewer.GRunning, traceviewer.GWaiting)
   299  			if getGInfo(ev.G).isSystemG {
   300  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscallRuntime, 1)
   301  			} else {
   302  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscall, 1)
   303  			}
   304  		case trace.EvGoSched, trace.EvGoPreempt:
   305  			setGState(ev, ev.G, traceviewer.GRunning, traceviewer.GRunnable)
   306  		case trace.EvGoStop,
   307  			trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv,
   308  			trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet:
   309  			setGState(ev, ev.G, traceviewer.GRunning, traceviewer.GWaiting)
   310  		case trace.EvGoBlockGC:
   311  			setGState(ev, ev.G, traceviewer.GRunning, traceviewer.GWaitingGC)
   312  		case trace.EvGCMarkAssistStart:
   313  			getGInfo(ev.G).markAssist = ev
   314  		case trace.EvGCMarkAssistDone:
   315  			getGInfo(ev.G).markAssist = nil
   316  		case trace.EvGoWaiting:
   317  			setGState(ev, ev.G, traceviewer.GRunnable, traceviewer.GWaiting)
   318  		case trace.EvGoInSyscall:
   319  			// Cancel out the effect of EvGoCreate at the beginning.
   320  			setGState(ev, ev.G, traceviewer.GRunnable, traceviewer.GWaiting)
   321  			if getGInfo(ev.G).isSystemG {
   322  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscallRuntime, 1)
   323  			} else {
   324  				emitter.IncThreadStateCount(time.Duration(ev.Ts), traceviewer.ThreadStateInSyscall, 1)
   325  			}
   326  		case trace.EvHeapAlloc:
   327  			emitter.HeapAlloc(time.Duration(ev.Ts), ev.Args[0])
   328  		case trace.EvHeapGoal:
   329  			emitter.HeapGoal(time.Duration(ev.Ts), ev.Args[0])
   330  		}
   331  		if setGStateErr != nil {
   332  			return setGStateErr
   333  		}
   334  
   335  		if err := emitter.Err(); err != nil {
   336  			return fmt.Errorf("invalid state after processing %v: %s", ev, err)
   337  		}
   338  
   339  		// Ignore events that are from uninteresting goroutines
   340  		// or outside of the interesting timeframe.
   341  		if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] {
   342  			continue
   343  		}
   344  		if !withinTimeRange(ev, ctx.startTime, ctx.endTime) {
   345  			continue
   346  		}
   347  
   348  		if ev.P < trace.FakeP && ev.P > maxProc {
   349  			maxProc = ev.P
   350  		}
   351  
   352  		// Emit trace objects.
   353  		switch ev.Type {
   354  		case trace.EvProcStart:
   355  			if ctx.mode&traceviewer.ModeGoroutineOriented != 0 {
   356  				continue
   357  			}
   358  			ctx.emitInstant(ev, "proc start", "")
   359  		case trace.EvProcStop:
   360  			if ctx.mode&traceviewer.ModeGoroutineOriented != 0 {
   361  				continue
   362  			}
   363  			ctx.emitInstant(ev, "proc stop", "")
   364  		case trace.EvGCStart:
   365  			ctx.emitSlice(ev, "GC")
   366  		case trace.EvGCDone:
   367  		case trace.EvSTWStart:
   368  			if ctx.mode&traceviewer.ModeGoroutineOriented != 0 {
   369  				continue
   370  			}
   371  			ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0]))
   372  		case trace.EvSTWDone:
   373  		case trace.EvGCMarkAssistStart:
   374  			// Mark assists can continue past preemptions, so truncate to the
   375  			// whichever comes first. We'll synthesize another slice if
   376  			// necessary in EvGoStart.
   377  			markFinish := ev.Link
   378  			goFinish := getGInfo(ev.G).start.Link
   379  			fakeMarkStart := *ev
   380  			text := "MARK ASSIST"
   381  			if markFinish == nil || markFinish.Ts > goFinish.Ts {
   382  				fakeMarkStart.Link = goFinish
   383  				text = "MARK ASSIST (unfinished)"
   384  			}
   385  			ctx.emitSlice(&fakeMarkStart, text)
   386  		case trace.EvGCSweepStart:
   387  			slice := ctx.makeSlice(ev, "SWEEP")
   388  			if done := ev.Link; done != nil && done.Args[0] != 0 {
   389  				slice.Arg = struct {
   390  					Swept     uint64 `json:"Swept bytes"`
   391  					Reclaimed uint64 `json:"Reclaimed bytes"`
   392  				}{done.Args[0], done.Args[1]}
   393  			}
   394  			ctx.emit(slice)
   395  		case trace.EvGoStart, trace.EvGoStartLabel:
   396  			info := getGInfo(ev.G)
   397  			if ev.Type == trace.EvGoStartLabel {
   398  				ctx.emitSlice(ev, ev.SArgs[0])
   399  			} else {
   400  				ctx.emitSlice(ev, info.name)
   401  			}
   402  			if info.markAssist != nil {
   403  				// If we're in a mark assist, synthesize a new slice, ending
   404  				// either when the mark assist ends or when we're descheduled.
   405  				markFinish := info.markAssist.Link
   406  				goFinish := ev.Link
   407  				fakeMarkStart := *ev
   408  				text := "MARK ASSIST (resumed, unfinished)"
   409  				if markFinish != nil && markFinish.Ts < goFinish.Ts {
   410  					fakeMarkStart.Link = markFinish
   411  					text = "MARK ASSIST (resumed)"
   412  				}
   413  				ctx.emitSlice(&fakeMarkStart, text)
   414  			}
   415  		case trace.EvGoCreate:
   416  			ctx.emitArrow(ev, "go")
   417  		case trace.EvGoUnblock:
   418  			ctx.emitArrow(ev, "unblock")
   419  		case trace.EvGoSysCall:
   420  			ctx.emitInstant(ev, "syscall", "")
   421  		case trace.EvGoSysExit:
   422  			ctx.emitArrow(ev, "sysexit")
   423  		case trace.EvUserLog:
   424  			ctx.emitInstant(ev, formatUserLog(ev), "user event")
   425  		case trace.EvUserTaskCreate:
   426  			ctx.emitInstant(ev, "task start", "user event")
   427  		case trace.EvUserTaskEnd:
   428  			ctx.emitInstant(ev, "task end", "user event")
   429  		case trace.EvCPUSample:
   430  			if ev.P >= 0 {
   431  				// only show in this UI when there's an associated P
   432  				ctx.emitInstant(ev, "CPU profile sample", "")
   433  			}
   434  		}
   435  	}
   436  
   437  	// Display task and its regions if we are in task-oriented presentation mode.
   438  	if ctx.mode&traceviewer.ModeTaskOriented != 0 {
   439  		// sort tasks based on the task start time.
   440  		sortedTask := make([]*taskDesc, len(ctx.tasks))
   441  		copy(sortedTask, ctx.tasks)
   442  		sort.SliceStable(sortedTask, func(i, j int) bool {
   443  			ti, tj := sortedTask[i], sortedTask[j]
   444  			if ti.firstTimestamp() == tj.firstTimestamp() {
   445  				return ti.lastTimestamp() < tj.lastTimestamp()
   446  			}
   447  			return ti.firstTimestamp() < tj.firstTimestamp()
   448  		})
   449  
   450  		for i, task := range sortedTask {
   451  			ctx.emitTask(task, i)
   452  
   453  			// If we are in goroutine-oriented mode, we draw regions.
   454  			// TODO(hyangah): add this for task/P-oriented mode (i.e., focustask view) too.
   455  			if ctx.mode&traceviewer.ModeGoroutineOriented != 0 {
   456  				for _, s := range task.regions {
   457  					ctx.emitRegion(s)
   458  				}
   459  			}
   460  		}
   461  	}
   462  
   463  	// Display goroutine rows if we are either in goroutine-oriented mode.
   464  	if ctx.mode&traceviewer.ModeGoroutineOriented != 0 {
   465  		for k, v := range ginfos {
   466  			if !ctx.gs[k] {
   467  				continue
   468  			}
   469  			emitter.Resource(k, v.name)
   470  		}
   471  		emitter.Focus(ctx.maing)
   472  
   473  		// Row for GC or global state (specified with G=0)
   474  		ctx.emitFooter(&format.Event{Name: "thread_sort_index", Phase: "M", PID: format.ProcsSection, TID: 0, Arg: &SortIndexArg{-1}})
   475  	} else {
   476  		// Display rows for Ps if we are in the default trace view mode.
   477  		for i := 0; i <= maxProc; i++ {
   478  			emitter.Resource(uint64(i), fmt.Sprintf("Proc %v", i))
   479  		}
   480  	}
   481  
   482  	return nil
   483  }
   484  
   485  func (ctx *traceContext) emit(e *format.Event) {
   486  	ctx.consumer.ConsumeViewerEvent(e, false)
   487  }
   488  
   489  func (ctx *traceContext) emitFooter(e *format.Event) {
   490  	ctx.consumer.ConsumeViewerEvent(e, true)
   491  }
   492  func (ctx *traceContext) time(ev *trace.Event) float64 {
   493  	// Trace viewer wants timestamps in microseconds.
   494  	return float64(ev.Ts) / 1000
   495  }
   496  
   497  func withinTimeRange(ev *trace.Event, s, e int64) bool {
   498  	if evEnd := ev.Link; evEnd != nil {
   499  		return ev.Ts <= e && evEnd.Ts >= s
   500  	}
   501  	return ev.Ts >= s && ev.Ts <= e
   502  }
   503  
   504  func tsWithinRange(ts, s, e int64) bool {
   505  	return s <= ts && ts <= e
   506  }
   507  
   508  func (ctx *traceContext) proc(ev *trace.Event) uint64 {
   509  	if ctx.mode&traceviewer.ModeGoroutineOriented != 0 && ev.P < trace.FakeP {
   510  		return ev.G
   511  	} else {
   512  		return uint64(ev.P)
   513  	}
   514  }
   515  
   516  func (ctx *traceContext) emitSlice(ev *trace.Event, name string) {
   517  	ctx.emit(ctx.makeSlice(ev, name))
   518  }
   519  
   520  func (ctx *traceContext) makeSlice(ev *trace.Event, name string) *format.Event {
   521  	// If ViewerEvent.Dur is not a positive value,
   522  	// trace viewer handles it as a non-terminating time interval.
   523  	// Avoid it by setting the field with a small value.
   524  	durationUsec := ctx.time(ev.Link) - ctx.time(ev)
   525  	if ev.Link.Ts-ev.Ts <= 0 {
   526  		durationUsec = 0.0001 // 0.1 nanoseconds
   527  	}
   528  	sl := &format.Event{
   529  		Name:     name,
   530  		Phase:    "X",
   531  		Time:     ctx.time(ev),
   532  		Dur:      durationUsec,
   533  		TID:      ctx.proc(ev),
   534  		Stack:    ctx.emitter.Stack(ev.Stk),
   535  		EndStack: ctx.emitter.Stack(ev.Link.Stk),
   536  	}
   537  
   538  	// grey out non-overlapping events if the event is not a global event (ev.G == 0)
   539  	if ctx.mode&traceviewer.ModeTaskOriented != 0 && ev.G != 0 {
   540  		// include P information.
   541  		if t := ev.Type; t == trace.EvGoStart || t == trace.EvGoStartLabel {
   542  			type Arg struct {
   543  				P int
   544  			}
   545  			sl.Arg = &Arg{P: ev.P}
   546  		}
   547  		// grey out non-overlapping events.
   548  		overlapping := false
   549  		for _, task := range ctx.tasks {
   550  			if _, overlapped := task.overlappingDuration(ev); overlapped {
   551  				overlapping = true
   552  				break
   553  			}
   554  		}
   555  		if !overlapping {
   556  			sl.Cname = colorLightGrey
   557  		}
   558  	}
   559  	return sl
   560  }
   561  
   562  func (ctx *traceContext) emitTask(task *taskDesc, sortIndex int) {
   563  	taskRow := uint64(task.id)
   564  	taskName := task.name
   565  	durationUsec := float64(task.lastTimestamp()-task.firstTimestamp()) / 1e3
   566  
   567  	ctx.emitter.Task(taskRow, taskName, sortIndex)
   568  	ts := float64(task.firstTimestamp()) / 1e3
   569  	sl := &format.Event{
   570  		Name:  taskName,
   571  		Phase: "X",
   572  		Time:  ts,
   573  		Dur:   durationUsec,
   574  		PID:   format.TasksSection,
   575  		TID:   taskRow,
   576  		Cname: pickTaskColor(task.id),
   577  	}
   578  	targ := TaskArg{ID: task.id}
   579  	if task.create != nil {
   580  		sl.Stack = ctx.emitter.Stack(task.create.Stk)
   581  		targ.StartG = task.create.G
   582  	}
   583  	if task.end != nil {
   584  		sl.EndStack = ctx.emitter.Stack(task.end.Stk)
   585  		targ.EndG = task.end.G
   586  	}
   587  	sl.Arg = targ
   588  	ctx.emit(sl)
   589  
   590  	if task.create != nil && task.create.Type == trace.EvUserTaskCreate && task.create.Args[1] != 0 {
   591  		ctx.arrowSeq++
   592  		ctx.emit(&format.Event{Name: "newTask", Phase: "s", TID: task.create.Args[1], ID: ctx.arrowSeq, Time: ts, PID: format.TasksSection})
   593  		ctx.emit(&format.Event{Name: "newTask", Phase: "t", TID: taskRow, ID: ctx.arrowSeq, Time: ts, PID: format.TasksSection})
   594  	}
   595  }
   596  
   597  func (ctx *traceContext) emitRegion(s regionDesc) {
   598  	if s.Name == "" {
   599  		return
   600  	}
   601  
   602  	if !tsWithinRange(s.firstTimestamp(), ctx.startTime, ctx.endTime) &&
   603  		!tsWithinRange(s.lastTimestamp(), ctx.startTime, ctx.endTime) {
   604  		return
   605  	}
   606  
   607  	ctx.regionID++
   608  	regionID := ctx.regionID
   609  
   610  	id := s.TaskID
   611  	scopeID := fmt.Sprintf("%x", id)
   612  	name := s.Name
   613  
   614  	sl0 := &format.Event{
   615  		Category: "Region",
   616  		Name:     name,
   617  		Phase:    "b",
   618  		Time:     float64(s.firstTimestamp()) / 1e3,
   619  		TID:      s.G, // only in goroutine-oriented view
   620  		ID:       uint64(regionID),
   621  		Scope:    scopeID,
   622  		Cname:    pickTaskColor(s.TaskID),
   623  	}
   624  	if s.Start != nil {
   625  		sl0.Stack = ctx.emitter.Stack(s.Start.Stk)
   626  	}
   627  	ctx.emit(sl0)
   628  
   629  	sl1 := &format.Event{
   630  		Category: "Region",
   631  		Name:     name,
   632  		Phase:    "e",
   633  		Time:     float64(s.lastTimestamp()) / 1e3,
   634  		TID:      s.G,
   635  		ID:       uint64(regionID),
   636  		Scope:    scopeID,
   637  		Cname:    pickTaskColor(s.TaskID),
   638  		Arg:      RegionArg{TaskID: s.TaskID},
   639  	}
   640  	if s.End != nil {
   641  		sl1.Stack = ctx.emitter.Stack(s.End.Stk)
   642  	}
   643  	ctx.emit(sl1)
   644  }
   645  
   646  func (ctx *traceContext) emitInstant(ev *trace.Event, name, category string) {
   647  	if !tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
   648  		return
   649  	}
   650  
   651  	cname := ""
   652  	if ctx.mode&traceviewer.ModeTaskOriented != 0 {
   653  		taskID, isUserAnnotation := isUserAnnotationEvent(ev)
   654  
   655  		show := false
   656  		for _, task := range ctx.tasks {
   657  			if isUserAnnotation && task.id == taskID || task.overlappingInstant(ev) {
   658  				show = true
   659  				break
   660  			}
   661  		}
   662  		// grey out or skip if non-overlapping instant.
   663  		if !show {
   664  			if isUserAnnotation {
   665  				return // don't display unrelated user annotation events.
   666  			}
   667  			cname = colorLightGrey
   668  		}
   669  	}
   670  	var arg any
   671  	if ev.Type == trace.EvProcStart {
   672  		type Arg struct {
   673  			ThreadID uint64
   674  		}
   675  		arg = &Arg{ev.Args[0]}
   676  	}
   677  	ctx.emit(&format.Event{
   678  		Name:     name,
   679  		Category: category,
   680  		Phase:    "I",
   681  		Scope:    "t",
   682  		Time:     ctx.time(ev),
   683  		TID:      ctx.proc(ev),
   684  		Stack:    ctx.emitter.Stack(ev.Stk),
   685  		Cname:    cname,
   686  		Arg:      arg})
   687  }
   688  
   689  func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
   690  	if ev.Link == nil {
   691  		// The other end of the arrow is not captured in the trace.
   692  		// For example, a goroutine was unblocked but was not scheduled before trace stop.
   693  		return
   694  	}
   695  	if ctx.mode&traceviewer.ModeGoroutineOriented != 0 && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
   696  		return
   697  	}
   698  
   699  	if ev.P == trace.NetpollP || ev.P == trace.TimerP || ev.P == trace.SyscallP {
   700  		// Trace-viewer discards arrows if they don't start/end inside of a slice or instant.
   701  		// So emit a fake instant at the start of the arrow.
   702  		ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock", "")
   703  	}
   704  
   705  	color := ""
   706  	if ctx.mode&traceviewer.ModeTaskOriented != 0 {
   707  		overlapping := false
   708  		// skip non-overlapping arrows.
   709  		for _, task := range ctx.tasks {
   710  			if _, overlapped := task.overlappingDuration(ev); overlapped {
   711  				overlapping = true
   712  				break
   713  			}
   714  		}
   715  		if !overlapping {
   716  			return
   717  		}
   718  	}
   719  
   720  	ctx.arrowSeq++
   721  	ctx.emit(&format.Event{Name: name, Phase: "s", TID: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.emitter.Stack(ev.Stk), Cname: color})
   722  	ctx.emit(&format.Event{Name: name, Phase: "t", TID: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link), Cname: color})
   723  }
   724  
   725  // firstTimestamp returns the timestamp of the first event record.
   726  func firstTimestamp() int64 {
   727  	res, _ := parseTrace()
   728  	if len(res.Events) > 0 {
   729  		return res.Events[0].Ts
   730  	}
   731  	return 0
   732  }
   733  
   734  // lastTimestamp returns the timestamp of the last event record.
   735  func lastTimestamp() int64 {
   736  	res, _ := parseTrace()
   737  	if n := len(res.Events); n > 1 {
   738  		return res.Events[n-1].Ts
   739  	}
   740  	return 0
   741  }
   742  
   743  // Mapping from more reasonable color names to the reserved color names in
   744  // https://github.com/catapult-project/catapult/blob/master/tracing/tracing/base/color_scheme.html#L50
   745  // The chrome trace viewer allows only those as cname values.
   746  const (
   747  	colorLightMauve     = "thread_state_uninterruptible" // 182, 125, 143
   748  	colorOrange         = "thread_state_iowait"          // 255, 140, 0
   749  	colorSeafoamGreen   = "thread_state_running"         // 126, 200, 148
   750  	colorVistaBlue      = "thread_state_runnable"        // 133, 160, 210
   751  	colorTan            = "thread_state_unknown"         // 199, 155, 125
   752  	colorIrisBlue       = "background_memory_dump"       // 0, 180, 180
   753  	colorMidnightBlue   = "light_memory_dump"            // 0, 0, 180
   754  	colorDeepMagenta    = "detailed_memory_dump"         // 180, 0, 180
   755  	colorBlue           = "vsync_highlight_color"        // 0, 0, 255
   756  	colorGrey           = "generic_work"                 // 125, 125, 125
   757  	colorGreen          = "good"                         // 0, 125, 0
   758  	colorDarkGoldenrod  = "bad"                          // 180, 125, 0
   759  	colorPeach          = "terrible"                     // 180, 0, 0
   760  	colorBlack          = "black"                        // 0, 0, 0
   761  	colorLightGrey      = "grey"                         // 221, 221, 221
   762  	colorWhite          = "white"                        // 255, 255, 255
   763  	colorYellow         = "yellow"                       // 255, 255, 0
   764  	colorOlive          = "olive"                        // 100, 100, 0
   765  	colorCornflowerBlue = "rail_response"                // 67, 135, 253
   766  	colorSunsetOrange   = "rail_animation"               // 244, 74, 63
   767  	colorTangerine      = "rail_idle"                    // 238, 142, 0
   768  	colorShamrockGreen  = "rail_load"                    // 13, 168, 97
   769  	colorGreenishYellow = "startup"                      // 230, 230, 0
   770  	colorDarkGrey       = "heap_dump_stack_frame"        // 128, 128, 128
   771  	colorTawny          = "heap_dump_child_node_arrow"   // 204, 102, 0
   772  	colorLemon          = "cq_build_running"             // 255, 255, 119
   773  	colorLime           = "cq_build_passed"              // 153, 238, 102
   774  	colorPink           = "cq_build_failed"              // 238, 136, 136
   775  	colorSilver         = "cq_build_abandoned"           // 187, 187, 187
   776  	colorManzGreen      = "cq_build_attempt_runnig"      // 222, 222, 75
   777  	colorKellyGreen     = "cq_build_attempt_passed"      // 108, 218, 35
   778  	colorAnotherGrey    = "cq_build_attempt_failed"      // 187, 187, 187
   779  )
   780  
   781  var colorForTask = []string{
   782  	colorLightMauve,
   783  	colorOrange,
   784  	colorSeafoamGreen,
   785  	colorVistaBlue,
   786  	colorTan,
   787  	colorMidnightBlue,
   788  	colorIrisBlue,
   789  	colorDeepMagenta,
   790  	colorGreen,
   791  	colorDarkGoldenrod,
   792  	colorPeach,
   793  	colorOlive,
   794  	colorCornflowerBlue,
   795  	colorSunsetOrange,
   796  	colorTangerine,
   797  	colorShamrockGreen,
   798  	colorTawny,
   799  	colorLemon,
   800  	colorLime,
   801  	colorPink,
   802  	colorSilver,
   803  	colorManzGreen,
   804  	colorKellyGreen,
   805  }
   806  
   807  func pickTaskColor(id uint64) string {
   808  	idx := id % uint64(len(colorForTask))
   809  	return colorForTask[idx]
   810  }
   811  

View as plain text