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