gstate.go

Documentation: cmd/trace/v2

     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  	"fmt"
     9  	"internal/trace"
    10  	"internal/trace/traceviewer"
    11  	"internal/trace/traceviewer/format"
    12  	tracev2 "internal/trace/v2"
    13  	"strings"
    14  )
    15  
    16  // resource is a generic constraint interface for resource IDs.
    17  type resource interface {
    18  	tracev2.GoID | tracev2.ProcID | tracev2.ThreadID
    19  }
    20  
    21  // noResource indicates the lack of a resource.
    22  const noResource = -1
    23  
    24  // gState represents the trace viewer state of a goroutine in a trace.
    25  //
    26  // The type parameter on this type is the resource which is used to construct
    27  // a timeline of events. e.g. R=ProcID for a proc-oriented view, R=GoID for
    28  // a goroutine-oriented view, etc.
    29  type gState[R resource] struct {
    30  	baseName  string
    31  	named     bool   // Whether baseName has been set.
    32  	label     string // EventLabel extension.
    33  	isSystemG bool
    34  
    35  	executing R // The resource this goroutine is executing on. (Could be itself.)
    36  
    37  	// lastStopStack is the stack trace at the point of the last
    38  	// call to the stop method. This tends to be a more reliable way
    39  	// of picking up stack traces, since the parser doesn't provide
    40  	// a stack for every state transition event.
    41  	lastStopStack tracev2.Stack
    42  
    43  	// activeRanges is the set of all active ranges on the goroutine.
    44  	activeRanges map[string]activeRange
    45  
    46  	// completedRanges is a list of ranges that completed since before the
    47  	// goroutine stopped executing. These are flushed on every stop or block.
    48  	completedRanges []completedRange
    49  
    50  	// startRunning is the most recent event that caused a goroutine to
    51  	// transition to GoRunning.
    52  	startRunningTime tracev2.Time
    53  
    54  	// startSyscall is the most recent event that caused a goroutine to
    55  	// transition to GoSyscall.
    56  	syscall struct {
    57  		time   tracev2.Time
    58  		stack  tracev2.Stack
    59  		active bool
    60  	}
    61  
    62  	// startBlockReason is the StateTransition.Reason of the most recent
    63  	// event that caused a gorotuine to transition to GoWaiting.
    64  	startBlockReason string
    65  
    66  	// startCause is the event that allowed this goroutine to start running.
    67  	// It's used to generate flow events. This is typically something like
    68  	// an unblock event or a goroutine creation event.
    69  	//
    70  	// startCause.resource is the resource on which startCause happened, but is
    71  	// listed separately because the cause may have happened on a resource that
    72  	// isn't R (or perhaps on some abstract nebulous resource, like trace.NetpollP).
    73  	startCause struct {
    74  		time     tracev2.Time
    75  		name     string
    76  		resource uint64
    77  		stack    tracev2.Stack
    78  	}
    79  }
    80  
    81  // newGState constructs a new goroutine state for the goroutine
    82  // identified by the provided ID.
    83  func newGState[R resource](goID tracev2.GoID) *gState[R] {
    84  	return &gState[R]{
    85  		baseName:     fmt.Sprintf("G%d", goID),
    86  		executing:    R(noResource),
    87  		activeRanges: make(map[string]activeRange),
    88  	}
    89  }
    90  
    91  // augmentName attempts to use stk to augment the name of the goroutine
    92  // with stack information. This stack must be related to the goroutine
    93  // in some way, but it doesn't really matter which stack.
    94  func (gs *gState[R]) augmentName(stk tracev2.Stack) {
    95  	if gs.named {
    96  		return
    97  	}
    98  	if stk == tracev2.NoStack {
    99  		return
   100  	}
   101  	name := lastFunc(stk)
   102  	gs.baseName += fmt.Sprintf(" %s", name)
   103  	gs.named = true
   104  	gs.isSystemG = trace.IsSystemGoroutine(name)
   105  }
   106  
   107  // setLabel adds an additional label to the goroutine's name.
   108  func (gs *gState[R]) setLabel(label string) {
   109  	gs.label = label
   110  }
   111  
   112  // name returns a name for the goroutine.
   113  func (gs *gState[R]) name() string {
   114  	name := gs.baseName
   115  	if gs.label != "" {
   116  		name += " (" + gs.label + ")"
   117  	}
   118  	return name
   119  }
   120  
   121  // setStartCause sets the reason a goroutine will be allowed to start soon.
   122  // For example, via unblocking or exiting a blocked syscall.
   123  func (gs *gState[R]) setStartCause(ts tracev2.Time, name string, resource uint64, stack tracev2.Stack) {
   124  	gs.startCause.time = ts
   125  	gs.startCause.name = name
   126  	gs.startCause.resource = resource
   127  	gs.startCause.stack = stack
   128  }
   129  
   130  // created indicates that this goroutine was just created by the provided creator.
   131  func (gs *gState[R]) created(ts tracev2.Time, creator R, stack tracev2.Stack) {
   132  	if creator == R(noResource) {
   133  		return
   134  	}
   135  	gs.setStartCause(ts, "go", uint64(creator), stack)
   136  }
   137  
   138  // start indicates that a goroutine has started running on a proc.
   139  func (gs *gState[R]) start(ts tracev2.Time, resource R, ctx *traceContext) {
   140  	// Set the time for all the active ranges.
   141  	for name := range gs.activeRanges {
   142  		gs.activeRanges[name] = activeRange{ts, tracev2.NoStack}
   143  	}
   144  
   145  	if gs.startCause.name != "" {
   146  		// It has a start cause. Emit a flow event.
   147  		ctx.Arrow(traceviewer.ArrowEvent{
   148  			Name:         gs.startCause.name,
   149  			Start:        ctx.elapsed(gs.startCause.time),
   150  			End:          ctx.elapsed(ts),
   151  			FromResource: uint64(gs.startCause.resource),
   152  			ToResource:   uint64(resource),
   153  			FromStack:    ctx.Stack(viewerFrames(gs.startCause.stack)),
   154  		})
   155  		gs.startCause.time = 0
   156  		gs.startCause.name = ""
   157  		gs.startCause.resource = 0
   158  		gs.startCause.stack = tracev2.NoStack
   159  	}
   160  	gs.executing = resource
   161  	gs.startRunningTime = ts
   162  }
   163  
   164  // syscallBegin indicates that the goroutine entered a syscall on a proc.
   165  func (gs *gState[R]) syscallBegin(ts tracev2.Time, resource R, stack tracev2.Stack) {
   166  	gs.syscall.time = ts
   167  	gs.syscall.stack = stack
   168  	gs.syscall.active = true
   169  	if gs.executing == R(noResource) {
   170  		gs.executing = resource
   171  		gs.startRunningTime = ts
   172  	}
   173  }
   174  
   175  // syscallEnd ends the syscall slice, wherever the syscall is at. This is orthogonal
   176  // to blockedSyscallEnd -- both must be called when a syscall ends and that syscall
   177  // blocked. They're kept separate because syscallEnd indicates the point at which the
   178  // goroutine is no longer executing on the resource (e.g. a proc) whereas blockedSyscallEnd
   179  // is the point at which the goroutine actually exited the syscall regardless of which
   180  // resource that happened on.
   181  func (gs *gState[R]) syscallEnd(ts tracev2.Time, blocked bool, ctx *traceContext) {
   182  	if !gs.syscall.active {
   183  		return
   184  	}
   185  	blockString := "no"
   186  	if blocked {
   187  		blockString = "yes"
   188  	}
   189  	gs.completedRanges = append(gs.completedRanges, completedRange{
   190  		name:       "syscall",
   191  		startTime:  gs.syscall.time,
   192  		endTime:    ts,
   193  		startStack: gs.syscall.stack,
   194  		arg:        format.BlockedArg{Blocked: blockString},
   195  	})
   196  	gs.syscall.active = false
   197  	gs.syscall.time = 0
   198  	gs.syscall.stack = tracev2.NoStack
   199  }
   200  
   201  // blockedSyscallEnd indicates the point at which the blocked syscall ended. This is distinct
   202  // and orthogonal to syscallEnd; both must be called if the syscall blocked. This sets up an instant
   203  // to emit a flow event from, indicating explicitly that this goroutine was unblocked by the system.
   204  func (gs *gState[R]) blockedSyscallEnd(ts tracev2.Time, stack tracev2.Stack, ctx *traceContext) {
   205  	name := "exit blocked syscall"
   206  	gs.setStartCause(ts, name, trace.SyscallP, stack)
   207  
   208  	// Emit an syscall exit instant event for the "Syscall" lane.
   209  	ctx.Instant(traceviewer.InstantEvent{
   210  		Name:     name,
   211  		Ts:       ctx.elapsed(ts),
   212  		Resource: trace.SyscallP,
   213  		Stack:    ctx.Stack(viewerFrames(stack)),
   214  	})
   215  }
   216  
   217  // unblock indicates that the goroutine gs represents has been unblocked.
   218  func (gs *gState[R]) unblock(ts tracev2.Time, stack tracev2.Stack, resource R, ctx *traceContext) {
   219  	name := "unblock"
   220  	viewerResource := uint64(resource)
   221  	if gs.startBlockReason != "" {
   222  		name = fmt.Sprintf("%s (%s)", name, gs.startBlockReason)
   223  	}
   224  	if strings.Contains(gs.startBlockReason, "network") {
   225  		// Attribute the network instant to the nebulous "NetpollP" if
   226  		// resource isn't a thread, because there's a good chance that
   227  		// resource isn't going to be valid in this case.
   228  		//
   229  		// TODO(mknyszek): Handle this invalidness in a more general way.
   230  		if _, ok := any(resource).(tracev2.ThreadID); !ok {
   231  			// Emit an unblock instant event for the "Network" lane.
   232  			viewerResource = trace.NetpollP
   233  		}
   234  		ctx.Instant(traceviewer.InstantEvent{
   235  			Name:     name,
   236  			Ts:       ctx.elapsed(ts),
   237  			Resource: viewerResource,
   238  			Stack:    ctx.Stack(viewerFrames(stack)),
   239  		})
   240  	}
   241  	gs.startBlockReason = ""
   242  	if viewerResource != 0 {
   243  		gs.setStartCause(ts, name, viewerResource, stack)
   244  	}
   245  }
   246  
   247  // block indicates that the goroutine has stopped executing on a proc -- specifically,
   248  // it blocked for some reason.
   249  func (gs *gState[R]) block(ts tracev2.Time, stack tracev2.Stack, reason string, ctx *traceContext) {
   250  	gs.startBlockReason = reason
   251  	gs.stop(ts, stack, ctx)
   252  }
   253  
   254  // stop indicates that the goroutine has stopped executing on a proc.
   255  func (gs *gState[R]) stop(ts tracev2.Time, stack tracev2.Stack, ctx *traceContext) {
   256  	// Emit the execution time slice.
   257  	var stk int
   258  	if gs.lastStopStack != tracev2.NoStack {
   259  		stk = ctx.Stack(viewerFrames(gs.lastStopStack))
   260  	}
   261  	// Check invariants.
   262  	if gs.startRunningTime == 0 {
   263  		panic("silently broken trace or generator invariant (startRunningTime != 0) not held")
   264  	}
   265  	if gs.executing == R(noResource) {
   266  		panic("non-executing goroutine stopped")
   267  	}
   268  	ctx.Slice(traceviewer.SliceEvent{
   269  		Name:     gs.name(),
   270  		Ts:       ctx.elapsed(gs.startRunningTime),
   271  		Dur:      ts.Sub(gs.startRunningTime),
   272  		Resource: uint64(gs.executing),
   273  		Stack:    stk,
   274  	})
   275  
   276  	// Flush completed ranges.
   277  	for _, cr := range gs.completedRanges {
   278  		ctx.Slice(traceviewer.SliceEvent{
   279  			Name:     cr.name,
   280  			Ts:       ctx.elapsed(cr.startTime),
   281  			Dur:      cr.endTime.Sub(cr.startTime),
   282  			Resource: uint64(gs.executing),
   283  			Stack:    ctx.Stack(viewerFrames(cr.startStack)),
   284  			EndStack: ctx.Stack(viewerFrames(cr.endStack)),
   285  			Arg:      cr.arg,
   286  		})
   287  	}
   288  	gs.completedRanges = gs.completedRanges[:0]
   289  
   290  	// Continue in-progress ranges.
   291  	for name, r := range gs.activeRanges {
   292  		// Check invariant.
   293  		if r.time == 0 {
   294  			panic("silently broken trace or generator invariant (activeRanges time != 0) not held")
   295  		}
   296  		ctx.Slice(traceviewer.SliceEvent{
   297  			Name:     name,
   298  			Ts:       ctx.elapsed(r.time),
   299  			Dur:      ts.Sub(r.time),
   300  			Resource: uint64(gs.executing),
   301  			Stack:    ctx.Stack(viewerFrames(r.stack)),
   302  		})
   303  	}
   304  
   305  	// Clear the range info.
   306  	for name := range gs.activeRanges {
   307  		gs.activeRanges[name] = activeRange{0, tracev2.NoStack}
   308  	}
   309  
   310  	gs.startRunningTime = 0
   311  	gs.lastStopStack = stack
   312  	gs.executing = R(noResource)
   313  }
   314  
   315  // finalize writes out any in-progress slices as if the goroutine stopped.
   316  // This must only be used once the trace has been fully processed and no
   317  // further events will be processed. This method may leave the gState in
   318  // an inconsistent state.
   319  func (gs *gState[R]) finish(ctx *traceContext) {
   320  	if gs.executing != R(noResource) {
   321  		gs.syscallEnd(ctx.endTime, false, ctx)
   322  		gs.stop(ctx.endTime, tracev2.NoStack, ctx)
   323  	}
   324  }
   325  
   326  // rangeBegin indicates the start of a special range of time.
   327  func (gs *gState[R]) rangeBegin(ts tracev2.Time, name string, stack tracev2.Stack) {
   328  	if gs.executing != R(noResource) {
   329  		// If we're executing, start the slice from here.
   330  		gs.activeRanges[name] = activeRange{ts, stack}
   331  	} else {
   332  		// If the goroutine isn't executing, there's no place for
   333  		// us to create a slice from. Wait until it starts executing.
   334  		gs.activeRanges[name] = activeRange{0, stack}
   335  	}
   336  }
   337  
   338  // rangeActive indicates that a special range of time has been in progress.
   339  func (gs *gState[R]) rangeActive(name string) {
   340  	if gs.executing != R(noResource) {
   341  		// If we're executing, and the range is active, then start
   342  		// from wherever the goroutine started running from.
   343  		gs.activeRanges[name] = activeRange{gs.startRunningTime, tracev2.NoStack}
   344  	} else {
   345  		// If the goroutine isn't executing, there's no place for
   346  		// us to create a slice from. Wait until it starts executing.
   347  		gs.activeRanges[name] = activeRange{0, tracev2.NoStack}
   348  	}
   349  }
   350  
   351  // rangeEnd indicates the end of a special range of time.
   352  func (gs *gState[R]) rangeEnd(ts tracev2.Time, name string, stack tracev2.Stack, ctx *traceContext) {
   353  	if gs.executing != R(noResource) {
   354  		r := gs.activeRanges[name]
   355  		gs.completedRanges = append(gs.completedRanges, completedRange{
   356  			name:       name,
   357  			startTime:  r.time,
   358  			endTime:    ts,
   359  			startStack: r.stack,
   360  			endStack:   stack,
   361  		})
   362  	}
   363  	delete(gs.activeRanges, name)
   364  }
   365  
   366  func lastFunc(s tracev2.Stack) string {
   367  	var last tracev2.StackFrame
   368  	s.Frames(func(f tracev2.StackFrame) bool {
   369  		last = f
   370  		return true
   371  	})
   372  	return last.Func
   373  }
   374
View as plain text