Source file src/internal/trace/event.go

     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  	"iter"
    10  	"math"
    11  	"strconv"
    12  	"strings"
    13  	"time"
    14  
    15  	"internal/trace/tracev2"
    16  	"internal/trace/version"
    17  )
    18  
    19  // EventKind indicates the kind of event this is.
    20  //
    21  // Use this information to obtain a more specific event that
    22  // allows access to more detailed information.
    23  type EventKind uint16
    24  
    25  const (
    26  	EventBad EventKind = iota
    27  
    28  	// EventKindSync is an event that indicates a global synchronization
    29  	// point in the trace. At the point of a sync event, the
    30  	// trace reader can be certain that all resources (e.g. threads,
    31  	// goroutines) that have existed until that point have been enumerated.
    32  	EventSync
    33  
    34  	// EventMetric is an event that represents the value of a metric at
    35  	// a particular point in time.
    36  	EventMetric
    37  
    38  	// EventLabel attaches a label to a resource.
    39  	EventLabel
    40  
    41  	// EventStackSample represents an execution sample, indicating what a
    42  	// thread/proc/goroutine was doing at a particular point in time via
    43  	// its backtrace.
    44  	//
    45  	// Note: Samples should be considered a close approximation of
    46  	// what a thread/proc/goroutine was executing at a given point in time.
    47  	// These events may slightly contradict the situation StateTransitions
    48  	// describe, so they should only be treated as a best-effort annotation.
    49  	EventStackSample
    50  
    51  	// EventRangeBegin and EventRangeEnd are a pair of generic events representing
    52  	// a special range of time. Ranges are named and scoped to some resource
    53  	// (identified via ResourceKind). A range that has begun but has not ended
    54  	// is considered active.
    55  	//
    56  	// EvRangeBegin and EvRangeEnd will share the same name, and an End will always
    57  	// follow a Begin on the same instance of the resource. The associated
    58  	// resource ID can be obtained from the Event. ResourceNone indicates the
    59  	// range is globally scoped. That is, any goroutine/proc/thread can start or
    60  	// stop, but only one such range may be active at any given time.
    61  	//
    62  	// EventRangeActive is like EventRangeBegin, but indicates that the range was
    63  	// already active. In this case, the resource referenced may not be in the current
    64  	// context.
    65  	EventRangeBegin
    66  	EventRangeActive
    67  	EventRangeEnd
    68  
    69  	// EvTaskBegin and EvTaskEnd are a pair of events representing a runtime/trace.Task.
    70  	EventTaskBegin
    71  	EventTaskEnd
    72  
    73  	// EventRegionBegin and EventRegionEnd are a pair of events represent a runtime/trace.Region.
    74  	EventRegionBegin
    75  	EventRegionEnd
    76  
    77  	// EventLog represents a runtime/trace.Log call.
    78  	EventLog
    79  
    80  	// EventStateTransition represents a state change for some resource.
    81  	EventStateTransition
    82  
    83  	// EventExperimental is an experimental event that is unvalidated and exposed in a raw form.
    84  	// Users are expected to understand the format and perform their own validation. These events
    85  	// may always be safely ignored.
    86  	EventExperimental
    87  )
    88  
    89  // String returns a string form of the EventKind.
    90  func (e EventKind) String() string {
    91  	if int(e) >= len(eventKindStrings) {
    92  		return eventKindStrings[0]
    93  	}
    94  	return eventKindStrings[e]
    95  }
    96  
    97  var eventKindStrings = [...]string{
    98  	EventBad:             "Bad",
    99  	EventSync:            "Sync",
   100  	EventMetric:          "Metric",
   101  	EventLabel:           "Label",
   102  	EventStackSample:     "StackSample",
   103  	EventRangeBegin:      "RangeBegin",
   104  	EventRangeActive:     "RangeActive",
   105  	EventRangeEnd:        "RangeEnd",
   106  	EventTaskBegin:       "TaskBegin",
   107  	EventTaskEnd:         "TaskEnd",
   108  	EventRegionBegin:     "RegionBegin",
   109  	EventRegionEnd:       "RegionEnd",
   110  	EventLog:             "Log",
   111  	EventStateTransition: "StateTransition",
   112  	EventExperimental:    "Experimental",
   113  }
   114  
   115  const maxTime = Time(math.MaxInt64)
   116  
   117  // Time is a timestamp in nanoseconds.
   118  //
   119  // It corresponds to the monotonic clock on the platform that the
   120  // trace was taken, and so is possible to correlate with timestamps
   121  // for other traces taken on the same machine using the same clock
   122  // (i.e. no reboots in between).
   123  //
   124  // The actual absolute value of the timestamp is only meaningful in
   125  // relation to other timestamps from the same clock.
   126  //
   127  // BUG: Timestamps coming from traces on Windows platforms are
   128  // only comparable with timestamps from the same trace. Timestamps
   129  // across traces cannot be compared, because the system clock is
   130  // not used as of Go 1.22.
   131  //
   132  // BUG: Traces produced by Go versions 1.21 and earlier cannot be
   133  // compared with timestamps from other traces taken on the same
   134  // machine. This is because the system clock was not used at all
   135  // to collect those timestamps.
   136  type Time int64
   137  
   138  // Sub subtracts t0 from t, returning the duration in nanoseconds.
   139  func (t Time) Sub(t0 Time) time.Duration {
   140  	return time.Duration(int64(t) - int64(t0))
   141  }
   142  
   143  // Metric provides details about a Metric event.
   144  type Metric struct {
   145  	// Name is the name of the sampled metric.
   146  	//
   147  	// Names follow the same convention as metric names in the
   148  	// runtime/metrics package, meaning they include the unit.
   149  	// Names that match with the runtime/metrics package represent
   150  	// the same quantity. Note that this corresponds to the
   151  	// runtime/metrics package for the Go version this trace was
   152  	// collected for.
   153  	Name string
   154  
   155  	// Value is the sampled value of the metric.
   156  	//
   157  	// The Value's Kind is tied to the name of the metric, and so is
   158  	// guaranteed to be the same for metric samples for the same metric.
   159  	Value Value
   160  }
   161  
   162  // Label provides details about a Label event.
   163  type Label struct {
   164  	// Label is the label applied to some resource.
   165  	Label string
   166  
   167  	// Resource is the resource to which this label should be applied.
   168  	Resource ResourceID
   169  }
   170  
   171  // Range provides details about a Range event.
   172  type Range struct {
   173  	// Name is a human-readable name for the range.
   174  	//
   175  	// This name can be used to identify the end of the range for the resource
   176  	// its scoped to, because only one of each type of range may be active on
   177  	// a particular resource. The relevant resource should be obtained from the
   178  	// Event that produced these details. The corresponding RangeEnd will have
   179  	// an identical name.
   180  	Name string
   181  
   182  	// Scope is the resource that the range is scoped to.
   183  	//
   184  	// For example, a ResourceGoroutine scope means that the same goroutine
   185  	// must have a start and end for the range, and that goroutine can only
   186  	// have one range of a particular name active at any given time. The
   187  	// ID that this range is scoped to may be obtained via Event.Goroutine.
   188  	//
   189  	// The ResourceNone scope means that the range is globally scoped. As a
   190  	// result, any goroutine/proc/thread may start or end the range, and only
   191  	// one such named range may be active globally at any given time.
   192  	//
   193  	// For RangeBegin and RangeEnd events, this will always reference some
   194  	// resource ID in the current execution context. For RangeActive events,
   195  	// this may reference a resource not in the current context. Prefer Scope
   196  	// over the current execution context.
   197  	Scope ResourceID
   198  }
   199  
   200  // RangeAttributes provides attributes about a completed Range.
   201  type RangeAttribute struct {
   202  	// Name is the human-readable name for the range.
   203  	Name string
   204  
   205  	// Value is the value of the attribute.
   206  	Value Value
   207  }
   208  
   209  // TaskID is the internal ID of a task used to disambiguate tasks (even if they
   210  // are of the same type).
   211  type TaskID uint64
   212  
   213  const (
   214  	// NoTask indicates the lack of a task.
   215  	NoTask = TaskID(^uint64(0))
   216  
   217  	// BackgroundTask is the global task that events are attached to if there was
   218  	// no other task in the context at the point the event was emitted.
   219  	BackgroundTask = TaskID(0)
   220  )
   221  
   222  // Task provides details about a Task event.
   223  type Task struct {
   224  	// ID is a unique identifier for the task.
   225  	//
   226  	// This can be used to associate the beginning of a task with its end.
   227  	ID TaskID
   228  
   229  	// ParentID is the ID of the parent task.
   230  	Parent TaskID
   231  
   232  	// Type is the taskType that was passed to runtime/trace.NewTask.
   233  	//
   234  	// May be "" if a task's TaskBegin event isn't present in the trace.
   235  	Type string
   236  }
   237  
   238  // Region provides details about a Region event.
   239  type Region struct {
   240  	// Task is the ID of the task this region is associated with.
   241  	Task TaskID
   242  
   243  	// Type is the regionType that was passed to runtime/trace.StartRegion or runtime/trace.WithRegion.
   244  	Type string
   245  }
   246  
   247  // Log provides details about a Log event.
   248  type Log struct {
   249  	// Task is the ID of the task this region is associated with.
   250  	Task TaskID
   251  
   252  	// Category is the category that was passed to runtime/trace.Log or runtime/trace.Logf.
   253  	Category string
   254  
   255  	// Message is the message that was passed to runtime/trace.Log or runtime/trace.Logf.
   256  	Message string
   257  }
   258  
   259  // Stack represents a stack. It's really a handle to a stack and it's trivially comparable.
   260  //
   261  // If two Stacks are equal then their Frames are guaranteed to be identical. If they are not
   262  // equal, however, their Frames may still be equal.
   263  type Stack struct {
   264  	table *evTable
   265  	id    stackID
   266  }
   267  
   268  // Frames is an iterator over the frames in a Stack.
   269  func (s Stack) Frames() iter.Seq[StackFrame] {
   270  	return func(yield func(StackFrame) bool) {
   271  		if s.id == 0 {
   272  			return
   273  		}
   274  		stk := s.table.stacks.mustGet(s.id)
   275  		for _, pc := range stk.pcs {
   276  			f := s.table.pcs[pc]
   277  			sf := StackFrame{
   278  				PC:   f.pc,
   279  				Func: s.table.strings.mustGet(f.funcID),
   280  				File: s.table.strings.mustGet(f.fileID),
   281  				Line: f.line,
   282  			}
   283  			if !yield(sf) {
   284  				return
   285  			}
   286  		}
   287  	}
   288  }
   289  
   290  // NoStack is a sentinel value that can be compared against any Stack value, indicating
   291  // a lack of a stack trace.
   292  var NoStack = Stack{}
   293  
   294  // StackFrame represents a single frame of a stack.
   295  type StackFrame struct {
   296  	// PC is the program counter of the function call if this
   297  	// is not a leaf frame. If it's a leaf frame, it's the point
   298  	// at which the stack trace was taken.
   299  	PC uint64
   300  
   301  	// Func is the name of the function this frame maps to.
   302  	Func string
   303  
   304  	// File is the file which contains the source code of Func.
   305  	File string
   306  
   307  	// Line is the line number within File which maps to PC.
   308  	Line uint64
   309  }
   310  
   311  // ExperimentalEvent presents a raw view of an experimental event's arguments and their names.
   312  type ExperimentalEvent struct {
   313  	// Name is the name of the event.
   314  	Name string
   315  
   316  	// Experiment is the name of the experiment this event is a part of.
   317  	Experiment string
   318  
   319  	// Args lists the names of the event's arguments in order.
   320  	Args []string
   321  
   322  	// argValues contains the raw integer arguments which are interpreted
   323  	// by ArgValue using table.
   324  	table     *evTable
   325  	argValues []uint64
   326  }
   327  
   328  // ArgValue returns a typed Value for the i'th argument in the experimental event.
   329  func (e ExperimentalEvent) ArgValue(i int) Value {
   330  	if i < 0 || i >= len(e.Args) {
   331  		panic(fmt.Sprintf("experimental event argument index %d out of bounds [0, %d)", i, len(e.Args)))
   332  	}
   333  	if strings.HasSuffix(e.Args[i], "string") {
   334  		s := e.table.strings.mustGet(stringID(e.argValues[i]))
   335  		return stringValue(s)
   336  	}
   337  	return uint64Value(e.argValues[i])
   338  }
   339  
   340  // ExperimentalBatch represents a packet of unparsed data along with metadata about that packet.
   341  type ExperimentalBatch struct {
   342  	// Thread is the ID of the thread that produced a packet of data.
   343  	Thread ThreadID
   344  
   345  	// Data is a packet of unparsed data all produced by one thread.
   346  	Data []byte
   347  }
   348  
   349  // Event represents a single event in the trace.
   350  type Event struct {
   351  	table *evTable
   352  	ctx   schedCtx
   353  	base  baseEvent
   354  }
   355  
   356  // Kind returns the kind of event that this is.
   357  func (e Event) Kind() EventKind {
   358  	return tracev2Type2Kind[e.base.typ]
   359  }
   360  
   361  // Time returns the timestamp of the event.
   362  func (e Event) Time() Time {
   363  	return e.base.time
   364  }
   365  
   366  // Goroutine returns the ID of the goroutine that was executing when
   367  // this event happened. It describes part of the execution context
   368  // for this event.
   369  //
   370  // Note that for goroutine state transitions this always refers to the
   371  // state before the transition. For example, if a goroutine is just
   372  // starting to run on this thread and/or proc, then this will return
   373  // NoGoroutine. In this case, the goroutine starting to run will be
   374  // can be found at Event.StateTransition().Resource.
   375  func (e Event) Goroutine() GoID {
   376  	return e.ctx.G
   377  }
   378  
   379  // Proc returns the ID of the proc this event event pertains to.
   380  //
   381  // Note that for proc state transitions this always refers to the
   382  // state before the transition. For example, if a proc is just
   383  // starting to run on this thread, then this will return NoProc.
   384  func (e Event) Proc() ProcID {
   385  	return e.ctx.P
   386  }
   387  
   388  // Thread returns the ID of the thread this event pertains to.
   389  //
   390  // Note that for thread state transitions this always refers to the
   391  // state before the transition. For example, if a thread is just
   392  // starting to run, then this will return NoThread.
   393  //
   394  // Note: tracking thread state is not currently supported, so this
   395  // will always return a valid thread ID. However thread state transitions
   396  // may be tracked in the future, and callers must be robust to this
   397  // possibility.
   398  func (e Event) Thread() ThreadID {
   399  	return e.ctx.M
   400  }
   401  
   402  // Stack returns a handle to a stack associated with the event.
   403  //
   404  // This represents a stack trace at the current moment in time for
   405  // the current execution context.
   406  func (e Event) Stack() Stack {
   407  	if e.base.typ == evSync {
   408  		return NoStack
   409  	}
   410  	if e.base.typ == tracev2.EvCPUSample {
   411  		return Stack{table: e.table, id: stackID(e.base.args[0])}
   412  	}
   413  	spec := tracev2.Specs()[e.base.typ]
   414  	if len(spec.StackIDs) == 0 {
   415  		return NoStack
   416  	}
   417  	// The stack for the main execution context is always the
   418  	// first stack listed in StackIDs. Subtract one from this
   419  	// because we've peeled away the timestamp argument.
   420  	id := stackID(e.base.args[spec.StackIDs[0]-1])
   421  	if id == 0 {
   422  		return NoStack
   423  	}
   424  	return Stack{table: e.table, id: id}
   425  }
   426  
   427  // Metric returns details about a Metric event.
   428  //
   429  // Panics if Kind != EventMetric.
   430  func (e Event) Metric() Metric {
   431  	if e.Kind() != EventMetric {
   432  		panic("Metric called on non-Metric event")
   433  	}
   434  	var m Metric
   435  	switch e.base.typ {
   436  	case tracev2.EvProcsChange:
   437  		m.Name = "/sched/gomaxprocs:threads"
   438  		m.Value = uint64Value(e.base.args[0])
   439  	case tracev2.EvHeapAlloc:
   440  		m.Name = "/memory/classes/heap/objects:bytes"
   441  		m.Value = uint64Value(e.base.args[0])
   442  	case tracev2.EvHeapGoal:
   443  		m.Name = "/gc/heap/goal:bytes"
   444  		m.Value = uint64Value(e.base.args[0])
   445  	default:
   446  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for Metric kind: %d", e.base.typ))
   447  	}
   448  	return m
   449  }
   450  
   451  // Label returns details about a Label event.
   452  //
   453  // Panics if Kind != EventLabel.
   454  func (e Event) Label() Label {
   455  	if e.Kind() != EventLabel {
   456  		panic("Label called on non-Label event")
   457  	}
   458  	if e.base.typ != tracev2.EvGoLabel {
   459  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for Label kind: %d", e.base.typ))
   460  	}
   461  	return Label{
   462  		Label:    e.table.strings.mustGet(stringID(e.base.args[0])),
   463  		Resource: ResourceID{Kind: ResourceGoroutine, id: int64(e.ctx.G)},
   464  	}
   465  }
   466  
   467  // Range returns details about an EventRangeBegin, EventRangeActive, or EventRangeEnd event.
   468  //
   469  // Panics if Kind != EventRangeBegin, Kind != EventRangeActive, and Kind != EventRangeEnd.
   470  func (e Event) Range() Range {
   471  	if kind := e.Kind(); kind != EventRangeBegin && kind != EventRangeActive && kind != EventRangeEnd {
   472  		panic("Range called on non-Range event")
   473  	}
   474  	var r Range
   475  	switch e.base.typ {
   476  	case tracev2.EvSTWBegin, tracev2.EvSTWEnd:
   477  		// N.B. ordering.advance smuggles in the STW reason as e.base.args[0]
   478  		// for tracev2.EvSTWEnd (it's already there for Begin).
   479  		r.Name = "stop-the-world (" + e.table.strings.mustGet(stringID(e.base.args[0])) + ")"
   480  		r.Scope = ResourceID{Kind: ResourceGoroutine, id: int64(e.Goroutine())}
   481  	case tracev2.EvGCBegin, tracev2.EvGCActive, tracev2.EvGCEnd:
   482  		r.Name = "GC concurrent mark phase"
   483  		r.Scope = ResourceID{Kind: ResourceNone}
   484  	case tracev2.EvGCSweepBegin, tracev2.EvGCSweepActive, tracev2.EvGCSweepEnd:
   485  		r.Name = "GC incremental sweep"
   486  		r.Scope = ResourceID{Kind: ResourceProc}
   487  		if e.base.typ == tracev2.EvGCSweepActive {
   488  			r.Scope.id = int64(e.base.args[0])
   489  		} else {
   490  			r.Scope.id = int64(e.Proc())
   491  		}
   492  		r.Scope.id = int64(e.Proc())
   493  	case tracev2.EvGCMarkAssistBegin, tracev2.EvGCMarkAssistActive, tracev2.EvGCMarkAssistEnd:
   494  		r.Name = "GC mark assist"
   495  		r.Scope = ResourceID{Kind: ResourceGoroutine}
   496  		if e.base.typ == tracev2.EvGCMarkAssistActive {
   497  			r.Scope.id = int64(e.base.args[0])
   498  		} else {
   499  			r.Scope.id = int64(e.Goroutine())
   500  		}
   501  	default:
   502  		panic(fmt.Sprintf("internal error: unexpected wire-event type for Range kind: %d", e.base.typ))
   503  	}
   504  	return r
   505  }
   506  
   507  // RangeAttributes returns attributes for a completed range.
   508  //
   509  // Panics if Kind != EventRangeEnd.
   510  func (e Event) RangeAttributes() []RangeAttribute {
   511  	if e.Kind() != EventRangeEnd {
   512  		panic("Range called on non-Range event")
   513  	}
   514  	if e.base.typ != tracev2.EvGCSweepEnd {
   515  		return nil
   516  	}
   517  	return []RangeAttribute{
   518  		{
   519  			Name:  "bytes swept",
   520  			Value: uint64Value(e.base.args[0]),
   521  		},
   522  		{
   523  			Name:  "bytes reclaimed",
   524  			Value: uint64Value(e.base.args[1]),
   525  		},
   526  	}
   527  }
   528  
   529  // Task returns details about a TaskBegin or TaskEnd event.
   530  //
   531  // Panics if Kind != EventTaskBegin and Kind != EventTaskEnd.
   532  func (e Event) Task() Task {
   533  	if kind := e.Kind(); kind != EventTaskBegin && kind != EventTaskEnd {
   534  		panic("Task called on non-Task event")
   535  	}
   536  	parentID := NoTask
   537  	var typ string
   538  	switch e.base.typ {
   539  	case tracev2.EvUserTaskBegin:
   540  		parentID = TaskID(e.base.args[1])
   541  		typ = e.table.strings.mustGet(stringID(e.base.args[2]))
   542  	case tracev2.EvUserTaskEnd:
   543  		parentID = TaskID(e.base.extra(version.Go122)[0])
   544  		typ = e.table.getExtraString(extraStringID(e.base.extra(version.Go122)[1]))
   545  	default:
   546  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for Task kind: %d", e.base.typ))
   547  	}
   548  	return Task{
   549  		ID:     TaskID(e.base.args[0]),
   550  		Parent: parentID,
   551  		Type:   typ,
   552  	}
   553  }
   554  
   555  // Region returns details about a RegionBegin or RegionEnd event.
   556  //
   557  // Panics if Kind != EventRegionBegin and Kind != EventRegionEnd.
   558  func (e Event) Region() Region {
   559  	if kind := e.Kind(); kind != EventRegionBegin && kind != EventRegionEnd {
   560  		panic("Region called on non-Region event")
   561  	}
   562  	if e.base.typ != tracev2.EvUserRegionBegin && e.base.typ != tracev2.EvUserRegionEnd {
   563  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for Region kind: %d", e.base.typ))
   564  	}
   565  	return Region{
   566  		Task: TaskID(e.base.args[0]),
   567  		Type: e.table.strings.mustGet(stringID(e.base.args[1])),
   568  	}
   569  }
   570  
   571  // Log returns details about a Log event.
   572  //
   573  // Panics if Kind != EventLog.
   574  func (e Event) Log() Log {
   575  	if e.Kind() != EventLog {
   576  		panic("Log called on non-Log event")
   577  	}
   578  	if e.base.typ != tracev2.EvUserLog {
   579  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for Log kind: %d", e.base.typ))
   580  	}
   581  	return Log{
   582  		Task:     TaskID(e.base.args[0]),
   583  		Category: e.table.strings.mustGet(stringID(e.base.args[1])),
   584  		Message:  e.table.strings.mustGet(stringID(e.base.args[2])),
   585  	}
   586  }
   587  
   588  // StateTransition returns details about a StateTransition event.
   589  //
   590  // Panics if Kind != EventStateTransition.
   591  func (e Event) StateTransition() StateTransition {
   592  	if e.Kind() != EventStateTransition {
   593  		panic("StateTransition called on non-StateTransition event")
   594  	}
   595  	var s StateTransition
   596  	switch e.base.typ {
   597  	case tracev2.EvProcStart:
   598  		s = procStateTransition(ProcID(e.base.args[0]), ProcIdle, ProcRunning)
   599  	case tracev2.EvProcStop:
   600  		s = procStateTransition(e.ctx.P, ProcRunning, ProcIdle)
   601  	case tracev2.EvProcSteal:
   602  		// N.B. ordering.advance populates e.base.extra.
   603  		beforeState := ProcRunning
   604  		if tracev2.ProcStatus(e.base.extra(version.Go122)[0]) == tracev2.ProcSyscallAbandoned {
   605  			// We've lost information because this ProcSteal advanced on a
   606  			// SyscallAbandoned state. Treat the P as idle because ProcStatus
   607  			// treats SyscallAbandoned as Idle. Otherwise we'll have an invalid
   608  			// transition.
   609  			beforeState = ProcIdle
   610  		}
   611  		s = procStateTransition(ProcID(e.base.args[0]), beforeState, ProcIdle)
   612  	case tracev2.EvProcStatus:
   613  		// N.B. ordering.advance populates e.base.extra.
   614  		s = procStateTransition(ProcID(e.base.args[0]), ProcState(e.base.extra(version.Go122)[0]), tracev2ProcStatus2ProcState[e.base.args[1]])
   615  	case tracev2.EvGoCreate, tracev2.EvGoCreateBlocked:
   616  		status := GoRunnable
   617  		if e.base.typ == tracev2.EvGoCreateBlocked {
   618  			status = GoWaiting
   619  		}
   620  		s = goStateTransition(GoID(e.base.args[0]), GoNotExist, status)
   621  		s.Stack = Stack{table: e.table, id: stackID(e.base.args[1])}
   622  	case tracev2.EvGoCreateSyscall:
   623  		s = goStateTransition(GoID(e.base.args[0]), GoNotExist, GoSyscall)
   624  	case tracev2.EvGoStart:
   625  		s = goStateTransition(GoID(e.base.args[0]), GoRunnable, GoRunning)
   626  	case tracev2.EvGoDestroy:
   627  		s = goStateTransition(e.ctx.G, GoRunning, GoNotExist)
   628  		s.Stack = e.Stack() // This event references the resource the event happened on.
   629  	case tracev2.EvGoDestroySyscall:
   630  		s = goStateTransition(e.ctx.G, GoSyscall, GoNotExist)
   631  	case tracev2.EvGoStop:
   632  		s = goStateTransition(e.ctx.G, GoRunning, GoRunnable)
   633  		s.Reason = e.table.strings.mustGet(stringID(e.base.args[0]))
   634  		s.Stack = e.Stack() // This event references the resource the event happened on.
   635  	case tracev2.EvGoBlock:
   636  		s = goStateTransition(e.ctx.G, GoRunning, GoWaiting)
   637  		s.Reason = e.table.strings.mustGet(stringID(e.base.args[0]))
   638  		s.Stack = e.Stack() // This event references the resource the event happened on.
   639  	case tracev2.EvGoUnblock, tracev2.EvGoSwitch, tracev2.EvGoSwitchDestroy:
   640  		// N.B. GoSwitch and GoSwitchDestroy both emit additional events, but
   641  		// the first thing they both do is unblock the goroutine they name,
   642  		// identically to an unblock event (even their arguments match).
   643  		s = goStateTransition(GoID(e.base.args[0]), GoWaiting, GoRunnable)
   644  	case tracev2.EvGoSyscallBegin:
   645  		s = goStateTransition(e.ctx.G, GoRunning, GoSyscall)
   646  		s.Stack = e.Stack() // This event references the resource the event happened on.
   647  	case tracev2.EvGoSyscallEnd:
   648  		s = goStateTransition(e.ctx.G, GoSyscall, GoRunning)
   649  		s.Stack = e.Stack() // This event references the resource the event happened on.
   650  	case tracev2.EvGoSyscallEndBlocked:
   651  		s = goStateTransition(e.ctx.G, GoSyscall, GoRunnable)
   652  		s.Stack = e.Stack() // This event references the resource the event happened on.
   653  	case tracev2.EvGoStatus, tracev2.EvGoStatusStack:
   654  		packedStatus := e.base.args[2]
   655  		from, to := packedStatus>>32, packedStatus&((1<<32)-1)
   656  		s = goStateTransition(GoID(e.base.args[0]), GoState(from), tracev2GoStatus2GoState[to])
   657  	default:
   658  		panic(fmt.Sprintf("internal error: unexpected wire-format event type for StateTransition kind: %d", e.base.typ))
   659  	}
   660  	return s
   661  }
   662  
   663  // Sync returns details that are relevant for the following events, up to but excluding the
   664  // next EventSync event.
   665  func (e Event) Sync() Sync {
   666  	if e.Kind() != EventSync {
   667  		panic("Sync called on non-Sync event")
   668  	}
   669  	s := Sync{N: int(e.base.args[0])}
   670  	if e.table != nil {
   671  		expBatches := make(map[string][]ExperimentalBatch)
   672  		for exp, batches := range e.table.expBatches {
   673  			expBatches[tracev2.Experiments()[exp]] = batches
   674  		}
   675  		s.ExperimentalBatches = expBatches
   676  		if e.table.hasClockSnapshot {
   677  			s.ClockSnapshot = &ClockSnapshot{
   678  				Trace: e.table.freq.mul(e.table.snapTime),
   679  				Wall:  e.table.snapWall,
   680  				Mono:  e.table.snapMono,
   681  			}
   682  		}
   683  	}
   684  	return s
   685  }
   686  
   687  // Sync contains details potentially relevant to all the following events, up to but excluding
   688  // the next EventSync event.
   689  type Sync struct {
   690  	// N indicates that this is the Nth sync event in the trace.
   691  	N int
   692  
   693  	// ClockSnapshot is a snapshot of different clocks taken in close in time
   694  	// that can be used to correlate trace events with data captured by other
   695  	// tools. May be nil for older trace versions.
   696  	ClockSnapshot *ClockSnapshot
   697  
   698  	// ExperimentalBatches contain all the unparsed batches of data for a given experiment.
   699  	ExperimentalBatches map[string][]ExperimentalBatch
   700  }
   701  
   702  // ClockSnapshot represents a near-simultaneous clock reading of several
   703  // different system clocks. The snapshot can be used as a reference to convert
   704  // timestamps to different clocks, which is helpful for correlating timestamps
   705  // with data captured by other tools.
   706  type ClockSnapshot struct {
   707  	// Trace is a snapshot of the trace clock.
   708  	Trace Time
   709  
   710  	// Wall is a snapshot of the system's wall clock.
   711  	Wall time.Time
   712  
   713  	// Mono is a snapshot of the system's monotonic clock.
   714  	Mono uint64
   715  }
   716  
   717  // Experimental returns a view of the raw event for an experimental event.
   718  //
   719  // Panics if Kind != EventExperimental.
   720  func (e Event) Experimental() ExperimentalEvent {
   721  	if e.Kind() != EventExperimental {
   722  		panic("Experimental called on non-Experimental event")
   723  	}
   724  	spec := tracev2.Specs()[e.base.typ]
   725  	argNames := spec.Args[1:] // Skip timestamp; already handled.
   726  	return ExperimentalEvent{
   727  		Name:       spec.Name,
   728  		Experiment: tracev2.Experiments()[spec.Experiment],
   729  		Args:       argNames,
   730  		table:      e.table,
   731  		argValues:  e.base.args[:len(argNames)],
   732  	}
   733  }
   734  
   735  const evSync = ^tracev2.EventType(0)
   736  
   737  var tracev2Type2Kind = [...]EventKind{
   738  	tracev2.EvCPUSample:           EventStackSample,
   739  	tracev2.EvProcsChange:         EventMetric,
   740  	tracev2.EvProcStart:           EventStateTransition,
   741  	tracev2.EvProcStop:            EventStateTransition,
   742  	tracev2.EvProcSteal:           EventStateTransition,
   743  	tracev2.EvProcStatus:          EventStateTransition,
   744  	tracev2.EvGoCreate:            EventStateTransition,
   745  	tracev2.EvGoCreateSyscall:     EventStateTransition,
   746  	tracev2.EvGoStart:             EventStateTransition,
   747  	tracev2.EvGoDestroy:           EventStateTransition,
   748  	tracev2.EvGoDestroySyscall:    EventStateTransition,
   749  	tracev2.EvGoStop:              EventStateTransition,
   750  	tracev2.EvGoBlock:             EventStateTransition,
   751  	tracev2.EvGoUnblock:           EventStateTransition,
   752  	tracev2.EvGoSyscallBegin:      EventStateTransition,
   753  	tracev2.EvGoSyscallEnd:        EventStateTransition,
   754  	tracev2.EvGoSyscallEndBlocked: EventStateTransition,
   755  	tracev2.EvGoStatus:            EventStateTransition,
   756  	tracev2.EvSTWBegin:            EventRangeBegin,
   757  	tracev2.EvSTWEnd:              EventRangeEnd,
   758  	tracev2.EvGCActive:            EventRangeActive,
   759  	tracev2.EvGCBegin:             EventRangeBegin,
   760  	tracev2.EvGCEnd:               EventRangeEnd,
   761  	tracev2.EvGCSweepActive:       EventRangeActive,
   762  	tracev2.EvGCSweepBegin:        EventRangeBegin,
   763  	tracev2.EvGCSweepEnd:          EventRangeEnd,
   764  	tracev2.EvGCMarkAssistActive:  EventRangeActive,
   765  	tracev2.EvGCMarkAssistBegin:   EventRangeBegin,
   766  	tracev2.EvGCMarkAssistEnd:     EventRangeEnd,
   767  	tracev2.EvHeapAlloc:           EventMetric,
   768  	tracev2.EvHeapGoal:            EventMetric,
   769  	tracev2.EvGoLabel:             EventLabel,
   770  	tracev2.EvUserTaskBegin:       EventTaskBegin,
   771  	tracev2.EvUserTaskEnd:         EventTaskEnd,
   772  	tracev2.EvUserRegionBegin:     EventRegionBegin,
   773  	tracev2.EvUserRegionEnd:       EventRegionEnd,
   774  	tracev2.EvUserLog:             EventLog,
   775  	tracev2.EvGoSwitch:            EventStateTransition,
   776  	tracev2.EvGoSwitchDestroy:     EventStateTransition,
   777  	tracev2.EvGoCreateBlocked:     EventStateTransition,
   778  	tracev2.EvGoStatusStack:       EventStateTransition,
   779  	tracev2.EvSpan:                EventExperimental,
   780  	tracev2.EvSpanAlloc:           EventExperimental,
   781  	tracev2.EvSpanFree:            EventExperimental,
   782  	tracev2.EvHeapObject:          EventExperimental,
   783  	tracev2.EvHeapObjectAlloc:     EventExperimental,
   784  	tracev2.EvHeapObjectFree:      EventExperimental,
   785  	tracev2.EvGoroutineStack:      EventExperimental,
   786  	tracev2.EvGoroutineStackAlloc: EventExperimental,
   787  	tracev2.EvGoroutineStackFree:  EventExperimental,
   788  	evSync:                        EventSync,
   789  }
   790  
   791  var tracev2GoStatus2GoState = [...]GoState{
   792  	tracev2.GoRunnable: GoRunnable,
   793  	tracev2.GoRunning:  GoRunning,
   794  	tracev2.GoWaiting:  GoWaiting,
   795  	tracev2.GoSyscall:  GoSyscall,
   796  }
   797  
   798  var tracev2ProcStatus2ProcState = [...]ProcState{
   799  	tracev2.ProcRunning:          ProcRunning,
   800  	tracev2.ProcIdle:             ProcIdle,
   801  	tracev2.ProcSyscall:          ProcRunning,
   802  	tracev2.ProcSyscallAbandoned: ProcIdle,
   803  }
   804  
   805  // String returns the event as a human-readable string.
   806  //
   807  // The format of the string is intended for debugging and is subject to change.
   808  func (e Event) String() string {
   809  	var sb strings.Builder
   810  	fmt.Fprintf(&sb, "M=%d P=%d G=%d", e.Thread(), e.Proc(), e.Goroutine())
   811  	fmt.Fprintf(&sb, " %s Time=%d", e.Kind(), e.Time())
   812  	// Kind-specific fields.
   813  	switch kind := e.Kind(); kind {
   814  	case EventMetric:
   815  		m := e.Metric()
   816  		v := m.Value.String()
   817  		if m.Value.Kind() == ValueString {
   818  			v = strconv.Quote(v)
   819  		}
   820  		fmt.Fprintf(&sb, " Name=%q Value=%s", m.Name, m.Value)
   821  	case EventLabel:
   822  		l := e.Label()
   823  		fmt.Fprintf(&sb, " Label=%q Resource=%s", l.Label, l.Resource)
   824  	case EventRangeBegin, EventRangeActive, EventRangeEnd:
   825  		r := e.Range()
   826  		fmt.Fprintf(&sb, " Name=%q Scope=%s", r.Name, r.Scope)
   827  		if kind == EventRangeEnd {
   828  			fmt.Fprintf(&sb, " Attributes=[")
   829  			for i, attr := range e.RangeAttributes() {
   830  				if i != 0 {
   831  					fmt.Fprintf(&sb, " ")
   832  				}
   833  				fmt.Fprintf(&sb, "%q=%s", attr.Name, attr.Value)
   834  			}
   835  			fmt.Fprintf(&sb, "]")
   836  		}
   837  	case EventTaskBegin, EventTaskEnd:
   838  		t := e.Task()
   839  		fmt.Fprintf(&sb, " ID=%d Parent=%d Type=%q", t.ID, t.Parent, t.Type)
   840  	case EventRegionBegin, EventRegionEnd:
   841  		r := e.Region()
   842  		fmt.Fprintf(&sb, " Task=%d Type=%q", r.Task, r.Type)
   843  	case EventLog:
   844  		l := e.Log()
   845  		fmt.Fprintf(&sb, " Task=%d Category=%q Message=%q", l.Task, l.Category, l.Message)
   846  	case EventStateTransition:
   847  		s := e.StateTransition()
   848  		fmt.Fprintf(&sb, " Resource=%s Reason=%q", s.Resource, s.Reason)
   849  		switch s.Resource.Kind {
   850  		case ResourceGoroutine:
   851  			id := s.Resource.Goroutine()
   852  			old, new := s.Goroutine()
   853  			fmt.Fprintf(&sb, " GoID=%d %s->%s", id, old, new)
   854  		case ResourceProc:
   855  			id := s.Resource.Proc()
   856  			old, new := s.Proc()
   857  			fmt.Fprintf(&sb, " ProcID=%d %s->%s", id, old, new)
   858  		}
   859  		if s.Stack != NoStack {
   860  			fmt.Fprintln(&sb)
   861  			fmt.Fprintln(&sb, "TransitionStack=")
   862  			for f := range s.Stack.Frames() {
   863  				fmt.Fprintf(&sb, "\t%s @ 0x%x\n", f.Func, f.PC)
   864  				fmt.Fprintf(&sb, "\t\t%s:%d\n", f.File, f.Line)
   865  			}
   866  		}
   867  	case EventExperimental:
   868  		r := e.Experimental()
   869  		fmt.Fprintf(&sb, " Name=%s Args=[", r.Name)
   870  		for i, arg := range r.Args {
   871  			if i != 0 {
   872  				fmt.Fprintf(&sb, ", ")
   873  			}
   874  			fmt.Fprintf(&sb, "%s=%s", arg, r.ArgValue(i).String())
   875  		}
   876  		fmt.Fprintf(&sb, "]")
   877  	case EventSync:
   878  		s := e.Sync()
   879  		fmt.Fprintf(&sb, " N=%d", s.N)
   880  		if s.ClockSnapshot != nil {
   881  			fmt.Fprintf(&sb, " Trace=%d Mono=%d Wall=%s",
   882  				s.ClockSnapshot.Trace,
   883  				s.ClockSnapshot.Mono,
   884  				s.ClockSnapshot.Wall.Format(time.RFC3339),
   885  			)
   886  		}
   887  	}
   888  	if stk := e.Stack(); stk != NoStack {
   889  		fmt.Fprintln(&sb)
   890  		fmt.Fprintln(&sb, "Stack=")
   891  		for f := range stk.Frames() {
   892  			fmt.Fprintf(&sb, "\t%s @ 0x%x\n", f.Func, f.PC)
   893  			fmt.Fprintf(&sb, "\t\t%s:%d\n", f.File, f.Line)
   894  		}
   895  	}
   896  	return sb.String()
   897  }
   898  
   899  // validateTableIDs checks to make sure lookups in e.table
   900  // will work.
   901  func (e Event) validateTableIDs() error {
   902  	if e.base.typ == evSync {
   903  		return nil
   904  	}
   905  	spec := tracev2.Specs()[e.base.typ]
   906  
   907  	// Check stacks.
   908  	for _, i := range spec.StackIDs {
   909  		id := stackID(e.base.args[i-1])
   910  		_, ok := e.table.stacks.get(id)
   911  		if !ok {
   912  			return fmt.Errorf("found invalid stack ID %d for event %s", id, spec.Name)
   913  		}
   914  	}
   915  	// N.B. Strings referenced by stack frames are validated
   916  	// early on, when reading the stacks in to begin with.
   917  
   918  	// Check strings.
   919  	for _, i := range spec.StringIDs {
   920  		id := stringID(e.base.args[i-1])
   921  		_, ok := e.table.strings.get(id)
   922  		if !ok {
   923  			return fmt.Errorf("found invalid string ID %d for event %s", id, spec.Name)
   924  		}
   925  	}
   926  	return nil
   927  }
   928  
   929  func syncEvent(table *evTable, ts Time, n int) Event {
   930  	ev := Event{
   931  		table: table,
   932  		ctx: schedCtx{
   933  			G: NoGoroutine,
   934  			P: NoProc,
   935  			M: NoThread,
   936  		},
   937  		base: baseEvent{
   938  			typ:  evSync,
   939  			time: ts,
   940  		},
   941  	}
   942  	ev.base.args[0] = uint64(n)
   943  	return ev
   944  }
   945  

View as plain text