User-space Tracing with ftrace and bpftrace

Dynamic tracing transforms the notion that "a certain function might be slow" into observable events: how many times it was called, what arguments were passed, what was returned, and how long it took from entry to return. First, determine the tracing level and the identity of the target, then decide on the script. Identical function names, paths, or TIDs do not necessarily represent the same business request.

The commands in this article follow the bpftrace 0.24 documentation. /absolute/path/prog, function names, and PIDs are placeholders to be replaced. The target binary, kernel capabilities, and permissions must meet the requirements; examples do not assume that all systems have the same libc paths.

Responsibilities of Tools at Each Layer

tracefs is often mounted at /sys/kernel/tracing, with compatible paths possibly located under debugfs. Do not confuse the ftrace kernel function tracer, the entire tracefs infrastructure, and BPF as the same mechanism. ftrace documentation

Probe Addresses: Symbol Names, Virtual Addresses, and File Offsets Differ

bpftrace or perf probe can help resolve ELF symbols. However, the definition of the raw kernel uprobe_events interface uses the target file path and file offset; you cannot directly write /bin/bash:readline as the raw event format.

Given a symbol's virtual address v in an ELF file, to find the file-backed mapping it belongs to, the typical conversion is file_offset = p_offset + (v - p_vaddr), verifying that the address falls within the file content range of the corresponding segment. The runtime load base address for PIE (Position Independent Executable) is not the same as this file offset; directly inserting the runtime address will result in probing the wrong location.

The conceptual form of the raw interface is as follows, which is a format specification where OFFSET needs to be replaced with a verified value:

p:group/event /absolute/path/prog:OFFSET
r:group/event_return /absolute/path/prog:OFFSET

This is interface syntax, not a structural diagram. In practice, it is usually preferable to use symbol resolution tools to avoid manual calculation errors. Raw event management also involves enabling, buffer reading, and deletion by name. Uprobe tracer documentation

List Capabilities and Targets First

bpftrace --version
bpftrace --info
bpftrace -l 'uprobe:/absolute/path/prog:*work*'
bpftrace -lv 'uprobe:/absolute/path/prog:work'
bpftrace -lv 'tracepoint:syscalls:sys_enter_openat'
readelf -Ws /absolute/path/prog

If a function is inlined, deleted, or exists only as an optimized clone, it may not have an independent entry point; C++ name mangling and multiple symbols with the same name also require disambiguation. DWARF can help obtain typed parameters, but it must match the running build. Paths inside and outside containers, deleted old mappings, and file replacements also affect target location.

bpftrace's -p PID attaches to specific processes for supported user probes, filters other related probes by PID, and exits when the target ends; see the documentation for the specific version for details. --dry-run attempts to load and attach before exiting; it is not a pure offline syntax check. bpftrace CLI

Prepare a Small Target to Verify Symbols and Results

Save as trace-target.c. work is a non-recursive, synchronously returning C function. The entry size represents the number of items participating in the loop, and the return value is the accumulated result; it does not read or write size bytes, so if using the script model later, you should rename the metric to input item count.

#include <stdio.h>
__attribute__((noinline))
long work(unsigned long size) {
    volatile unsigned long total = 0;
    for (unsigned long i = 0; i < size; ++i) total += i & 7u;
    return (long)total;
}
int main(void) {
    long a = work(1000);
    long b = work(2000);
    printf("%ld %ld\n", a, b);
    return a == 3500 && b == 7000 ? 0 : 1;
}

cc -g -O1 trace-target.c -o trace-target
./trace-target
readelf -Ws ./trace-target
objdump -d ./trace-target

In this example, accumulation within the passed range and long conversion are valid. First confirm the existence of an independent entry for work, the program outputs 3500 7000, and then establish the probe; noinline is a compiler attribute to help preserve the observation point, and does not guarantee that any production build will use the same address and code shape.

Short-lived processes may end before manual attachment. If using bpftrace -c to launch the target, note that 0.24 does not filter all probes to that child process by default; for user context probes, you can explicitly filter using pid == cpid. Child processes started by the tool also inherit the tool's permissions; when choosing the execution method, ensure it matches the execution conditions of the original workload. bpftrace -c

Parameters: Read Parameters at Entry, Read Results at Return

