summary.go

Documentation: internal/trace

     1  // Copyright 2023 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 trace
     6  
     7  import (
     8  	tracev2 "internal/trace/v2"
     9  	"sort"
    10  	"time"
    11  )
    12  
    13  // Summary is the analysis result produced by the summarizer.
    14  type Summary struct {
    15  	Goroutines map[tracev2.GoID]*GoroutineSummary
    16  	Tasks      map[tracev2.TaskID]*UserTaskSummary
    17  }
    18  
    19  // GoroutineSummary contains statistics and execution details of a single goroutine.
    20  // (For v2 traces.)
    21  type GoroutineSummary struct {
    22  	ID           tracev2.GoID
    23  	Name         string       // A non-unique human-friendly identifier for the goroutine.
    24  	PC           uint64       // The first PC we saw for the entry function of the goroutine
    25  	CreationTime tracev2.Time // Timestamp of the first appearance in the trace.
    26  	StartTime    tracev2.Time // Timestamp of the first time it started running. 0 if the goroutine never ran.
    27  	EndTime      tracev2.Time // Timestamp of when the goroutine exited. 0 if the goroutine never exited.
    28  
    29  	// List of regions in the goroutine, sorted based on the start time.
    30  	Regions []*UserRegionSummary
    31  
    32  	// Statistics of execution time during the goroutine execution.
    33  	GoroutineExecStats
    34  
    35  	// goroutineSummary is state used just for computing this structure.
    36  	// It's dropped before being returned to the caller.
    37  	//
    38  	// More specifically, if it's nil, it indicates that this summary has
    39  	// already been finalized.
    40  	*goroutineSummary
    41  }
    42  
    43  // UserTaskSummary represents a task in the trace.
    44  type UserTaskSummary struct {
    45  	ID       tracev2.TaskID
    46  	Name     string
    47  	Parent   *UserTaskSummary // nil if the parent is unknown.
    48  	Children []*UserTaskSummary
    49  
    50  	// Task begin event. An EventTaskBegin event or nil.
    51  	Start *tracev2.Event
    52  
    53  	// End end event. Normally EventTaskEnd event or nil.
    54  	End *tracev2.Event
    55  
    56  	// Logs is a list of tracev2.EventLog events associated with the task.
    57  	Logs []*tracev2.Event
    58  
    59  	// List of regions in the task, sorted based on the start time.
    60  	Regions []*UserRegionSummary
    61  
    62  	// Goroutines is the set of goroutines associated with this task.
    63  	Goroutines map[tracev2.GoID]*GoroutineSummary
    64  }
    65  
    66  // Complete returns true if we have complete information about the task
    67  // from the trace: both a start and an end.
    68  func (s *UserTaskSummary) Complete() bool {
    69  	return s.Start != nil && s.End != nil
    70  }
    71  
    72  // Descendents returns a slice consisting of itself (always the first task returned),
    73  // and the transitive closure of all of its children.
    74  func (s *UserTaskSummary) Descendents() []*UserTaskSummary {
    75  	descendents := []*UserTaskSummary{s}
    76  	for _, child := range s.Children {
    77  		descendents = append(descendents, child.Descendents()...)
    78  	}
    79  	return descendents
    80  }
    81  
    82  // UserRegionSummary represents a region and goroutine execution stats
    83  // while the region was active. (For v2 traces.)
    84  type UserRegionSummary struct {
    85  	TaskID tracev2.TaskID
    86  	Name   string
    87  
    88  	// Region start event. Normally EventRegionBegin event or nil,
    89  	// but can be a state transition event from NotExist or Undetermined
    90  	// if the region is a synthetic region representing task inheritance
    91  	// from the parent goroutine.
    92  	Start *tracev2.Event
    93  
    94  	// Region end event. Normally EventRegionEnd event or nil,
    95  	// but can be a state transition event to NotExist if the goroutine
    96  	// terminated without explicitly ending the region.
    97  	End *tracev2.Event
    98  
    99  	GoroutineExecStats
   100  }
   101  
   102  // GoroutineExecStats contains statistics about a goroutine's execution
   103  // during a period of time.
   104  type GoroutineExecStats struct {
   105  	// These stats are all non-overlapping.
   106  	ExecTime          time.Duration
   107  	SchedWaitTime     time.Duration
   108  	BlockTimeByReason map[string]time.Duration
   109  	SyscallTime       time.Duration
   110  	SyscallBlockTime  time.Duration
   111  
   112  	// TotalTime is the duration of the goroutine's presence in the trace.
   113  	// Necessarily overlaps with other stats.
   114  	TotalTime time.Duration
   115  
   116  	// Total time the goroutine spent in certain ranges; may overlap
   117  	// with other stats.
   118  	RangeTime map[string]time.Duration
   119  }
   120  
   121  func (s GoroutineExecStats) NonOverlappingStats() map[string]time.Duration {
   122  	stats := map[string]time.Duration{
   123  		"Execution time":         s.ExecTime,
   124  		"Sched wait time":        s.SchedWaitTime,
   125  		"Syscall execution time": s.SyscallTime,
   126  		"Block time (syscall)":   s.SyscallBlockTime,
   127  		"Unknown time":           s.UnknownTime(),
   128  	}
   129  	for reason, dt := range s.BlockTimeByReason {
   130  		stats["Block time ("+reason+")"] += dt
   131  	}
   132  	// N.B. Don't include RangeTime or TotalTime; they overlap with these other
   133  	// stats.
   134  	return stats
   135  }
   136  
   137  // UnknownTime returns whatever isn't accounted for in TotalTime.
   138  func (s GoroutineExecStats) UnknownTime() time.Duration {
   139  	sum := s.ExecTime + s.SchedWaitTime + s.SyscallTime +
   140  		s.SyscallBlockTime
   141  	for _, dt := range s.BlockTimeByReason {
   142  		sum += dt
   143  	}
   144  	// N.B. Don't include range time. Ranges overlap with
   145  	// other stats, whereas these stats are non-overlapping.
   146  	if sum < s.TotalTime {
   147  		return s.TotalTime - sum
   148  	}
   149  	return 0
   150  }
   151  
   152  // sub returns the stats v-s.
   153  func (s GoroutineExecStats) sub(v GoroutineExecStats) (r GoroutineExecStats) {
   154  	r = s.clone()
   155  	r.ExecTime -= v.ExecTime
   156  	r.SchedWaitTime -= v.SchedWaitTime
   157  	for reason := range s.BlockTimeByReason {
   158  		r.BlockTimeByReason[reason] -= v.BlockTimeByReason[reason]
   159  	}
   160  	r.SyscallTime -= v.SyscallTime
   161  	r.SyscallBlockTime -= v.SyscallBlockTime
   162  	r.TotalTime -= v.TotalTime
   163  	for name := range s.RangeTime {
   164  		r.RangeTime[name] -= v.RangeTime[name]
   165  	}
   166  	return r
   167  }
   168  
   169  func (s GoroutineExecStats) clone() (r GoroutineExecStats) {
   170  	r = s
   171  	r.BlockTimeByReason = make(map[string]time.Duration)
   172  	for reason, dt := range s.BlockTimeByReason {
   173  		r.BlockTimeByReason[reason] = dt
   174  	}
   175  	r.RangeTime = make(map[string]time.Duration)
   176  	for name, dt := range s.RangeTime {
   177  		r.RangeTime[name] = dt
   178  	}
   179  	return r
   180  }
   181  
   182  // snapshotStat returns the snapshot of the goroutine execution statistics.
   183  // This is called as we process the ordered trace event stream. lastTs is used
   184  // to process pending statistics if this is called before any goroutine end event.
   185  func (g *GoroutineSummary) snapshotStat(lastTs tracev2.Time) (ret GoroutineExecStats) {
   186  	ret = g.GoroutineExecStats.clone()
   187  
   188  	if g.goroutineSummary == nil {
   189  		return ret // Already finalized; no pending state.
   190  	}
   191  
   192  	// Set the total time if necessary.
   193  	if g.TotalTime == 0 {
   194  		ret.TotalTime = lastTs.Sub(g.CreationTime)
   195  	}
   196  
   197  	// Add in time since lastTs.
   198  	if g.lastStartTime != 0 {
   199  		ret.ExecTime += lastTs.Sub(g.lastStartTime)
   200  	}
   201  	if g.lastRunnableTime != 0 {
   202  		ret.SchedWaitTime += lastTs.Sub(g.lastRunnableTime)
   203  	}
   204  	if g.lastBlockTime != 0 {
   205  		ret.BlockTimeByReason[g.lastBlockReason] += lastTs.Sub(g.lastBlockTime)
   206  	}
   207  	if g.lastSyscallTime != 0 {
   208  		ret.SyscallTime += lastTs.Sub(g.lastSyscallTime)
   209  	}
   210  	if g.lastSyscallBlockTime != 0 {
   211  		ret.SchedWaitTime += lastTs.Sub(g.lastSyscallBlockTime)
   212  	}
   213  	for name, ts := range g.lastRangeTime {
   214  		ret.RangeTime[name] += lastTs.Sub(ts)
   215  	}
   216  	return ret
   217  }
   218  
   219  // finalize is called when processing a goroutine end event or at
   220  // the end of trace processing. This finalizes the execution stat
   221  // and any active regions in the goroutine, in which case trigger is nil.
   222  func (g *GoroutineSummary) finalize(lastTs tracev2.Time, trigger *tracev2.Event) {
   223  	if trigger != nil {
   224  		g.EndTime = trigger.Time()
   225  	}
   226  	finalStat := g.snapshotStat(lastTs)
   227  
   228  	g.GoroutineExecStats = finalStat
   229  
   230  	// System goroutines are never part of regions, even though they
   231  	// "inherit" a task due to creation (EvGoCreate) from within a region.
   232  	// This may happen e.g. if the first GC is triggered within a region,
   233  	// starting the GC worker goroutines.
   234  	if !IsSystemGoroutine(g.Name) {
   235  		for _, s := range g.activeRegions {
   236  			s.End = trigger
   237  			s.GoroutineExecStats = finalStat.sub(s.GoroutineExecStats)
   238  			g.Regions = append(g.Regions, s)
   239  		}
   240  	}
   241  	*(g.goroutineSummary) = goroutineSummary{}
   242  }
   243  
   244  // goroutineSummary is a private part of GoroutineSummary that is required only during analysis.
   245  type goroutineSummary struct {
   246  	lastStartTime        tracev2.Time
   247  	lastRunnableTime     tracev2.Time
   248  	lastBlockTime        tracev2.Time
   249  	lastBlockReason      string
   250  	lastSyscallTime      tracev2.Time
   251  	lastSyscallBlockTime tracev2.Time
   252  	lastRangeTime        map[string]tracev2.Time
   253  	activeRegions        []*UserRegionSummary // stack of active regions
   254  }
   255  
   256  // Summarizer constructs per-goroutine time statistics for v2 traces.
   257  type Summarizer struct {
   258  	// gs contains the map of goroutine summaries we're building up to return to the caller.
   259  	gs map[tracev2.GoID]*GoroutineSummary
   260  
   261  	// tasks contains the map of task summaries we're building up to return to the caller.
   262  	tasks map[tracev2.TaskID]*UserTaskSummary
   263  
   264  	// syscallingP and syscallingG represent a binding between a P and G in a syscall.
   265  	// Used to correctly identify and clean up after syscalls (blocking or otherwise).
   266  	syscallingP map[tracev2.ProcID]tracev2.GoID
   267  	syscallingG map[tracev2.GoID]tracev2.ProcID
   268  
   269  	// rangesP is used for optimistic tracking of P-based ranges for goroutines.
   270  	//
   271  	// It's a best-effort mapping of an active range on a P to the goroutine we think
   272  	// is associated with it.
   273  	rangesP map[rangeP]tracev2.GoID
   274  
   275  	lastTs tracev2.Time // timestamp of the last event processed.
   276  	syncTs tracev2.Time // timestamp of the last sync event processed (or the first timestamp in the trace).
   277  }
   278  
   279  // NewSummarizer creates a new struct to build goroutine stats from a trace.
   280  func NewSummarizer() *Summarizer {
   281  	return &Summarizer{
   282  		gs:          make(map[tracev2.GoID]*GoroutineSummary),
   283  		tasks:       make(map[tracev2.TaskID]*UserTaskSummary),
   284  		syscallingP: make(map[tracev2.ProcID]tracev2.GoID),
   285  		syscallingG: make(map[tracev2.GoID]tracev2.ProcID),
   286  		rangesP:     make(map[rangeP]tracev2.GoID),
   287  	}
   288  }
   289  
   290  type rangeP struct {
   291  	id   tracev2.ProcID
   292  	name string
   293  }
   294  
   295  // Event feeds a single event into the stats summarizer.
   296  func (s *Summarizer) Event(ev *tracev2.Event) {
   297  	if s.syncTs == 0 {
   298  		s.syncTs = ev.Time()
   299  	}
   300  	s.lastTs = ev.Time()
   301  
   302  	switch ev.Kind() {
   303  	// Record sync time for the RangeActive events.
   304  	case tracev2.EventSync:
   305  		s.syncTs = ev.Time()
   306  
   307  	// Handle state transitions.
   308  	case tracev2.EventStateTransition:
   309  		st := ev.StateTransition()
   310  		switch st.Resource.Kind {
   311  		// Handle goroutine transitions, which are the meat of this computation.
   312  		case tracev2.ResourceGoroutine:
   313  			id := st.Resource.Goroutine()
   314  			old, new := st.Goroutine()
   315  			if old == new {
   316  				// Skip these events; they're not telling us anything new.
   317  				break
   318  			}
   319  
   320  			// Handle transition out.
   321  			g := s.gs[id]
   322  			switch old {
   323  			case tracev2.GoUndetermined, tracev2.GoNotExist:
   324  				g = &GoroutineSummary{ID: id, goroutineSummary: &goroutineSummary{}}
   325  				// If we're coming out of GoUndetermined, then the creation time is the
   326  				// time of the last sync.
   327  				if old == tracev2.GoUndetermined {
   328  					g.CreationTime = s.syncTs
   329  				} else {
   330  					g.CreationTime = ev.Time()
   331  				}
   332  				// The goroutine is being created, or it's being named for the first time.
   333  				g.lastRangeTime = make(map[string]tracev2.Time)
   334  				g.BlockTimeByReason = make(map[string]time.Duration)
   335  				g.RangeTime = make(map[string]time.Duration)
   336  
   337  				// When a goroutine is newly created, inherit the task
   338  				// of the active region. For ease handling of this
   339  				// case, we create a fake region description with the
   340  				// task id. This isn't strictly necessary as this
   341  				// goroutine may not be associated with the task, but
   342  				// it can be convenient to see all children created
   343  				// during a region.
   344  				//
   345  				// N.B. ev.Goroutine() will always be NoGoroutine for the
   346  				// Undetermined case, so this is will simply not fire.
   347  				if creatorG := s.gs[ev.Goroutine()]; creatorG != nil && len(creatorG.activeRegions) > 0 {
   348  					regions := creatorG.activeRegions
   349  					s := regions[len(regions)-1]
   350  					g.activeRegions = []*UserRegionSummary{{TaskID: s.TaskID, Start: ev}}
   351  				}
   352  				s.gs[g.ID] = g
   353  			case tracev2.GoRunning:
   354  				// Record execution time as we transition out of running
   355  				g.ExecTime += ev.Time().Sub(g.lastStartTime)
   356  				g.lastStartTime = 0
   357  			case tracev2.GoWaiting:
   358  				// Record block time as we transition out of waiting.
   359  				if g.lastBlockTime != 0 {
   360  					g.BlockTimeByReason[g.lastBlockReason] += ev.Time().Sub(g.lastBlockTime)
   361  					g.lastBlockTime = 0
   362  				}
   363  			case tracev2.GoRunnable:
   364  				// Record sched latency time as we transition out of runnable.
   365  				if g.lastRunnableTime != 0 {
   366  					g.SchedWaitTime += ev.Time().Sub(g.lastRunnableTime)
   367  					g.lastRunnableTime = 0
   368  				}
   369  			case tracev2.GoSyscall:
   370  				// Record syscall execution time and syscall block time as we transition out of syscall.
   371  				if g.lastSyscallTime != 0 {
   372  					if g.lastSyscallBlockTime != 0 {
   373  						g.SyscallBlockTime += ev.Time().Sub(g.lastSyscallBlockTime)
   374  						g.SyscallTime += g.lastSyscallBlockTime.Sub(g.lastSyscallTime)
   375  					} else {
   376  						g.SyscallTime += ev.Time().Sub(g.lastSyscallTime)
   377  					}
   378  					g.lastSyscallTime = 0
   379  					g.lastSyscallBlockTime = 0
   380  
   381  					// Clear the syscall map.
   382  					delete(s.syscallingP, s.syscallingG[id])
   383  					delete(s.syscallingG, id)
   384  				}
   385  			}
   386  
   387  			// The goroutine hasn't been identified yet. Take the transition stack
   388  			// and identify the goroutine by the root frame of that stack.
   389  			// This root frame will be identical for all transitions on this
   390  			// goroutine, because it represents its immutable start point.
   391  			if g.Name == "" {
   392  				stk := st.Stack
   393  				if stk != tracev2.NoStack {
   394  					var frame tracev2.StackFrame
   395  					var ok bool
   396  					stk.Frames(func(f tracev2.StackFrame) bool {
   397  						frame = f
   398  						ok = true
   399  						return true
   400  					})
   401  					if ok {
   402  						// NB: this PC won't actually be consistent for
   403  						// goroutines which existed at the start of the
   404  						// trace. The UI doesn't use it directly; this
   405  						// mainly serves as an indication that we
   406  						// actually saw a call stack for the goroutine
   407  						g.PC = frame.PC
   408  						g.Name = frame.Func
   409  					}
   410  				}
   411  			}
   412  
   413  			// Handle transition in.
   414  			switch new {
   415  			case tracev2.GoRunning:
   416  				// We started running. Record it.
   417  				g.lastStartTime = ev.Time()
   418  				if g.StartTime == 0 {
   419  					g.StartTime = ev.Time()
   420  				}
   421  			case tracev2.GoRunnable:
   422  				g.lastRunnableTime = ev.Time()
   423  			case tracev2.GoWaiting:
   424  				if st.Reason != "forever" {
   425  					g.lastBlockTime = ev.Time()
   426  					g.lastBlockReason = st.Reason
   427  					break
   428  				}
   429  				// "Forever" is like goroutine death.
   430  				fallthrough
   431  			case tracev2.GoNotExist:
   432  				g.finalize(ev.Time(), ev)
   433  			case tracev2.GoSyscall:
   434  				s.syscallingP[ev.Proc()] = id
   435  				s.syscallingG[id] = ev.Proc()
   436  				g.lastSyscallTime = ev.Time()
   437  			}
   438  
   439  		// Handle procs to detect syscall blocking, which si identifiable as a
   440  		// proc going idle while the goroutine it was attached to is in a syscall.
   441  		case tracev2.ResourceProc:
   442  			id := st.Resource.Proc()
   443  			old, new := st.Proc()
   444  			if old != new && new == tracev2.ProcIdle {
   445  				if goid, ok := s.syscallingP[id]; ok {
   446  					g := s.gs[goid]
   447  					g.lastSyscallBlockTime = ev.Time()
   448  					delete(s.syscallingP, id)
   449  				}
   450  			}
   451  		}
   452  
   453  	// Handle ranges of all kinds.
   454  	case tracev2.EventRangeBegin, tracev2.EventRangeActive:
   455  		r := ev.Range()
   456  		var g *GoroutineSummary
   457  		switch r.Scope.Kind {
   458  		case tracev2.ResourceGoroutine:
   459  			// Simple goroutine range. We attribute the entire range regardless of
   460  			// goroutine stats. Lots of situations are still identifiable, e.g. a
   461  			// goroutine blocked often in mark assist will have both high mark assist
   462  			// and high block times. Those interested in a deeper view can look at the
   463  			// trace viewer.
   464  			g = s.gs[r.Scope.Goroutine()]
   465  		case tracev2.ResourceProc:
   466  			// N.B. These ranges are not actually bound to the goroutine, they're
   467  			// bound to the P. But if we happen to be on the P the whole time, let's
   468  			// try to attribute it to the goroutine. (e.g. GC sweeps are here.)
   469  			g = s.gs[ev.Goroutine()]
   470  			if g != nil {
   471  				s.rangesP[rangeP{id: r.Scope.Proc(), name: r.Name}] = ev.Goroutine()
   472  			}
   473  		}
   474  		if g == nil {
   475  			break
   476  		}
   477  		if ev.Kind() == tracev2.EventRangeActive {
   478  			if ts := g.lastRangeTime[r.Name]; ts != 0 {
   479  				g.RangeTime[r.Name] += s.syncTs.Sub(ts)
   480  			}
   481  			g.lastRangeTime[r.Name] = s.syncTs
   482  		} else {
   483  			g.lastRangeTime[r.Name] = ev.Time()
   484  		}
   485  	case tracev2.EventRangeEnd:
   486  		r := ev.Range()
   487  		var g *GoroutineSummary
   488  		switch r.Scope.Kind {
   489  		case tracev2.ResourceGoroutine:
   490  			g = s.gs[r.Scope.Goroutine()]
   491  		case tracev2.ResourceProc:
   492  			rp := rangeP{id: r.Scope.Proc(), name: r.Name}
   493  			if goid, ok := s.rangesP[rp]; ok {
   494  				if goid == ev.Goroutine() {
   495  					// As the comment in the RangeBegin case states, this is only OK
   496  					// if we finish on the same goroutine we started on.
   497  					g = s.gs[goid]
   498  				}
   499  				delete(s.rangesP, rp)
   500  			}
   501  		}
   502  		if g == nil {
   503  			break
   504  		}
   505  		ts := g.lastRangeTime[r.Name]
   506  		if ts == 0 {
   507  			break
   508  		}
   509  		g.RangeTime[r.Name] += ev.Time().Sub(ts)
   510  		delete(g.lastRangeTime, r.Name)
   511  
   512  	// Handle user-defined regions.
   513  	case tracev2.EventRegionBegin:
   514  		g := s.gs[ev.Goroutine()]
   515  		r := ev.Region()
   516  		region := &UserRegionSummary{
   517  			Name:               r.Type,
   518  			TaskID:             r.Task,
   519  			Start:              ev,
   520  			GoroutineExecStats: g.snapshotStat(ev.Time()),
   521  		}
   522  		g.activeRegions = append(g.activeRegions, region)
   523  		// Associate the region and current goroutine to the task.
   524  		task := s.getOrAddTask(r.Task)
   525  		task.Regions = append(task.Regions, region)
   526  		task.Goroutines[g.ID] = g
   527  	case tracev2.EventRegionEnd:
   528  		g := s.gs[ev.Goroutine()]
   529  		r := ev.Region()
   530  		var sd *UserRegionSummary
   531  		if regionStk := g.activeRegions; len(regionStk) > 0 {
   532  			// Pop the top region from the stack since that's what must have ended.
   533  			n := len(regionStk)
   534  			sd = regionStk[n-1]
   535  			regionStk = regionStk[:n-1]
   536  			g.activeRegions = regionStk
   537  			// N.B. No need to add the region to a task; the EventRegionBegin already handled it.
   538  		} else {
   539  			// This is an "end" without a start. Just fabricate the region now.
   540  			sd = &UserRegionSummary{Name: r.Type, TaskID: r.Task}
   541  			// Associate the region and current goroutine to the task.
   542  			task := s.getOrAddTask(r.Task)
   543  			task.Goroutines[g.ID] = g
   544  			task.Regions = append(task.Regions, sd)
   545  		}
   546  		sd.GoroutineExecStats = g.snapshotStat(ev.Time()).sub(sd.GoroutineExecStats)
   547  		sd.End = ev
   548  		g.Regions = append(g.Regions, sd)
   549  
   550  	// Handle tasks and logs.
   551  	case tracev2.EventTaskBegin, tracev2.EventTaskEnd:
   552  		// Initialize the task.
   553  		t := ev.Task()
   554  		task := s.getOrAddTask(t.ID)
   555  		task.Name = t.Type
   556  		task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
   557  		if ev.Kind() == tracev2.EventTaskBegin {
   558  			task.Start = ev
   559  		} else {
   560  			task.End = ev
   561  		}
   562  		// Initialize the parent, if one exists and it hasn't been done yet.
   563  		// We need to avoid doing it twice, otherwise we could appear twice
   564  		// in the parent's Children list.
   565  		if t.Parent != tracev2.NoTask && task.Parent == nil {
   566  			parent := s.getOrAddTask(t.Parent)
   567  			task.Parent = parent
   568  			parent.Children = append(parent.Children, task)
   569  		}
   570  	case tracev2.EventLog:
   571  		log := ev.Log()
   572  		// Just add the log to the task. We'll create the task if it
   573  		// doesn't exist (it's just been mentioned now).
   574  		task := s.getOrAddTask(log.Task)
   575  		task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
   576  		task.Logs = append(task.Logs, ev)
   577  	}
   578  }
   579  
   580  func (s *Summarizer) getOrAddTask(id tracev2.TaskID) *UserTaskSummary {
   581  	task := s.tasks[id]
   582  	if task == nil {
   583  		task = &UserTaskSummary{ID: id, Goroutines: make(map[tracev2.GoID]*GoroutineSummary)}
   584  		s.tasks[id] = task
   585  	}
   586  	return task
   587  }
   588  
   589  // Finalize indicates to the summarizer that we're done processing the trace.
   590  // It cleans up any remaining state and returns the full summary.
   591  func (s *Summarizer) Finalize() *Summary {
   592  	for _, g := range s.gs {
   593  		g.finalize(s.lastTs, nil)
   594  
   595  		// Sort based on region start time.
   596  		sort.Slice(g.Regions, func(i, j int) bool {
   597  			x := g.Regions[i].Start
   598  			y := g.Regions[j].Start
   599  			if x == nil {
   600  				return true
   601  			}
   602  			if y == nil {
   603  				return false
   604  			}
   605  			return x.Time() < y.Time()
   606  		})
   607  		g.goroutineSummary = nil
   608  	}
   609  	return &Summary{
   610  		Goroutines: s.gs,
   611  		Tasks:      s.tasks,
   612  	}
   613  }
   614  
   615  // RelatedGoroutinesV2 finds a set of goroutines related to goroutine goid for v2 traces.
   616  // The association is based on whether they have synchronized with each other in the Go
   617  // scheduler (one has unblocked another).
   618  func RelatedGoroutinesV2(events []tracev2.Event, goid tracev2.GoID) map[tracev2.GoID]struct{} {
   619  	// Process all the events, looking for transitions of goroutines
   620  	// out of GoWaiting. If there was an active goroutine when this
   621  	// happened, then we know that active goroutine unblocked another.
   622  	// Scribble all these down so we can process them.
   623  	type unblockEdge struct {
   624  		operator tracev2.GoID
   625  		operand  tracev2.GoID
   626  	}
   627  	var unblockEdges []unblockEdge
   628  	for _, ev := range events {
   629  		if ev.Goroutine() == tracev2.NoGoroutine {
   630  			continue
   631  		}
   632  		if ev.Kind() != tracev2.EventStateTransition {
   633  			continue
   634  		}
   635  		st := ev.StateTransition()
   636  		if st.Resource.Kind != tracev2.ResourceGoroutine {
   637  			continue
   638  		}
   639  		id := st.Resource.Goroutine()
   640  		old, new := st.Goroutine()
   641  		if old == new || old != tracev2.GoWaiting {
   642  			continue
   643  		}
   644  		unblockEdges = append(unblockEdges, unblockEdge{
   645  			operator: ev.Goroutine(),
   646  			operand:  id,
   647  		})
   648  	}
   649  	// Compute the transitive closure of depth 2 of goroutines that have unblocked each other
   650  	// (starting from goid).
   651  	gmap := make(map[tracev2.GoID]struct{})
   652  	gmap[goid] = struct{}{}
   653  	for i := 0; i < 2; i++ {
   654  		// Copy the map.
   655  		gmap1 := make(map[tracev2.GoID]struct{})
   656  		for g := range gmap {
   657  			gmap1[g] = struct{}{}
   658  		}
   659  		for _, edge := range unblockEdges {
   660  			if _, ok := gmap[edge.operand]; ok {
   661  				gmap1[edge.operator] = struct{}{}
   662  			}
   663  		}
   664  		gmap = gmap1
   665  	}
   666  	return gmap
   667  }
   668
View as plain text