Execution tracing a SQL query

NB: “trace” or “tracing” herein refers to the go runtime’s tracing. This is not the distributed tracing, which is the instrumentation we add at the application level, although these certainly overlap in places.

traceon / traceoff

Adding traceon somefile.trace to a logic test will start tracing at that point, until traceoff is called. go tool trace can then be used to render the trace data (see demo below).

AnnotateTrace()

The AnnotateTrace() method in util/tracer makes a cgo call to a noop, void c method. Since all cgo calls are recorded as events in the trace, with their stacktraces, this provides a very lightweight and quick way to add a marker to a trace.

ANNOTATE_TRACES=1

As cgo calls are not "free", AnnotateTrace only makes the cgo call when the env var ANNOTATE_TRACES is set. Thus it is "safe" to leave AnnotateTrace calls in production code, but ANNOTATE_TRACES=1 must be passed when running the code being traced.

Demo

$ go test -i -c ./sql
…
$ ANNOTATE_TRACES=1 ./sql.test -test.run TestLogic -d sql/tracedata/update
…
$ go tool trace ./sql.test update.trace
[opens in chrome]

Using the Trace Viewer

The trace viewer ONLY WORKS IN CHROME. They baked the client directly into chrome and rely on that, so opening a trace in Safari or whatever will just complain that tr is undefined.

If you haven't used this before: Using the arrow/select tool, dragged across a single slice, will show the stack trace for that slice. AFAIK, binary searching with that is the best way to find the stacktrace for the AnnotateTrace() call you are interested in. The range select tool measures the time between slices.

Making the viewer bigger

The Chrome extension "stylebot" allows applying user-set styles based on URL regex.

127.0.0.1**/trace:

#analysis {
    display: block;
    height: 1000px;
}