THE LACK THEREOF

Deep Code Tracing

(Draft blog entry)

Let's have some fun with tracing code!

Here is a nice way to get Elasticsearch+Kibana up and running:

docker run -d -p 9200:9200 -p 5601:5601 nshou/elasticsearch-kibana

We're going to record our traces as a time-series. We unfortunately have to do a small config first, to ES know that our timestamp is ... a timestamp:

curl -v -XPUT 'http://elastic:changeme@localhost:9200/trace' -d '
{
  "mappings": {
    "trace": {
      "properties": {
        "timestamp": {
          "type": "date"
        }
      }
    }
  }
}'

Now we need to write down interesting things during our program execution. In my case, I'm working with a Rails project using RSpec. So I put this code near the top of spec/spec_helper.rb. Once executed, this code will start writing out to 'trace.log' lots and lots of tracing data:

git_sha = `git rev-parse HEAD`.chomp
trace_seq = 0
trace_log = File.new('trace.log', 'w')
trace_id = SecureRandom.uuid
trace = TracePoint.new(:line) do |tp|
  next unless tp.path.start_with?(Rails.root.to_s)
  event = {
    trace_id: trace_id,
    timestamp: Time.now.utc.round(10).iso8601(6),
    git_sha: git_sha,
    path: tp.path,
    line: tp.lineno,
    class: tp.defined_class.to_s,
    method: tp.method_id,
    seq: (trace_seq += 1)
  }
  if $rspec_example
    event.merge!({
      rspec_location: $rspec_example.location,
      rspec_description: $rspec_example.description,
      rspec_full_description: $rspec_example.full_description,
    })
  end
  trace_log.puts(event.to_json)
end
trace.enable

I have some stuff in there that is specific to RSpec. Later in the same file I put this config to track the current test being executed:

config.before :each do
  $rspec_example = example
end
config.after :each do
  $rspec_example = nil
end

Then I run my tests, which outputs trace.log. With this tracing turned on, it went at about half the normal speed. Mine is 123M (after disabling some logging). Now we load it into our ES. I do this in batches of 10k, and then POST it into ES:

cat trace.log \
  | jq -c '. | {"index": {"_index": "trace", "_type": "trace"}}, .' \
  | split -l 10000 - load-

for f in load-* ; do
  cat $f | curl -XPOST 'http://elastic:changeme@localhost:9200/_bulk' --data-binary @- >/dev/null
done

# I guess we could clean up now...
rm load-*

OK! Now we can finally have some fun!

Load up http://localhost:5601/

Given a file, annotate the lines with a list of the tests that touch that line:

FILEPATH=$1

curl -s -XGET "localhost:9200/trace/_search?q=%2Bpath:$FILEPATH%20%2Bline:%5B1%20TO%20100000%5D&sort=timestamp:desc&size=10000&pretty" \
  | jq -r '.hits.hits[]._source| "\(.line) \(.rspec_location)"' \
  | sort -u -n

Given a file and a line, list all of the tests that cover that line:

#!/bin/sh

FILEPATH=$1
LINE=$2

curl -s -XGET \
  "localhost:9200/trace/_search?q=%2Bpath:$FILEPATH%20%2Bline:$LINE&sort=timestamp:desc&size=1000&pretty" \
  | jq -r '.hits.hits[]._source.rspec_location' \
  | sort -u

Ideas:

Related work:

Navigation

Blog

https://thelackthereof.org/pics/16px-Feed-icon.svg.png Blog RSS Feed

Tweets


Code

Follow @awwaiid

Wiki Edits

https://thelackthereof.org/pics/16px-Feed-icon.svg.png Wiki RSS Feed

... more changes