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 / tradeoff

Adding traceon somefile.trace to a logic test will start tracing at that point, until traceoff is called, and go tool trace can then be used to render the collected trace in somefile.trace.

AnnotateTrace() / ANNOTATE_TRACES=1

All cgo calls are recorded as events in the trace, with their stacktraces, so a no-op cgo call is a lightweight and quick way to add a marker to a trace. The AnnotateTrace() call in util/tracer is intended for this purpose, but, as cgo calls are not "free", only actually makes the call if the ANNOTATE_TRACES env var is set.

Demo

(pwd: ./sql)

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

$ go test -v -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

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.

The Trace Renderer in Chrome is too small

The Chrome extension "stylebot" allows applying user-set styles based on URL regex. You might find this useful for 127.0.0.1**/trace:

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