tracer: load unwinder eBPF programs concurrently

[alban]

Problem

Starting the tracer is dominated by loading the unwinder eBPF programs into the
kernel. Measured on an 8 vCPU arm64 VM, of the ~2.02s spent in NewTracer(),
~1.84s (91%) is spent loading eBPF programs:

Phase	Time
kallsyms.NewSymbolizer	121 ms
LoadCollectionSpec	6 ms
loadRodataVars	29 ms
loadAllMaps	102 ms
rewriteMaps	6 ms
loadPerfUnwinders	934 ms
loadProbeUnwinders	910 ms
pmebpf.LoadMaps + pm.New	< 1 ms
NewTracer total	~2.02 s

The programs are loaded one at a time, and each load blocks in the kernel
verifier. Verification of one program does not depend on any other program, so
the loads can run concurrently.

Change

Split the collection of the programs to load from the loading itself:

• perfUnwinderJobs() and probeUnwinderJobs() only prepare the (already
  existing) per-program work, including the probe specific instruction rewrites.
  They do not touch the kernel.
• loadPrograms() then verifies the collected jobs with a bounded
  errgroup, limited to GOMAXPROCS. Everything that mutates shared state,
  registering the programs in ebpfProgs and updating the tail call maps, stays
  sequential and happens once all programs are loaded.

The perf and the probe unwinders refer to disjoint sets of program
specifications ("perf_" and "kprobe_" prefixed), and the probe unwinders only
depend on maps that are already loaded at that point, not on the loaded perf
programs. Their jobs are therefore collected first and loaded together, so the
two groups are verified concurrently as well.

rlimit.MaximizeMemlock() was called per program. It changes a process wide
resource limit and restores it afterwards, so it must not run while other
programs are being loaded. It is now called once for the whole loading phase.

loadPerfUnwinders() and loadProbeUnwinders() keep their signatures; the
latter is still used to load probes at runtime from probes.go.

Program load errors are no longer logged from the loading goroutines. A verifier
error is hundreds of lines long and is logged line by line, so logging it
concurrently would interleave several of them into an unreadable mess. Each job
records its error instead, and once all loads have finished the failures are
reported in job order, so the error that is returned does not depend on the order
in which the loads happened to complete. A single unsupported instruction usually
makes every program fail, so only the first failure is logged in full and the
others are summarized; the sequential loader used to stop at the first failure
and so only ever printed one log.

Results

Adds BenchmarkNewTracer (tracer/ebpf_integration_test.go), the first benchmark
covering tracer startup. Run with:

sudo go test -tags integration -run='^$' -bench=BenchmarkNewTracer \
    -benchtime=5x -count=10 ./tracer/

benchstat over 10 runs each, 8 vCPU arm64 VM:

goos: linux
goarch: arm64
pkg: go.opentelemetry.io/ebpf-profiler/tracer
            │   old.txt    │               new.txt               │
            │    sec/op    │   sec/op     vs base                │
NewTracer-8   2062.9m ± 4%   810.5m ± 2%  -60.71% (p=0.000 n=10)

The program loading phase itself goes from ~1.84s to ~0.60s (~3.0x). The
end-to-end number is lower than that because NewTracer also does work this
change does not touch (NewSymbolizer, map creation).

A note on profiling this code path

The Go CPU profiler cannot be used to measure eBPF program loading: cilium/ebpf
masks SIGPROF around the program load syscall (maskProfilerSignal() in
internal/sys), so the verifier time is invisible to the profiler. A CPU profile
of this benchmark only samples ~23% of the wall time and attributes a large
share to unmaskProfilerSignal, which is an artifact. The numbers above are
wall-clock measurements.

Testing

• go vet -tags integration ./tracer/ and gofmt are clean.
• sudo go test -tags integration -count=1 ./tracer/... passes, including the
  eBPF integration tests TestTracerErrorPropagation, TestTracerMapMonitorsError,
  TestTraceTransmissionAndParsing and TestAllTracers.
• The same integration tests pass under -race, exercising the concurrent
  loading path.

AI disclosure

