Tracing and Debugging

A request may be slow due to CPU, run queue, locks, or devices. Tracing should first determine the measurement object and start/end boundaries, then collect sufficient events to validate hypotheses.

1. Define the Problem and Measurement Object First

The same "request duration" may include application queuing, system calls, block layer queuing, and device processing. Latencies at different layers cannot be directly added unless the nesting and parallelism of events are explicitly defined.

2. ftrace and tracefs

Modern tracefs is often mounted at /sys/kernel/tracing, while the legacy path /sys/kernel/debug/tracing may still exist. available_tracers lists currently available tracers, and available_filter_functions lists traceable functions; configurations differ and affect visibility.

cat /sys/kernel/tracing/available_tracers
cat /sys/kernel/tracing/events/sched/sched_switch/format

These read-only commands confirm capabilities and fields; a read failure should not immediately lead to the conclusion that a function does not exist. Enabling function/function_graph changes the tracing state; actual collection should use an independent trace instance: set the filter scope and buffer first, then start collection, and finally disable and clean up after completion.

• function records the entry of selected functions; enabling it globally without filtering may generate a large volume of events.
• function_graph correlates function entry and return, displaying call hierarchy and duration. Whether time spent being scheduled out is included depends on tracer options.
• trace provides a formatted buffer view; trace_pipe is a consumptive read. Multiple readers will compete for events and cannot be treated as independent broadcast logs.

CPU buffers may overwrite or lose records; cross-CPU comparison also requires understanding trace_clock. Trace instances can isolate various collection configurations, but shared resources like dynamic probe definitions may still interfere with each other. See the ftrace documentation for interfaces and options.

Dynamic ftrace is Not kprobe Events

Dynamic ftrace enables/disables function tracing via instrumentation points in traceable functions; registering with kprobe_events or dynamic_events creates dynamic probe events, which belong to a different mechanism. Reading fixed-offset expressions like state+0x12(%di) requires matching the architecture, function signature, and structure layout simultaneously, and cannot be used as a generic example for reading TCP states.

Prioritize checking for suitable tracepoints; if dynamic function probing is truly necessary, combine target symbols, BTF/DWARF, and actual source code to interpret arguments. See kprobe events.

3. perf: Counters and Sampling Answer Different Questions

perf stat summarizes counters; perf record generates samples based on events; perf report aggregates samples. Recording cycles for a sleeping process does not represent the CPU hotspots of the entire machine for ten seconds.

# Measure this command and its inherited scope, not the whole machine.
perf stat -e cycles,instructions,cache-misses -- ./workload

# Record the call stack of the actual workload; DWARF unwinding has additional overhead.
perf record -e cycles -g --call-graph dwarf -- ./workload
perf report

# If the issue is indeed a whole-machine hotspot, explicitly use system-wide sampling.
perf record -a -e cycles -g -- sleep 10

./workload represents the program to be tested and should be replaced with the actual command. Permissions, PMU, virtualization, and platform capabilities determine event availability; generic names like cache-misses may not correspond to identical hardware meanings across different CPUs.

When too many events cause multiplexing, check the execution time ratio and scaling results. Call stack quality also depends on frame pointers, DWARF, symbols, and unwinding methods; missing symbols, lost samples, and incorrect unwinding can all alter hotspot maps. Sample percentages represent the proportion relative to the current event and recording scope, not the precise wall-clock time of any arbitrary function. See perf stat and perf record for tool semantics.

4. Correctly Constructing Latency Histograms

hist(nsecs) displays timestamp distribution, not operation latency. Below is an example using bpftrace 0.24 to record complete write system calls for a specified process during the collection period, using TID to correlate entry and exit.

First, check that the target tracepoints and fields exist:

bpftrace -lv 'tracepoint:syscalls:sys_enter_write'
bpftrace -lv 'tracepoint:syscalls:sys_exit_write'

Save as write-latency.bt:

tracepoint:syscalls:sys_enter_write
/pid == $1/
{
    @start[tid] = nsecs(monotonic);
}

tracepoint:syscalls:sys_exit_write
/pid == $1 && @start[tid]/
{
    @lat_us = hist((nsecs(monotonic) - @start[tid]) / 1000);
    @returns[args->ret < 0] = count();
    delete(@start, tid);
}

