trace

Documentation

Overview

Package trace contains facilities for programs to generate trace for Go execution tracer.

Tracing runtime activities

The execution trace captures a wide range of execution events such as goroutine creation/blocking/unblocking, syscall enter/exit/block, GC-related events, changes of heap size, processor start/stop, etc. A precise nanosecond-precision timestamp and a stack trace is captured for most events. The generated trace can be interpreted using `go tool trace`.

Support for tracing tests and benchmarks built with the standard testing package is built into `go test`. For example, the following command runs the test in the current directory and writes the trace file (trace.out).

go test -trace=test.out

This runtime/trace package provides APIs to add equivalent tracing support to a standalone program. See the Example that demonstrates how to use this API to enable tracing.

There is also a standard HTTP interface to trace data. Adding the following line will install a handler under the /debug/pprof/trace URL to download a live trace:

import _ "net/http/pprof"

See the net/http/pprof package for more details about all of the debug endpoints installed by this import.

User annotation

Package trace provides user annotation APIs that can be used to log interesting events during execution.

There are three types of user annotations: log messages, spans, and tasks.

Log emits a timestamped message to the execution trace along with additional information such as the category of the message and which goroutine called Log. The execution tracer provides UIs to filter and group goroutines using the log category and the message supplied in Log.

A span is for logging a time interval during a goroutine's execution. By definition, a span starts and ends in the same goroutine. Spans can be nested to represent subintervals. For example, the following code records four spans in the execution trace to trace the durations of sequential steps in a cappuccino making operation.

trace.WithSpan(ctx, "makeCappuccino", func(ctx context.Context) {

   // orderID allows to identify a specific order
   // among many cappuccino order span records.
   trace.Log(ctx, "orderID", orderID)

   trace.WithSpan(ctx, "steamMilk", steamMilk)
   trace.WithSpan(ctx, "extractCoffee", extractCoffee)
   trace.WithSpan(ctx, "mixMilkCoffee", mixMilkCoffee)
})

A task is a higher-level component that aids tracing of logical operations such as an RPC request, an HTTP request, or an interesting local operation which may require multiple goroutines working together. Since tasks can involve multiple goroutines, they are tracked via a context.Context object. NewContext creates a new task and embeds it in the returned context.Context object. Log messages and spans are attached to the task, if any, in the Context passed to Log and WithSpan.

For example, assume that we decided to froth milk, extract coffee, and mix milk and coffee in separate goroutines. With a task, the trace tool can identify the goroutines involved in a specific cappuccino order.

ctx, taskEnd:= trace.NewContext(ctx, "makeCappuccino")
trace.Log(ctx, "orderID", orderID)

milk := make(chan bool)
espresso := make(chan bool)

go func() {
   trace.WithSpan(ctx, "steamMilk", steamMilk)
   milk<-true
})()
go func() {
   trace.WithSpan(ctx, "extractCoffee", extractCoffee)
   espresso<-true
})()
go func() {
   defer taskEnd()  // When assemble is done, the order is complete.
   <-espresso
   <-milk
   trace.WithSpan(ctx, "mixMilkCoffee", mixMilkCoffee)
})()

The trace tool computes the latency of a task by measuring the time between the task creation and the task end and provides latency distributions for each task type found in the trace.

Example

Example demonstrates the use of the trace package to trace the execution of a Go program. The trace output will be written to the file trace.out

package main

import (
	"fmt"
	"log"
	"os"
	"runtime/trace"
)

// Example demonstrates the use of the trace package to trace
// the execution of a Go program. The trace output will be
// written to the file trace.out
func main() {
	f, err := os.Create("trace.out")
	if err != nil {
		log.Fatalf("failed to create trace output file: %v", err)
	}
	defer func() {
		if err := f.Close(); err != nil {
			log.Fatalf("failed to close trace file: %v", err)
		}
	}()

	if err := trace.Start(f); err != nil {
		log.Fatalf("failed to start trace: %v", err)
	}
	defer trace.Stop()

	// your program here
	RunMyProgram()
}

func RunMyProgram() {
	fmt.Printf("this function will be traced")
}

Index

• func IsEnabled() bool
• func Log(ctx context.Context, category, message string)
• func Logf(ctx context.Context, category, format string, args ...interface{})
• func NewContext(pctx context.Context, taskType string) (ctx context.Context, end func())
• func Start(w io.Writer) error
• func StartSpan(ctx context.Context, spanType string) func()
• func Stop()
• func WithSpan(ctx context.Context, spanType string, fn func(context.Context))

Examples

• Package

Functions

func IsEnabled

func IsEnabled() bool

IsEnabled returns whether tracing is enabled. The information is advisory only. The tracing status may have changed by the time this function returns.

func Log

func Log(ctx context.Context, category, message string)

Log emits a one-off event with the given category and message. Category can be empty and the API assumes there are only a handful of unique categories in the system.

func Logf

func Logf(ctx context.Context, category, format string, args ...interface{})

Logf is like Log, but the value is formatted using the specified format spec.

func NewContext

func NewContext(pctx context.Context, taskType string) (ctx context.Context, end func())

NewContext creates a child context with a new task instance with the type taskType. If the input context contains a task, the new task is its subtask.

The taskType is used to classify task instances. Analysis tools like the Go execution tracer may assume there are only a bounded number of unique task types in the system.

The returned end function is used to mark the task's end. The trace tool measures task latency as the time between task creation and when the end function is called, and provides the latency distribution per task type. If the end function is called multiple times, only the first call is used in the latency measurement.

ctx, taskEnd := trace.NewContext(ctx, "awesome task")
trace.WithSpan(ctx, prepWork)
// preparation of the task
go func() {  // continue processing the task in a separate goroutine.
    defer taskEnd()
    trace.WithSpan(ctx, remainingWork)
}

func Start

func Start(w io.Writer) error

Start enables tracing for the current program. While tracing, the trace will be buffered and written to w. Start returns an error if tracing is already enabled.

func StartSpan

func StartSpan(ctx context.Context, spanType string) func()

StartSpan starts a span and returns a function for marking the end of the span. The span end function must be called from the same goroutine where the span was started. Within each goroutine, spans must nest. That is, spans started after this span must be ended before this span can be ended. Callers are encouraged to instead use WithSpan when possible, since it naturally satisfies these restrictions.

func Stop

func Stop()

Stop stops the current tracing, if any. Stop only returns after all the writes for the trace have completed.

func WithSpan

func WithSpan(ctx context.Context, spanType string, fn func(context.Context))

WithSpan starts a span associated with its calling goroutine, runs fn, and then ends the span. If the context carries a task, the span is attached to the task. Otherwise, the span is attached to the background task.

The spanType is used to classify spans, so there should be only a handful of unique span types.