The commit carries an Assisted-by: trailer as required by the OpenTelemetry
GenAI policy (https://github.com/open-telemetry/community/blob/main/policies/genai.md).

AIL:3

("AI Created, Human Full Structure" on the AI Influence Level scale,
https://danielmiessler.com/blog/ai-influence-level-ail: the problem statement,
the constraints, the measurement methodology and the review of each hypothesis
were mine; the implementation and the benchmark were written by the model within
that structure. I have read, understood and tested the result, and I take
responsibility for it.)

[alban]

I added a second commit, tracer: load the most expensive eBPF programs first, which cuts the program load phase by a further 19% on a 4 CPU machine on top of the concurrent loading in the first commit.

Why there was anything left to gain

Loading the programs concurrently makes this phase bounded by the single slowest program rather than by the total amount of work. unwind_python takes ~0.5s to verify on its own, which is roughly 30% of the total verification work across all 27 programs. Unless it is started early, it keeps running long after everything else has finished and it alone decides how long the phase takes.

The order the jobs are currently submitted in is just the order they happen to be built in, which is unrelated to cost. Every unwinder is loaded twice, once for perf and once for kprobe, and the two sets are concatenated by append(perfJobs, probeJobs...):

 0 perf_unwind_stop      12 tracepoint__sched_process_free   15 kprobe_unwind_stop
 1 perf_unwind_native    13 tracepoint__sys_exit_prctl       16 kprobe_unwind_native
 2 perf_unwind_perl      14 native_tracer_entry              17 kprobe_unwind_perl
 3 perf_unwind_python                                        18 kprobe_unwind_python
 4 perf_unwind_php                                           19 kprobe_unwind_php

perf_unwind_python is job 3, so it always starts immediately. But the identical and equally expensive kprobe_unwind_python is job 18, and cannot start until enough of the preceding jobs have finished. The phase is extended by exactly that delay.

The change

Sort the jobs longest-first before submitting them, using the instruction count as the cost proxy. This is longest-processing-time-first scheduling.

Results

Program load makespan, comparing the existing build order against the sorted order on the same binary (the ordering is switched at runtime so both arms are byte-identical), interleaved A/B runs, benchstat with n=12:

CPUs	build order	sorted	change
8	561.1m ± 5%	518.4m ± 5%	−7.61% (p=0.001)
4	631.9m ± 4%	509.8m ± 3%	−19.33% (p=0.000)
2	1000.5m ± 2%	843.8m ± 3%	−15.66% (p=0.000)

Relative to the pre-PR sequential baseline of ~1.70s, the two commits together give:

CPUs	baseline	first commit	both commits
8	1701.3m ± 1%	561.1m (−67.02%)	518.4m (−69.53%)
4	1711.2m ± 1%	631.9m (−63.07%)	509.8m (−70.21%)
2	1703.5m ± 2%	1000.5m (−41.27%)	843.8m (−50.47%)

The lower bound for this phase is max(longest job, total work / CPUs). At 8 and 4 CPUs that bound is the ~510ms of unwind_python itself, and the sorted numbers sit on it — so this removes the scheduling loss entirely rather than merely reducing it. At 2 CPUs the phase is work bound instead, and the sort helps by packing the remaining jobs more tightly. The gain is largest on the 2–4 CPU machines typical of CI runners and containers.

On the cost proxy

The instruction count is deliberately coarse. It ranks unwind_python and unwind_native first, which is all the schedule depends on, but it misranks the cheaper programs — unwind_stop is large yet verifies quickly, while go_labels is small yet verifies slowly. I tried loop-aware and backward-jump-aware metrics and they ranked worse, because verifier cost is driven by state pruning rather than by anything visible in a static scan. There is a comment in the code saying so, to stop someone "fixing" it later.

If a more exact proxy is ever wanted, ProgramInfo.VerifiedInstructions() gives the real post-load figure on kernel ≥ 5.16 and would make a good CI guard test pinning the top two.

Measurement setup

Reproducing this on other hardware would be welcome, in particular on x86-64.

• arm64, 8 vCPU, kernel 7.0.0-31-generic
• all interpreters enabled (27 programs loaded)
• CPU counts restricted with taskset -c
• makespan of the load phase measured in isolation, not end to end — the end-to-end number is swamped by variance in loadAllMaps

Per-program load times (mean of 3 runs at 8 CPUs)

These are measured under 8-way contention, so they are upper bounds.

program	ms
perf_unwind_python	535–560
kprobe_unwind_python	521–528
kprobe_unwind_native	158
perf_unwind_native	149
unwind_ruby	74–78
unwind_v8, go_labels	32–37
unwind_hotspot	20–22
unwind_perl, unwind_php	8–9
unwind_dotnet	5–7

Total ≈ 1823ms across 27 programs.

Unrelated observation

While measuring this I noticed unwind_python reaches 603410 processed instructions, about 60% of the 1M verifier ceiling, and that this grows linearly at ~43k per python_frames_per_program iteration (82% of the ceiling at 20 frames). The cost per iteration is essentially one full native unwind step, because Python is the only interpreter that inlines unwind_one_frame into its loop. That is not something this PR changes, but it is close enough to the limit to be worth someone's attention.

[opentelemetry-pr-dashboard]

Pull request dashboard status

Waiting on the author · refreshed 2026-09-10 20:29 UTC

Respond to 3 review items (e.g. link a commit, explain why not, ask a follow-up):

• Inline threads: 1, 2
• Top-level threads: 3

Status above doesn't look right?

• Just replied or pushed? Anything around or after the refresh time above may not be picked up yet — give it a few minutes.
• Should this be with reviewers? Comment /dashboard route:reviewers to route it to them.
• Anything wrong — including the routing? Report it with what you expected; it helps us improve the dashboard.

[wehzzz]

Since this seems to be dead code, can we safely remove it?

[alban]

Thanks, removed.

[wehzzz]

Currently, no callers in the profiler deal with these failed loads, so the comment might be misleading here (this was also the case before, if I'm not mistaken).

If this is behavior we want to support for users, it should be explicit in LoadProbeUnwinders rather than here. Even then, I'm not sure we should make the user handle it instead of handling it directly in the code.

Suggested change

	// Hand over every program that did load, so that a partially failed load is
	// still cleaned up by the caller.
	// Register every program that did load, also on a partial failure, so the
	// loaded programs stay reachable for the caller. No current caller closes
	// them on error.

[alban]

Good catch. main does the same: the loaded programs stay in ebpfProgs, which the caller discards, so they're only closed once the GC runs cilium/ebpf's fd cleanup. Rather than document that, I think it is better if  loadPrograms  closes them on failure and hands over nothing; safe there because the tail call maps haven't been updated yet. I updated the PR.

[florianl]

I think, this change would cause issues atm originating from (*ProbeContext) CollectionSpecWith(...) and the use of *cebpf.ProgramSpec.Copy() and *cebpf.MapSpec.Copy(), as these XYZ.Copy() functions only create shallow copies. Modifying/rewriting one might causes issues in another. Currently, this is not an issue, as elements are loaded sequentually.

[florianl]

Maybe that is a personal preference, but I tend to look for getting all errors instead of just the first one. If subsequent errors are hidden, one might miss something in the whole picture/situation.

[florianl]

Here we cause a resource leakage if some programs load but others fail. In this case, some error is returned, OTel collector might keep running, depending on ErrorMode, and partial programs and maps are being kept loaded.