Analysis — callsight

The report

$ callsight analyze traces/ --exe bin/matrixlab.instr --top 5
events=1000000 threads=26 functions=139 span=48.7ms unmatched_exits=0 unclosed_enters=136

== TOP BY SELF TIME ==
     calls      incl_ms      self_ms       max_ms  function (first location)
       272      529.382      529.382        9.983  timer_sleep_us (src/utils/timer.c:38)
    127048       52.470       52.470        6.643  qs_swap (src/sort/quicksort.c:5)
     57284      366.418       35.370        5.738  fft_recursive (src/signal/fft.c:63)
    104870       33.523       33.523       10.017  stats_running_push (src/stats/statistics.c:84)
      3195       60.699       30.238       18.485  qs_partition (src/sort/quicksort.c:23)

== TOP BY INCLUSIVE TIME ==
…

== PER-THREAD SUMMARY ==
     tid     events      span_ms

Trace files are streamed rather than loaded, so a multi-million-event run costs a few MB of analyzer memory instead of scaling with the event count.

The columns

Column	Meaning	Use it to find
`calls`	Times the function was entered and matched with an exit.	Exclusion candidates. The biggest numbers are your event volume.
`incl_ms`	Wall time from enter to exit, children included. Recursive frames each count their own span.	Which high-level operation is slow.
`self_ms`	Inclusive minus the time spent inside instrumented children.	Where the work actually happens. The hot leaves.
`max_ms`	The single slowest call.	Tail latency. A small mean with a large max is a stall.

Self time is only "self" relative to what you instrumented. Time spent in an excluded callee is attributed to its caller, because no hook marked the boundary. That is usually what you want — but it is why a function can look hot right after you exclude the thing it calls.

The summary line

Field	Meaning
`events`	Enter and exit records read across all trace files.
`threads`	Distinct thread ids seen.
`functions`	Distinct functions with at least one completed call.
`span`	First to last timestamp across all threads.
`unmatched_exits`	Exits with no matching enter. 0 means a clean trace.
`unclosed_enters`	Frames still open at the end — normal: threads parked inside a call when the run ended, or when `TRACE_MAX` stopped collection mid-stack.

Flame graphs

--format folded prints one collapsed stack per call path, with self time in nanoseconds — the input format that flamegraph.pl and speedscope read.

$ callsight analyze traces/ --exe ./yourapp.instr --format folded > out.folded
$ head -2 out.folded
thread_main;workload_matrix;workload_sleep;timer_adaptive_sleep;timer_sleep_us 93371544
thread_main;workload_signal;workload_sleep;timer_adaptive_sleep;timer_sleep_us 91943551

$ flamegraph.pl out.folded > out.svg     # or drop out.folded into speedscope.app

Flame graph of the matrixlab workload showing per-workload towers and the recursive fft and quicksort stacks

The bundled matrixlab workload — 1,000,000 events, 26 threads. The tall narrow towers are the recursive fft_recursive and qs_recursive call chains.

Because the values are self time, the folded total equals the sum of the self_ms column — the flame graph and the table are two views of exactly the same numbers.

JSON for your own tooling

$ callsight analyze traces/ --exe ./yourapp.instr --format json --top 0 > report.json

The whole report: summary counters, one row per function (function, location, calls, incl_ms, self_ms, max_ms), and a per_thread array. Rows come sorted by self time; --top 0 keeps every one of them.

{
  "events": 1000000,
  "threads": 26,
  "functions": 139,
  "span_ms": 48.697,
  "unmatched_exits": 0,
  "unclosed_enters": 136,
  "rows": [
    { "function": "timer_sleep_us", "location": "src/utils/timer.c:38",
      "calls": 272, "incl_ms": 529.382, "self_ms": 529.382, "max_ms": 9.983 }
  ],
  "per_thread": [ { "tid": 60475, "events": 39104, "span_ms": 44.9 } ],
  "tool": "callsight", "version": "0.3.0"
}

Two obvious uses: diffing two runs to see whether a fix helped, and asserting in CI that a function's call count or self time hasn't regressed.

The tightening loop

Run wide. No include lines — instrument everything, with a TRACE_MAX so the run stays bounded.
Sort by calls. The top rows are usually tiny leaf helpers: accessors, swaps, hashes, RNG.
Exclude them in trace.config and rebuild. Volume typically drops 10–100× and the structure gets clearer, not worse.
Now read self_ms. With the noise gone, the real hot leaves are visible.
Zoom in. include-func <entry point> to trace one task's subtree and nothing else.

When a trace looks wrong

Every function is `??`

The binary was linked as a position-independent executable, so recorded runtime addresses don't match link addresses. analyze warns when most addresses fail to resolve. Relink with -no-pie — both build integrations already do.

A function I expected is missing

It was inlined — no call boundary means no hook. Check with nm, or build that file at a lower optimization level.
It is excluded — run callsight scan . --config trace.config to see the selection.
It is only reached through a function pointer and you used include-func: static call-graph resolution can't follow those.
It never returned during the trace — only completed calls appear in the table.

`unmatched_exits` is not zero

Some exits had no matching enter. Normal causes: TRACE_THREADS activating a thread mid-call (events before the match are absent by design), a TRACE_MAX cap hit mid-stack, or a truncated tail from a killed process. A large count with none of those in play is worth reporting.

`addr2line not found`

Install binutils (apt install binutils), or put the matching cross-toolchain addr2line on PATH when analyzing a trace from another architecture.

No trace files

The run needs TRACE_ENABLE=1 — without it the hooks are inert by design. Check TRACE_DIR, and remember that the process must exit cleanly (or the threads must finish) for the last buffers to flush.

Configuration →Turn what you learned into a tighter selection. Web UI →The same report, sortable, in a browser.