interval:s:10
{
    exit();
}

END
{
    clear(@start);
}

bpftrace write-latency.bt 12345

Replace 12345 with the PID of the process to be tested. @returns[0] indicates non-negative returns, @returns[1] indicates negative returns; positive values may also indicate short writes and cannot be directly called "complete business success." The time unit is microseconds; 10,000 microseconds is 10 milliseconds.

This measurement includes blocking and scheduling waits during the syscall, which is not equivalent to device completion latency; for example, after a file write returns, data may still be in the page cache. It also does not cover other write paths like writev or io_uring. Calls that entered before collection started or have not returned by the end will not be included in complete samples; tail analysis should consider this truncation.

Correlate Identity: Design Synchronous Syscalls and Asynchronous Requests Separately

TID is sufficient to correlate the entry and exit of ordinary synchronous syscalls, but asynchronous I/O requests complete across threads/interrupts. Use a true request identity instead, and handle reuse, merging, retries, and cleanup. When tracing generic recursive functions, you must also distinguish nesting depth; do not simply copy a single start[tid]. Refer to the bpftrace 0.24 standard library for language and time interfaces.

Start overlapping requests from one thread and choose their completion threads. Both correlation methods process the same events, exposing errors even when a computed duration looks plausible.

5. Aggregation, Loss, and Overhead

Per-event printf may make user-space output a bottleneck. When only distribution is needed, prioritize aggregating count/hist/sum on the kernel side; when details are truly needed, explicitly define sampling, filtering, buffer capacity, and loss counting.

Losses must be recorded and residual entries cleaned up; do not allow the next request to inherit old timestamps.

BCC provides many ready-made tools, but the traditional BCC workflow typically compiles BPF at runtime and is not a complete set of fixed pre-compiled CO-RE binaries. Names like biolatency, runqlat, and tcpretrans indicate general purposes, but accurate measurement of start/end points and filter conditions still depends on the installed version. See the BCC project.

6. Logs, Dynamic Debugging, and Fault Dumps

printk log levels affect the severity classification of records; the console threshold determines which records are printed to the console, which is not equivalent to other levels disappearing from the log ring. Actual KERN_* macro encodings should use kernel headers; do not pseudocode readable <0> display forms as current macro definitions.

Dynamic debug only controls call sites like pr_debug() / dev_dbg() that are compiled into the corresponding mechanism. Querying by function name and finding no entries does not mean the function was not executed; the function may simply lack corresponding debug call sites. The interface may be located at /proc/dynamic_debug/control or debugfs, depending on configuration.

kdump requires reserving crashkernel memory and preparing the capture kernel, initramfs, and save path. After a crash, it switches to the capture kernel, and the original memory is exported via interfaces like /proc/vmcore, then saved or filtered by user-space tools. Do not assume you will definitely get a complete, readable dump next time just by executing kexec -p; device state and capture environment must also be supported.

Dump Analysis: Symbols Must Match the Kernel at Crash Time

When analyzing, use vmlinux, debug symbols, and necessary modules that match the crash kernel, rather than mechanically applying the current uname -r: the machine may have already rebooted to another version. In crash, bt usually views the backtrace of the current/specified task, while foreach bt is the per-task backtrace. See kdump and crash help.

KGDB allows setting breakpoints, reading registers, and single-stepping; pausing execution changes timing behavior, so it is not suitable for directly inferring real latency from breakpoint results; connection transmission, kernel configuration, and symbols must also match. For configuration and examples, see Build and Development Directory.

7. An Interpretable Diagnostic Workflow

1. Fix the scenario. Record requests, time windows, load, and latency boundaries.
2. Narrow the direction. Use counters or sampling to distinguish on-CPU from waiting.
3. Validate hypotheses. Select a few events, diving into relevant function paths if necessary.
4. Check observation impact. Compare throughput, latency, and loss before and after enabling.
5. Preserve interpretation conditions. Record tool versions, configurations, filters, and measurement limitations.

Each step should reduce uncertainty, rather than simply expanding log volume.

Related reading: eBPF Basics, Program Types, User-space ftrace and bpftrace Practices.