For a long work(unsigned long size) compiled with the standard native C ABI, the entry uprobe can read arg0, and the return uretprobe can read retval. At return, parameter registers may have already been overwritten, so you cannot treat arg0 as the original size in the uretprobe.

The position of argN depends on the ABI and type classification. Floating-point types, structs, stack-passed arguments, and language-runtime-specific ABIs cannot be solved by arbitrarily replacing %si, %rdi, or x0. When you need to preserve entry parameters, record them at the entry and retrieve them at the matching return. bpftrace probe documentation

Reading strings also requires distinguishing between "pointer address" and "content at that time." str() attempts to read user memory at the time of the probe; string length is constrained by configuration, and incorrect addresses or content changes will affect the result. Do not automatically treat the returned pointer as the entry string.

A Latency Script with Clear Preconditions

Save the following as work.bt. The precondition is that the same thread does not nest, recurse, or re-enter work via a signal handler, and that calls return normally; if these conditions are not met, use the correlation design described later.

uprobe:/absolute/path/prog:work
{
    @start[tid] = nsecs(monotonic);
    @size[tid] = arg0;
}

uretprobe:/absolute/path/prog:work
/@start[tid]/
{
    @lat_us = hist((nsecs(monotonic) - @start[tid]) / 1000);
    if ((int64)retval >= 0) {
        @successful_input_bytes = sum(@size[tid]);
    }
    delete(@start, tid);
    delete(@size, tid);
}

END
{
    clear(@start);
    clear(@size);
}

bpftrace -p 12345 work.bt

Here, we additionally stipulate that a non-negative return value represents success, and we accumulate the sum of entry sizes for successful calls, not live memory, actual written bytes, or return values. If the interface definition of work differs, the metric semantics should be modified.

nsecs(monotonic) explicitly uses a monotonic clock that excludes system suspend time; the difference divided by 1000 is in microseconds. Therefore, lat_us > 10000 indicates more than 10 milliseconds, not 10 microseconds. hist aggregates on the kernel side to avoid outputting text for every call; map deletion syntax follows the 0.24 standard library. bpftrace standard library

The time from function entry to return includes CPU execution, preemption, blocking, and probe overhead. A very long call duration does not independently prove a futex wait occurred; even if futex system calls are seen during that period, you must check the operation type, return value, and time interval to determine the actual wait.

How to Correlate Recursion, Thread Exit, and Asynchronous Requests

Using only @start[tid] to save a timestamp means inner calls will overwrite outer ones. In recursive scenarios, you can maintain depth per TID and use (tid, depth) as the key for start time and parameters; upon return, take the current layer and decrement. You need to consider calls already in progress at attachment, missed returns, longjmp, exception unwinding, thread exit, and map capacity; otherwise, depth may still mismatch.

Coroutines or asynchronous requests may span threads and multiple function calls. In this case, TID is suitable for representing the executing thread but cannot serve as a request ID. It is best to record request_id via USDT or an application's existing correlation identifier, linking start, suspend, resume, and completion events.

Return probes are also not transparent to all language runtimes: custom stacks, special return paths, etc., require checking support. For complex runtimes, semantically explicit USDT is often more stable than relying on the machine ABI of a specific internal function.

Use Event Sequences to See Which Timestamp is Overwritten by Recursion

Assume an outer work on the same thread enters at 100 μs, a recursive inner work enters at 130 μs, the inner one returns at 170 μs, and the outer one returns at 200 μs. When only one @start[tid] is saved, 130 overwrites 100; the first return yields 40 μs and deletes the entry, causing the outer 100 μs duration to be lost.

The offline model below uses a per-thread stack, used only to verify pairing logic, and does not load BPF or attach probes. It additionally records "returns without entry" and calls that were incomplete at the end of observation.

from collections import defaultdict
stacks = defaultdict(list)
durations = []
orphan_returns = 0
events = [
    (1, "return", 90),
    (1, "enter", 100), (1, "enter", 130),
    (1, "return", 170), (1, "return", 200),
    (2, "enter", 210),
]
for tid, kind, timestamp in events:
    if kind == "enter":
        stacks[tid].append(timestamp)
    elif stacks[tid]:
        start = stacks[tid].pop()
        assert timestamp >= start
        durations.append((tid, timestamp - start))
    else:
        orphan_returns += 1
assert durations == [(1, 40), (1, 100)]
assert orphan_returns == 1
assert sum(map(len, stacks.values())) == 1

