Tracing: optimize and reduce overhead

[edwintorok]

We've noticed some delays when tracing is enabled, and suspected it is due to lock contention or GC activity created by the tracing module itself.

I've added some benchmarks to measure the overhead of tracing, and made some improvements (more improvements are possible).
The benchmarks test both a situation with no workload, and a situation with 2 other threads: one running the same workload as the function under test, and another that runs a very GC intensive workload.

Improved:

• when max spans limit is hit: don't spam syslog. Time goes down from 202 milliseconds to 14 microseconds per span
• reduce lock contention: eliminate one global lock, replace with atomic ops
• reduce allocation

We are now at ~9µs/nested span on this particular machine, but further improvements are possible by delaying work to the exporter thread and finishing really quickly otherwise (e.g. upstream ocaml-trace claims ~60ns/span).

When tracing is disabled the overhead is very small, just like before (on the order of 20ns without a workload).

Before:

Running benchmarks (no workloads)
╭─────────────────────────────────────┬───────────────────────────┬───────────────────────────┬───────────────────────────╮
│name                                 │  major-allocated          │  minor-allocated          │  monotonic-clock          │
├─────────────────────────────────────┼───────────────────────────┼───────────────────────────┼───────────────────────────┤
│  tracing/max span overflow          │             0.0000 mjw/run│          1187.0000 mnw/run│       96214066.4652 ns/run│
│  tracing/overhead(off)              │             0.0000 mjw/run│            14.0000 mnw/run│             19.0061 ns/run│
│  tracing/overhead(on, create span)  │             2.9250 mjw/run│           496.3888 mnw/run│          25431.5210 ns/run│
│  tracing/overhead(on, no span)      │             0.0000 mjw/run│            14.0000 mnw/run│             18.8063 ns/run│
╰─────────────────────────────────────┴───────────────────────────┴───────────────────────────┴───────────────────────────╯

tracing/overhead(on, no span) (ns):
 { monotonic-clock per run = 18.806282 (confidence: 20.597860 to 16.986898);
   r² = Some 0.63699 }
tracing/max span overflow (ns):
 { monotonic-clock per run = 96214066.465201 (confidence: 125336685.666667 to 70136316.380165);
   r² = Some 0.518256 }
tracing/overhead(off) (ns):
 { monotonic-clock per run = 19.006133 (confidence: 20.619355 to 17.390492);
   r² = Some 0.667542 }
tracing/overhead(on, create span) (ns):
 { monotonic-clock per run = 25431.521030 (confidence: 37607.254799 to 15151.227932);
   r² = Some 0.0329005 }

Running benchmarks (workloads)
╭─────────────────────────────────────┬───────────────────────────┬───────────────────────────┬───────────────────────────╮
│name                                 │  major-allocated          │  minor-allocated          │  monotonic-clock          │
├─────────────────────────────────────┼───────────────────────────┼───────────────────────────┼───────────────────────────┤
│  tracing/max span overflow          │         80934.7363 mjw/run│      10580588.4725 mnw/run│      202271848.5714 ns/run│
│  tracing/overhead(off)              │             0.0000 mjw/run│            16.5479 mnw/run│            212.0958 ns/run│
│  tracing/overhead(on, create span)  │             0.0000 mjw/run│           503.4400 mnw/run│          15633.2400 ns/run│
│  tracing/overhead(on, no span)      │             0.0000 mjw/run│            18.3256 mnw/run│            326.9568 ns/run│
╰─────────────────────────────────────┴───────────────────────────┴───────────────────────────┴───────────────────────────╯

tracing/overhead(on, no span) (ns):
 { monotonic-clock per run = 326.956811; r² = Some -9.40099 }
tracing/max span overflow (ns):
 { monotonic-clock per run = 202271848.571429; r² = Some 0.065489 }
tracing/overhead(off) (ns):
 { monotonic-clock per run = 212.095829; r² = Some -4.46794 }
tracing/overhead(on, create span) (ns):
 { monotonic-clock per run = 15633.240000; r² = Some 0.805726 }

After:

Running benchmarks (no workloads)
╭─────────────────────────────────────┬───────────────────────────┬───────────────────────────┬───────────────────────────╮
│name                                 │  major-allocated          │  minor-allocated          │  monotonic-clock          │
├─────────────────────────────────────┼───────────────────────────┼───────────────────────────┼───────────────────────────┤
│  tracing/max span overflow          │             0.0964 mjw/run│           379.0196 mnw/run│          14479.0371 ns/run│
│  tracing/overhead(off)              │             0.0000 mjw/run│            14.0000 mnw/run│             18.2174 ns/run│
│  tracing/overhead(on, create span)  │             0.0000 mjw/run│           397.3440 mnw/run│          14712.1307 ns/run│
│  tracing/overhead(on, no span)      │             0.0000 mjw/run│            14.0000 mnw/run│             18.1771 ns/run│
╰─────────────────────────────────────┴───────────────────────────┴───────────────────────────┴───────────────────────────╯

tracing/overhead(on, no span) (ns):
 { monotonic-clock per run = 18.177093 (confidence: 19.990180 to 16.374104);
   r² = Some 0.600249 }
tracing/max span overflow (ns):
 { monotonic-clock per run = 14479.037101 (confidence: 15625.053708 to 13293.667720);
   r² = Some 0.635766 }
tracing/overhead(off) (ns):
 { monotonic-clock per run = 18.217390 (confidence: 19.845841 to 16.442527);
   r² = Some 0.642373 }
tracing/overhead(on, create span) (ns):
 { monotonic-clock per run = 14712.130670 (confidence: 23416.444172 to 7426.891454);
   r² = Some 0.0476263 }

Running benchmarks (workloads)
╭─────────────────────────────────────┬───────────────────────────┬───────────────────────────┬───────────────────────────╮
│name                                 │  major-allocated          │  minor-allocated          │  monotonic-clock          │
├─────────────────────────────────────┼───────────────────────────┼───────────────────────────┼───────────────────────────┤
│  tracing/max span overflow          │             0.0000 mjw/run│           380.4429 mnw/run│           7658.2207 ns/run│
│  tracing/overhead(off)              │             0.0000 mjw/run│            15.3007 mnw/run│            102.2479 ns/run│
│  tracing/overhead(on, create span)  │             0.0000 mjw/run│           400.5094 mnw/run│           8657.5585 ns/run│
│  tracing/overhead(on, no span)      │             0.0000 mjw/run│            18.1333 mnw/run│            373.9794 ns/run│
╰─────────────────────────────────────┴───────────────────────────┴───────────────────────────┴───────────────────────────╯

tracing/overhead(on, no span) (ns):
 { monotonic-clock per run = 373.979447 (confidence: 435.400802 to 336.056569);
   r² = Some -1.84338 }
tracing/max span overflow (ns):
 { monotonic-clock per run = 7658.220695 (confidence: 7952.878804 to 7396.117711);
   r² = Some 0.950954 }
tracing/overhead(off) (ns):
 { monotonic-clock per run = 102.247932 (confidence: 119.364768 to 89.830417);
   r² = Some -0.607146 }
tracing/overhead(on, create span) (ns):
 { monotonic-clock per run = 8657.558458 (confidence: 8904.596470 to 8435.216348);
   r² = Some 0.956299 }

Draft PR, this was only unit tested so far.

[edwintorok]

Tested in koji. Had to also increase max_spans because a single VM start in a pool would exceed it.
This should now be safe because we use the cardinal operation of Map/Set instead of List.length, so we no longer have O(n^2) performance issues.