tracing

Overview ¶

Package tracing provides usage and runtime support for Go tracing facilities.

Trace events ¶

A Go package can define several events of interest to trace via special comments. With such definition a tracing event becomes associated with trace function that is used to signal when the event happens. For example:

package hello

//trace:event traceHelloPre(who string)
//trace:event traceHello(who string)

func SayHello(who string) {
	traceHelloPre(who)
	fmt.Println("Hello, %s", who)
	traceHello(who)
}

By default using trace function does nothing and has very small overhead(*).

Probes ¶

However it is possible to attach probing functions to events. A probe, once attached, is called whenever event is signalled in the context which triggered the event and pauses original code execution until the probe is finished. It is possible to attach several probing functions to the same event and dynamically detach/(re-)attach them at runtime. Attaching/detaching probes must be done under tracing.Lock. For example:

type saidHelloT struct {
	who  string
	when time.Time
}
saidHello := make(chan saidHelloT)

tracing.Lock()
p := traceHello_Attach(nil, func(who string) {
	saidHello <- saidHelloT{who, time.Now()}
})
tracing.Unlock()

go func() {
	for hello := range saidHello {
		fmt.Printf("Said hello to %v @ %v\n", hello.who, hello.when)
	}
}()

SayHello("JP")
SayHello("Kirr")
SayHello("Varya")

tracing.Lock()
p.Detach()
tracing.Unlock()

close(saidHello)

For convenience it is possible to keep group of attached probes and detach them all at once using ProbeGroup:

pg := &tracing.ProbeGroup{}

tracing.Lock()
traceHelloPre_Attach(pg, func(who string) { ... })
traceHello_Attach(pg, func(who string) { ... })
tracing.Unlock()

// some activity

// when probes needs to be detached (no explicit tracing.Lock needed):
pg.Done()

Probes is general mechanism which allows various kinds of trace events usage. Three ways particularly are well-understood and handy:

• recording events stream
• profiling
• synchronous tracing

Recording events stream ¶

To get better understanding of what happens when it is possible to record events into a stream and later either visualize or postprocess them. This is similar to how Go execution tracer works:

https://golang.org/s/go15trace
https://golang.org/pkg/runtime/trace
https://golang.org/cmd/trace

though there it records only predefined set of events related to Go runtime.

TODO tracing should provide infrastructure to write events out in format understood by chromium trace-viewer: https://github.com/catapult-project/catapult/tree/master/tracing

NOTE there is also talk/work to implement user events for runtime/trace: https://golang.org/issues/16619.

Profiling ¶

A profile is aggregate summary of collection of stack traces showing the call sequences that led to instances of a particular event. One could create runtime/pprof.Profile and use Profile.Add in a probe attached to particular trace event. The profile can be later analyzed and visualised with Profile.WriteTo and `go tool pprof`.

Please refer to runtime/pprof package documentation for details.

XXX Profile.Add needs unique value for each invocation - how do we do? Provide NaN every time?

XXX should tracing provide more tight integration with runtime/pprof.Profile?

Synchronous tracing ¶

For testing purposes it is sometimes practical to leverage the property that probes pause original code execution until the probe run is finished. That means while the probe is running original goroutine

• is paused at well-defined point (where trace function is called), thus
• it cannot mutate any state it is programmed to mutate.

Using this properties it is possible to attach testing probes and verify that a set of goroutines in tested code in question

• produce events in correct order, and
• at every event associated internal state is correct.

Please see package lab.nexedi.com/kirr/go123/tracing/tracetest for details.

Cross package tracing ¶

Trace events are not part of exported package API with rationale that package's regular API and internal trace events usually have different stability commitments. However with tracing-specific importing mechanism it is possible to get access to trace events another package provides:

package another

//trace:import "hello"

This will make _Attach functions for all tracing events from package hello be available as regular functions prefixed with imported package name:

tracing.Lock()
hello_traceHello_Attach(nil, func(who string) {
	fmt.Printf("SayHello in package hello: %s", who)
})
tracing.Unlock()

...

Gotrace ¶

The way //trace:event and //trace:import work is via additional code being generated for them. Whenever a package uses any //trace: directive, it has to organize to run `gotrace gen` on its sources for them to work, usually with the help of //go:generate. For example:

package hello

//go:generate gotrace gen .

//trace:event ...

Besides `gotrace gen` gotrace has other subcommands also related to tracing, for example `gotrace list` lists trace events a package provides.

Please see `gotrace help` and lab.nexedi.com/kirr/go123/tracing/cmd/gotrace for gotrace documentation.

--------

(*) inlined check whether a global pointer != nil.