Execution Tracing a SQL Query

NB: “trace” or “tracing” herein refers to the go runtime’s tracing, which follows execution goroutine to goroutine and notes locks, blocking, syscalls, etc. 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() / ANNOTATE_TRACES=1

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.

However, as cgo calls are not "free", AnnotateTrace only makes the cgo call when the env var ANNOTATE_TRACES is set, making it "safe" to leave AnnotateTrace calls in production code.

Demo

(pwd: ./sql)

$ git diff
+traceon trace.out
+
+statement ok
+UPDATE kv SET v = k + v WHERE k = 3
+
+traceoff

$ go test -i -c
…
$ ANNOTATE_TRACES=1 ./sql.test -test.run TestLogic -d testdata/update
…
$ go tool trace ./sql.test trace.out
[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;
}