goroutines.go

Documentation: internal/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 trace
     6  
     7  import (
     8  	"sort"
     9  	"strings"
    10  )
    11  
    12  // GDesc contains statistics and execution details of a single goroutine.
    13  type GDesc struct {
    14  	ID           uint64
    15  	Name         string
    16  	PC           uint64
    17  	CreationTime int64
    18  	StartTime    int64
    19  	EndTime      int64
    20  
    21  	// List of regions in the goroutine, sorted based on the start time.
    22  	Regions []*UserRegionDesc
    23  
    24  	// Statistics of execution time during the goroutine execution.
    25  	GExecutionStat
    26  
    27  	*gdesc // private part.
    28  }
    29  
    30  // UserRegionDesc represents a region and goroutine execution stats
    31  // while the region was active.
    32  type UserRegionDesc struct {
    33  	TaskID uint64
    34  	Name   string
    35  
    36  	// Region start event. Normally EvUserRegion start event or nil,
    37  	// but can be EvGoCreate event if the region is a synthetic
    38  	// region representing task inheritance from the parent goroutine.
    39  	Start *Event
    40  
    41  	// Region end event. Normally EvUserRegion end event or nil,
    42  	// but can be EvGoStop or EvGoEnd event if the goroutine
    43  	// terminated without explicitly ending the region.
    44  	End *Event
    45  
    46  	GExecutionStat
    47  }
    48  
    49  // GExecutionStat contains statistics about a goroutine's execution
    50  // during a period of time.
    51  type GExecutionStat struct {
    52  	ExecTime      int64
    53  	SchedWaitTime int64
    54  	IOTime        int64
    55  	BlockTime     int64
    56  	SyscallTime   int64
    57  	GCTime        int64
    58  	SweepTime     int64
    59  	TotalTime     int64
    60  }
    61  
    62  // sub returns the stats v-s.
    63  func (s GExecutionStat) sub(v GExecutionStat) (r GExecutionStat) {
    64  	r = s
    65  	r.ExecTime -= v.ExecTime
    66  	r.SchedWaitTime -= v.SchedWaitTime
    67  	r.IOTime -= v.IOTime
    68  	r.BlockTime -= v.BlockTime
    69  	r.SyscallTime -= v.SyscallTime
    70  	r.GCTime -= v.GCTime
    71  	r.SweepTime -= v.SweepTime
    72  	r.TotalTime -= v.TotalTime
    73  	return r
    74  }
    75  
    76  // snapshotStat returns the snapshot of the goroutine execution statistics.
    77  // This is called as we process the ordered trace event stream. lastTs and
    78  // activeGCStartTime are used to process pending statistics if this is called
    79  // before any goroutine end event.
    80  func (g *GDesc) snapshotStat(lastTs, activeGCStartTime int64) (ret GExecutionStat) {
    81  	ret = g.GExecutionStat
    82  
    83  	if g.gdesc == nil {
    84  		return ret // finalized GDesc. No pending state.
    85  	}
    86  
    87  	if activeGCStartTime != 0 { // terminating while GC is active
    88  		if g.CreationTime < activeGCStartTime {
    89  			ret.GCTime += lastTs - activeGCStartTime
    90  		} else {
    91  			// The goroutine's lifetime completely overlaps
    92  			// with a GC.
    93  			ret.GCTime += lastTs - g.CreationTime
    94  		}
    95  	}
    96  
    97  	if g.TotalTime == 0 {
    98  		ret.TotalTime = lastTs - g.CreationTime
    99  	}
   100  
   101  	if g.lastStartTime != 0 {
   102  		ret.ExecTime += lastTs - g.lastStartTime
   103  	}
   104  	if g.blockNetTime != 0 {
   105  		ret.IOTime += lastTs - g.blockNetTime
   106  	}
   107  	if g.blockSyncTime != 0 {
   108  		ret.BlockTime += lastTs - g.blockSyncTime
   109  	}
   110  	if g.blockSyscallTime != 0 {
   111  		ret.SyscallTime += lastTs - g.blockSyscallTime
   112  	}
   113  	if g.blockSchedTime != 0 {
   114  		ret.SchedWaitTime += lastTs - g.blockSchedTime
   115  	}
   116  	if g.blockSweepTime != 0 {
   117  		ret.SweepTime += lastTs - g.blockSweepTime
   118  	}
   119  	return ret
   120  }
   121  
   122  // finalize is called when processing a goroutine end event or at
   123  // the end of trace processing. This finalizes the execution stat
   124  // and any active regions in the goroutine, in which case trigger is nil.
   125  func (g *GDesc) finalize(lastTs, activeGCStartTime int64, trigger *Event) {
   126  	if trigger != nil {
   127  		g.EndTime = trigger.Ts
   128  	}
   129  	finalStat := g.snapshotStat(lastTs, activeGCStartTime)
   130  
   131  	g.GExecutionStat = finalStat
   132  
   133  	// System goroutines are never part of regions, even though they
   134  	// "inherit" a task due to creation (EvGoCreate) from within a region.
   135  	// This may happen e.g. if the first GC is triggered within a region,
   136  	// starting the GC worker goroutines.
   137  	if !IsSystemGoroutine(g.Name) {
   138  		for _, s := range g.activeRegions {
   139  			s.End = trigger
   140  			s.GExecutionStat = finalStat.sub(s.GExecutionStat)
   141  			g.Regions = append(g.Regions, s)
   142  		}
   143  	}
   144  	*(g.gdesc) = gdesc{}
   145  }
   146  
   147  // gdesc is a private part of GDesc that is required only during analysis.
   148  type gdesc struct {
   149  	lastStartTime    int64
   150  	blockNetTime     int64
   151  	blockSyncTime    int64
   152  	blockSyscallTime int64
   153  	blockSweepTime   int64
   154  	blockGCTime      int64
   155  	blockSchedTime   int64
   156  
   157  	activeRegions []*UserRegionDesc // stack of active regions
   158  }
   159  
   160  // GoroutineStats generates statistics for all goroutines in the trace.
   161  func GoroutineStats(events []*Event) map[uint64]*GDesc {
   162  	gs := make(map[uint64]*GDesc)
   163  	var lastTs int64
   164  	var gcStartTime int64 // gcStartTime == 0 indicates gc is inactive.
   165  	for _, ev := range events {
   166  		lastTs = ev.Ts
   167  		switch ev.Type {
   168  		case EvGoCreate:
   169  			g := &GDesc{ID: ev.Args[0], CreationTime: ev.Ts, gdesc: new(gdesc)}
   170  			g.blockSchedTime = ev.Ts
   171  			// When a goroutine is newly created, inherit the task
   172  			// of the active region. For ease handling of this
   173  			// case, we create a fake region description with the
   174  			// task id. This isn't strictly necessary as this
   175  			// goroutine may not be associated with the task, but
   176  			// it can be convenient to see all children created
   177  			// during a region.
   178  			if creatorG := gs[ev.G]; creatorG != nil && len(creatorG.gdesc.activeRegions) > 0 {
   179  				regions := creatorG.gdesc.activeRegions
   180  				s := regions[len(regions)-1]
   181  				if s.TaskID != 0 {
   182  					g.gdesc.activeRegions = []*UserRegionDesc{
   183  						{TaskID: s.TaskID, Start: ev},
   184  					}
   185  				}
   186  			}
   187  			gs[g.ID] = g
   188  		case EvGoStart, EvGoStartLabel:
   189  			g := gs[ev.G]
   190  			if g.PC == 0 && len(ev.Stk) > 0 {
   191  				g.PC = ev.Stk[0].PC
   192  				g.Name = ev.Stk[0].Fn
   193  			}
   194  			g.lastStartTime = ev.Ts
   195  			if g.StartTime == 0 {
   196  				g.StartTime = ev.Ts
   197  			}
   198  			if g.blockSchedTime != 0 {
   199  				g.SchedWaitTime += ev.Ts - g.blockSchedTime
   200  				g.blockSchedTime = 0
   201  			}
   202  		case EvGoEnd, EvGoStop:
   203  			g := gs[ev.G]
   204  			g.finalize(ev.Ts, gcStartTime, ev)
   205  		case EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
   206  			EvGoBlockSync, EvGoBlockCond:
   207  			g := gs[ev.G]
   208  			g.ExecTime += ev.Ts - g.lastStartTime
   209  			g.lastStartTime = 0
   210  			g.blockSyncTime = ev.Ts
   211  		case EvGoSched, EvGoPreempt:
   212  			g := gs[ev.G]
   213  			g.ExecTime += ev.Ts - g.lastStartTime
   214  			g.lastStartTime = 0
   215  			g.blockSchedTime = ev.Ts
   216  		case EvGoSleep, EvGoBlock:
   217  			g := gs[ev.G]
   218  			g.ExecTime += ev.Ts - g.lastStartTime
   219  			g.lastStartTime = 0
   220  		case EvGoBlockNet:
   221  			g := gs[ev.G]
   222  			g.ExecTime += ev.Ts - g.lastStartTime
   223  			g.lastStartTime = 0
   224  			g.blockNetTime = ev.Ts
   225  		case EvGoBlockGC:
   226  			g := gs[ev.G]
   227  			g.ExecTime += ev.Ts - g.lastStartTime
   228  			g.lastStartTime = 0
   229  			g.blockGCTime = ev.Ts
   230  		case EvGoUnblock:
   231  			g := gs[ev.Args[0]]
   232  			if g.blockNetTime != 0 {
   233  				g.IOTime += ev.Ts - g.blockNetTime
   234  				g.blockNetTime = 0
   235  			}
   236  			if g.blockSyncTime != 0 {
   237  				g.BlockTime += ev.Ts - g.blockSyncTime
   238  				g.blockSyncTime = 0
   239  			}
   240  			g.blockSchedTime = ev.Ts
   241  		case EvGoSysBlock:
   242  			g := gs[ev.G]
   243  			g.ExecTime += ev.Ts - g.lastStartTime
   244  			g.lastStartTime = 0
   245  			g.blockSyscallTime = ev.Ts
   246  		case EvGoSysExit:
   247  			g := gs[ev.G]
   248  			if g.blockSyscallTime != 0 {
   249  				g.SyscallTime += ev.Ts - g.blockSyscallTime
   250  				g.blockSyscallTime = 0
   251  			}
   252  			g.blockSchedTime = ev.Ts
   253  		case EvGCSweepStart:
   254  			g := gs[ev.G]
   255  			if g != nil {
   256  				// Sweep can happen during GC on system goroutine.
   257  				g.blockSweepTime = ev.Ts
   258  			}
   259  		case EvGCSweepDone:
   260  			g := gs[ev.G]
   261  			if g != nil && g.blockSweepTime != 0 {
   262  				g.SweepTime += ev.Ts - g.blockSweepTime
   263  				g.blockSweepTime = 0
   264  			}
   265  		case EvGCStart:
   266  			gcStartTime = ev.Ts
   267  		case EvGCDone:
   268  			for _, g := range gs {
   269  				if g.EndTime != 0 {
   270  					continue
   271  				}
   272  				if gcStartTime < g.CreationTime {
   273  					g.GCTime += ev.Ts - g.CreationTime
   274  				} else {
   275  					g.GCTime += ev.Ts - gcStartTime
   276  				}
   277  			}
   278  			gcStartTime = 0 // indicates gc is inactive.
   279  		case EvUserRegion:
   280  			g := gs[ev.G]
   281  			switch mode := ev.Args[1]; mode {
   282  			case 0: // region start
   283  				g.activeRegions = append(g.activeRegions, &UserRegionDesc{
   284  					Name:           ev.SArgs[0],
   285  					TaskID:         ev.Args[0],
   286  					Start:          ev,
   287  					GExecutionStat: g.snapshotStat(lastTs, gcStartTime),
   288  				})
   289  			case 1: // region end
   290  				var sd *UserRegionDesc
   291  				if regionStk := g.activeRegions; len(regionStk) > 0 {
   292  					n := len(regionStk)
   293  					sd = regionStk[n-1]
   294  					regionStk = regionStk[:n-1] // pop
   295  					g.activeRegions = regionStk
   296  				} else {
   297  					sd = &UserRegionDesc{
   298  						Name:   ev.SArgs[0],
   299  						TaskID: ev.Args[0],
   300  					}
   301  				}
   302  				sd.GExecutionStat = g.snapshotStat(lastTs, gcStartTime).sub(sd.GExecutionStat)
   303  				sd.End = ev
   304  				g.Regions = append(g.Regions, sd)
   305  			}
   306  		}
   307  	}
   308  
   309  	for _, g := range gs {
   310  		g.finalize(lastTs, gcStartTime, nil)
   311  
   312  		// sort based on region start time
   313  		sort.Slice(g.Regions, func(i, j int) bool {
   314  			x := g.Regions[i].Start
   315  			y := g.Regions[j].Start
   316  			if x == nil {
   317  				return true
   318  			}
   319  			if y == nil {
   320  				return false
   321  			}
   322  			return x.Ts < y.Ts
   323  		})
   324  
   325  		g.gdesc = nil
   326  	}
   327  
   328  	return gs
   329  }
   330  
   331  // RelatedGoroutines finds a set of goroutines related to goroutine goid.
   332  func RelatedGoroutines(events []*Event, goid uint64) map[uint64]bool {
   333  	// BFS of depth 2 over "unblock" edges
   334  	// (what goroutines unblock goroutine goid?).
   335  	gmap := make(map[uint64]bool)
   336  	gmap[goid] = true
   337  	for i := 0; i < 2; i++ {
   338  		gmap1 := make(map[uint64]bool)
   339  		for g := range gmap {
   340  			gmap1[g] = true
   341  		}
   342  		for _, ev := range events {
   343  			if ev.Type == EvGoUnblock && gmap[ev.Args[0]] {
   344  				gmap1[ev.G] = true
   345  			}
   346  		}
   347  		gmap = gmap1
   348  	}
   349  	gmap[0] = true // for GC events
   350  	return gmap
   351  }
   352  
   353  func IsSystemGoroutine(entryFn string) bool {
   354  	// This mimics runtime.isSystemGoroutine as closely as
   355  	// possible.
   356  	// Also, locked g in extra M (with empty entryFn) is system goroutine.
   357  	return entryFn == "" || entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.")
   358  }
   359
View as plain text