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() and the ANNOTATE_TRACES var

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]

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;
}