The problem with unbounded tracing
Event tracing writes 32 bytes per function entry and 32 per exit. A call-heavy program reaches millions of events per second, so a few seconds of tracing is hundreds of megabytes and a few minutes is more disk than most embedded targets have at all. Left unbounded that is not a slow leak — it is a device that stops working, in the middle of the investigation you were running.
So capture is bounded by default. You can turn the bound off, but you have to say so.
| Variable | Default | Meaning |
|---|---|---|
TRACE_MAX_MB | 512 | Total on-disk budget for the process. 0 means unlimited |
TRACE_FULL | stop | What happens at the budget: stop keeps the beginning, wrap keeps the end |
TRACE_SEG_MB | 32 | Segment size, which is the rotation granularity. Under wrap this is an upper bound — see below |
TRACE_MIN_FREE_MB | 64 | Stop if the filesystem falls below this much free space. 0 disables the check |
TRACE_MAX | 0 | Global event cap, as an upper bound |
Keep the start, or keep the end
The two policies answer different questions.
stop (the default) records until the budget is gone and
then stops. Use it when the interesting behaviour is at the beginning — startup cost,
initialization order, the first request.
TRACE_ENABLE=1 TRACE_MAX_MB=256 ./bin/app.instr
wrap turns the trace directory into a flight recorder: old
segments are discarded as new ones are written, so what survives is the most recent
TRACE_MAX_MB of execution. Use it for the question instrumentation answers
better than anything else — what was this program doing in the moments before it
hung?
TRACE_ENABLE=1 TRACE_MAX_MB=256 TRACE_FULL=wrap ./bin/app.instr
# ... reproduce the hang, then kill it and analyze what is left
callsight analyze labels it that way rather than leaving you to wonder.
Segments
Each thread writes trace.<pid>.<tid>.<seq>.bin, rotating
to a new sequence number every TRACE_SEG_MB. Segments are what make rotation
possible at all — wrap works by unlinking a whole segment — and they keep any
single file small enough to copy off a device.
Under wrap, TRACE_SEG_MB is an upper bound rather than the
size actually used. A thread can never discard the segment it is currently writing, so the
steady state holds up to two segments per thread; with a couple of dozen threads a fixed
32 MB segment would overshoot a small budget by an order of magnitude. The runtime
therefore sizes segments against the budget and the number of participating threads. A
floor of 64 KB per segment remains, so a very small budget spread over many threads
still cannot be honoured exactly — roughly threads × 128 KB is the practical
minimum.
Files are never appended to. The kernel recycles thread ids, so a long-running pool eventually hands a new thread an id that an earlier one used; appending there would put a second file header in the middle of an existing capture and shift every later record off the 32-byte grid. The sequence number makes that unrepresentable.
Budget accounting happens once per flush — every 8192 events — not once per event. A shared counter touched by every thread on every hook would serialize the whole program on one cache line exactly when tracing is heaviest.
Summary mode: runs of any length
If what you want is which functions cost the most rather than a timeline, you
do not need the events at all. TRACE_MODE=summary aggregates inside the
process — call counts, inclusive and self time, min, max and a latency histogram per
function, over a per-thread shadow stack — and writes only totals when the thread exits.
TRACE_ENABLE=1 TRACE_MODE=summary ./bin/app.instr
Memory is proportional to the number of instrumented functions, not to the number of calls, and so is the output. On the project's own benchmark, a run that writes 244 MB of events in the default mode writes 2.8 KB in summary mode — and writes the same 2.8 KB when the run is ten times longer:
$ python3 tests/bench/run_bench.py
mode total vs plain ns/hook on disk
plain build (no hooks) 0.9ms 1.00 - -
instrumented, tracing off 5.9ms 6.73 0.6 -
TRACE_CLOCK=tsc (default here) 97.1ms 111.70 12.0 244.1MB
TRACE_CLOCK=mono 130.6ms 150.22 16.2 244.1MB
TRACE_MODE=summary 65.1ms 74.84 8.0 2.8KB
summary mode on disk: 2.8KB for 200,000 iterations, 2.8KB for 2,000,000 — constant
Summary mode is also the cheaper hot path: there is no event record to write and no I/O to do. What you give up is anything that needs an ordering — flame graphs, the Perfetto timeline, and hot call sites all need the call paths that only event mode records.
| events (default) | summary | streaming | |
|---|---|---|---|
| On-disk growth | bounded by TRACE_MAX_MB | constant | none on the device |
| Run length | until the budget | unbounded | unbounded |
| Counts & times | exact | exact | exact, minus ring drops |
| Percentiles | yes | yes | yes |
| Flame graph / timeline | yes | no | yes |
| Needs | disk | nothing | a network path to a server |
The free-space floor
The budget bounds what callsight writes; the floor bounds what it leaves behind for
everyone else. Every 4 MB per thread the runtime checks the filesystem holding the trace
directory and stops if free space has fallen below TRACE_MIN_FREE_MB. The
check is a statvfs syscall roughly once per 130,000 events, which is not
measurable next to the events themselves.
Write failures are checked too. If a write fails part way — a full disk, a quota, a size limit — the partial record is trimmed off so the file stays well-formed, the capture stops, and the reason goes to stderr and into the trace. The old behaviour was to ignore the return value, which produced a report that looked clean and was simply missing everything after the failure.
Nothing ends silently
Whenever capture ends for a reason other than the program finishing, the runtime writes
a marker into the trace itself, and callsight analyze prints
it above the tables:
events=850059 threads=24 functions=84 span=6.6ms unmatched_exits=0 unclosed_enters=127
! capture stopped: the 512 MB on-disk budget was reached (TRACE_MAX_MB); everything
after that point is missing
| Marker | Means |
|---|---|
budget | TRACE_MAX_MB was reached under the stop policy |
wrap | Segments were discarded; the report covers the end of the run |
nospace | Free space fell below TRACE_MIN_FREE_MB |
write_error | A write failed; the payload is the errno |
max_events | The TRACE_MAX event cap was reached |
truncated | A segment ends mid-record: the process was killed, or a write failed part way |
Markers are ordinary 32-byte records with their own event kind, so they cost nothing to carry and any reader that does not understand one skips it. They travel over the streaming protocol as well.
The server side
The same reasoning applies to the analysis host. callsight serve bounds and
rotates its output per connection, because a device that streams for an hour should not
fill the machine you are analyzing on either.
callsight serve --max-mb 4096 --seg-mb 256
Choosing a bound
- Leave the default unless you have a reason. 512 MB is around 16 million events — enough to see structure, small enough to be harmless.
- On a device, set it far lower and consider streaming instead, which writes nothing locally at all.
- Chasing a hang or a rare stall?
TRACE_FULL=wrapwith a budget you can afford to keep resident. - Profiling a long run?
TRACE_MODE=summary. Hours of execution, kilobytes of output, exact counts. - Cutting volume at the source beats cutting it afterwards. The config file decides which functions emit hooks at all, and excluded code costs nothing at runtime.