This model assumes complete event ordering and normal nesting for the same thread. In practice, missing intermediate returns, longjmp, or exception paths may permanently misalign stack depth; therefore, adding depth does not completely solve the correlation issue. You should record mismatch counts, limit per-thread depth and total key count, and clean up at confirmed thread exits or session boundaries.

In particular, slow calls still executing at the end of observation will not enter the completion latency histogram if they do not return. If you clear them directly without counting, the report may be biased towards faster, completed calls. You can separately report the number of incomplete calls and the lower bound of wait time up to the stop point; do not treat them as having zero latency.

Whose Start Time is Overwritten by the Inner Call?

The timeline visualizes the containment relationship: the outer 100 μs already contains the inner time. If the entry writes to the same start[TID], the inner call overwrites 100; after the inner call returns and the entry is deleted, the outer call loses its pairing basis. A stack can preserve the start point of each layer, but it cannot recover missing events out of thin air; incomplete and mismatch counts should still be reported with the results.

USDT: Pre-agreed Observable Business Events

Applications can define request start points using SDT macros, for example, where request_id and size are provided by business code in the following snippet:

#include <sys/sdt.h>

DTRACE_PROBE2(myapp, request_start, request_id, size);

This code placed in the function body requires installing the corresponding headers and completing the build. After listing the probes actually carried by the target, consume them according to their parameter contracts:

readelf -n /absolute/path/prog
bpftrace -l 'usdt:/absolute/path/prog:*'
bpftrace -p 12345 -e 'usdt:/absolute/path/prog:myapp:request_start {
    @requests = count();
}'

USDT describes positions and parameters via probe metadata in the build artifacts; some implementations also use semaphores to coordinate activation. When inactive, the cost is usually low, but not absolutely zero: code layout, parameter calculation, and build methods may still incur costs. You cannot uniformly write that all architectures replace a certain segment of NOPs with x86 INT3.

Business Probes Need to be Versioned Along with Field Semantics

Events usually require start/finish pairs, and may also include suspend/resume or explicit cancel. If a request spans machines, you cannot directly subtract their respective monotonic values; single-machine latency and clocks/causality in distributed tracing should be handled separately.

Metric aggregation also requires dimension control. Keeping every request_id as a histogram key long-term causes high-cardinality maps; usually, use IDs for short-term correlation, delete after completion, and then aggregate by limited dimensions such as operation name and result type. A small number of anomalous samples can retain details, but should not turn all normal requests into permanent keys.

Extending from User Functions to System Behavior

bpftrace -p 12345 -e 'tracepoint:syscalls:sys_enter_openat {
    @open_calls = count();
}'

This count describes the number of openat entry hits, not that the open was successful; success, failure, and latency need exit pairing. The filename also cannot fully express the final resolved file identity; directory fds, mount namespaces, symbolic links, and path modifications may all be involved.

Existing BCC tools are suitable for verifying the direction first. For example, execsnoop observes exec calls and their arguments/results, not a complete "who forked whom" trace; process creation also requires fork, clone, or scheduling events. Tools may compile BPF at runtime and are not all pre-compiled kernel programs just because they are command-line tools. BCC execsnoop source code

Judging Whether Results Are Trustworthy

Clearly define the target PID, build identity, probe location, parameter types, start/end times, and count denominators. If there are no events, first confirm that the actual path was indeed executed, then check symbol resolution, permissions, and support capabilities; do not immediately assert that the business did not occur.

High-frequency probes change the program under test. Prioritize aggregation at the probe end, limit the number of dimensions and observation time, and check for feedback such as dropped events, full maps, and read failures. Stopping the tool usually releases the attachments it manages; manually created tracefs events should be cleaned up by this session's name, not by clearing all uprobe configurations on the machine.

Sampling is suitable for finding hotspots, while event tracing is suitable for verifying specific paths and time relationships. Use them in combination, see Deep Dive into Perf.

Keywords: ftrace, tracefs, uprobe, uretprobe, USDT, bpftrace, BCC, ABI, file offset, latency, correlation

Attach Denominators and Gaps to Observation Results

Map aggregation completed in probes and user-space per-event output have different data paths; seeing output loss does not justify indiscriminately modifying all counts, nor does it justify assuming the entire observation has no gaps. Describing collection coverage, pairing coverage, and output coverage separately allows you to know exactly which calls a latency distribution represents.