Trace-cmd: Intercepting Kernel Function Graphs, Profiling Scheduler Latency, and Diagnosing System Bottlenecks in Production

Reaching for traditional troubleshooting utilities only compounds the confusion. Standard tools like top and vmstat sample system activity over broad intervals of one or two seconds, averaging out the microsecond-level stalls that ruin real-time performance. Meanwhile, running strace on a live production daemon is akin to hitting the emergency brake on a motorway; by attaching heavy system call monitors, it introduces crippling execution overhead that can drag an already struggling service into a complete outage. You need a way to watch the Linux kernel's internal machinery in real time, with microsecond precision, without slowing down the very workloads you are trying to rescue.

This is where trace-cmd comes in. It serves as the dedicated command-line orchestrator for Ftrace, the Linux kernel's built-in event tracing subsystem. Acting like a high-speed flight data recorder, trace-cmd hooks directly into the operating system's internal functions, schedulers, and network pathways to capture exactly what the kernel is doing behind the scenes with virtually zero overhead.

If you need an immediate pulse on what your CPU cores and scheduler are doing right now, the single most valuable command to run is a one-second scheduler snapshot:

sudo trace-cmd record -e sched:sched_switch sleep 1

With that single line, trace-cmd arms the kernel's scheduler tracepoints, streams event data directly into lockless per-CPU memory buffers, and writes a compact binary capture file (trace.dat) to disk. You can inspect the health and volume of that recording immediately:

trace-cmd report --stat

trace-cmd version 3.1.2
CPU 0: 421 events, 0 dropped
CPU 1: 512 events, 0 dropped
CPU 2: 389 events, 0 dropped
CPU 3: 467 events, 0 dropped
Buffer sizes: 1408 KB per CPU

In less than two seconds, you have collected hundreds of precise scheduling transitions across every CPU core without losing a single event. To understand why this approach is safe enough to run against high-throughput production clusters, we need to look at the engine humming underneath.

Architectural Breakdown: The Engine Under the Hood

Historically, interacting with Ftrace required manual manipulation of pseudo-files exposed through debugfs or tracefs (typically mounted at /sys/kernel/tracing). Manually orchestrating traces via shell commands (echo function > current_tracer) introduces severe limitations: reading from human-readable ASCII pipes incurs continuous context-switching, text formatting, and buffer-copying overhead inside the kernel, distorting the very timing properties under investigation.

trace-cmd resolves this friction by operating as a native binary pipeline interacting with four core architectural components:

1. Dynamic Code Patching (-pg / -mfentry)

When the Linux kernel is compiled with CONFIG_FUNCTION_TRACER, the compiler inserts a five-byte call instruction (traditionally referencing mcount(), or __fentry__() on modern x86_64 architectures) at the prologue of every kernel function. During early kernel boot, the kernel replaces these dynamic call sites with single-cycle NOP (no-operation) instructions via the Dynamic Ftrace mechanism.

When trace-cmd activates a function tracer, the kernel selectively rewrites these specific NOP locations with jumps to tracing trampolines using atomic text-patching operations (text_poke_bp()). As a result, non-traced functions execute at native hardware speed with zero runtime branch overhead, while traced functions route register states into the tracing pipeline.

2. Per-CPU Lockless Ring Buffers

The kernel allocates high-throughput, per-CPU memory buffers using circular double-linked page structures. Tracing callbacks write timestamped binary event records without acquiring global spinlocks, eliminating cross-core cache invalidation and bus contention. When running trace-cmd record, the user-space process establishes a dedicated recorder thread per logical processor, leveraging the splice() system call to move pages directly from kernel ring buffer pages to the storage medium (trace.dat) without intermediate copies to user memory space.

3. Static Event Tracepoints (TRACE_EVENT)

Static tracepoints are compile-time hooks placed at strategic locations within kernel subsystems (e.g., scheduler state machines, memory allocators, virtual file systems, network drivers). Defined by the TRACE_EVENT() macro system, an inactive tracepoint consists of an unconditional jump over an out-of-line tracing stub, managed via compiler jump labels (static_key). When enabled by trace-cmd, the jump instruction is dynamically modified to execute the tracepoint callback, copying contextual parameters (such as PID, comm, execution priority, or sk_buff pointers) into the per-CPU ring buffer.

4. Function Graph Shadow Stacks

The function_graph tracer instruments both the entry and the exit of kernel functions. By intercepting the function prologue and rewriting the return address on the thread's stack to point to return_to_handler, Ftrace maintains a per-thread shadow call stack. When the function returns, the tracing harness measures the exact temporal differential between entry and return, giving trace-cmd the data required to construct hierarchical call trees annotated with microsecond execution durations.

Core Flags and Quick Start

The trace-cmd command suite provides subcommands analogous to modern developer tooling suites (record, report, listen, split, hist, and reset).

The Beginner Baseline: One-Second Scheduler Snapshot

To capture immediate system state and verify binary extraction, execute a one-second scheduler trace:

sudo trace-cmd record -e sched:sched_switch sleep 1

  plugin 'sched:sched_switch'
Hit Ctrl^C to stop recording
CPU0 data recorded: 40960 bytes
CPU1 data recorded: 49152 bytes
CPU2 data recorded: 36864 bytes
CPU3 data recorded: 45056 bytes

Inspect the resulting trace.dat file:

trace-cmd report --stat

trace-cmd version 3.1.2
CPU 0: 421 events, 0 dropped
CPU 1: 512 events, 0 dropped
CPU 2: 389 events, 0 dropped
CPU 3: 467 events, 0 dropped
Buffer sizes: 1408 KB per CPU

5 Real-World Production Use Cases

1. Tracing Kernel Function Execution Graphs to Isolate Storage Stalls

Scenario

A PostgreSQL database node experiences unexplained I/O write spikes. Average IOPS remain within disk SLA, but write system calls occasionally block for upwards of 40 milliseconds, causing query worker starvation. The engineer must inspect the Virtual Filesystem (VFS) and block storage drivers to determine whether the delay stems from page dirtying locks, journal commits, or physical block writes.

Command

sudo trace-cmd record -p function_graph \
  -g vfs_write \
  --max-graph-depth 4 \
  -b 8192 \
  -F /usr/lib/postgresql/15/bin/postgres -- -D /var/lib/postgresql/15/main

Realistic Terminal Output

Run trace-cmd report to view the hierarchical execution tree:

           postgres-48219 [002] 184920.104231: funcgraph_entry:                   |  vfs_write() {
           postgres-48219 [002] 184920.104232: funcgraph_entry:                   |    __vfs_write() {
           postgres-48219 [002] 184920.104233: funcgraph_entry:                   |      new_sync_write() {
           postgres-48219 [002] 184920.104234: funcgraph_entry:                   |        ext4_file_write_iter() {
           postgres-48219 [002] 184920.104236: funcgraph_entry:      ! 38412 us   |          ext4_buffered_write_iter();
           postgres-48219 [002] 184920.142650: funcgraph_exit:       ! 38418 us   |        }
           postgres-48219 [002] 184920.142651: funcgraph_exit:       ! 38420 us   |      }
           postgres-48219 [002] 184920.142652: funcgraph_exit:       ! 38422 us   |    }
           postgres-48219 [002] 184920.142653: funcgraph_exit:       ! 38424 us   |  }

Line-by-Line Technical Analysis

• postgres-48219 [002] 184920.104231: The process postgres (PID 48219) running on CPU core 2 invokes vfs_write() at monotonic timestamp 184920.104231.
• funcgraph_entry: | vfs_write() {: The function graph tracer captures the descent down the virtual filesystem call chain through __vfs_write() and new_sync_write().
• ext4_buffered_write_iter();: Execution branches into the Ext4 filesystem implementation.
• ! 38412 us: The exclamation mark (!) is an automatic Ftrace threshold indicator signaling an execution duration exceeding 10,000 microseconds (10 milliseconds). The function required 38.412ms to complete.
• The delay happens entirely inside ext4_buffered_write_iter(), pointing to write-stall behavior during page cache allocation or page dirty throttling rather than lower-level SCSI/NVMe transport layer blocking.

Explicit Next Action

The engineer inspects dirty memory kernel tuning parameters. The findings indicate that the kernel dirty background limits were set too high, triggering synchronous memory-write stalls under bursty write traffic:

sudo sysctl -w vm.dirty_background_ratio=5
sudo sysctl -w vm.dirty_ratio=10

2. Profiling Thread Wakeup and Scheduler Latency

Scenario

A high-frequency trading application or distributed key-value store reports high 99th-percentile tail latency. While thread compute times are nominal (under 50 microseconds), the end-to-end processing time exceeds 5 milliseconds. The team suspects thread run-queue starvation and CPU context-switching delay caused by noisy neighbor processes.

Command

sudo trace-cmd record \
  -e sched:sched_wakeup \
  -e sched:sched_switch \
  -e sched:sched_migrate_task \
  -b 16384 \
  -- sleep 5

Realistic Terminal Output

Run trace-cmd report to measure scheduler delay:

       worker-pool-1029 [001] 291044.200100: sched_wakeup:        comm=worker-task pid=1034 prio=120 target_cpu=001
       worker-pool-1029 [001] 291044.200105: sched_migrate_task: pid=1034 prio=120 orig_cpu=1 dest_cpu=3
         batch_job-8401 [003] 291044.204510: sched_switch:        batch_job:8401 [120] R ==> worker-task:1034 [120]

Line-by-Line Technical Analysis

• worker-pool-1029 [001] 291044.200100: sched_wakeup: Process 1029 transitions thread worker-task (PID 1034) to a runnable state at timestamp 291044.200100, targeting CPU 1 with static priority 120 (standard SCHED_OTHER nice level 0).
• sched_migrate_task: pid=1034 ... dest_cpu=3: The kernel scheduler identifies core contention on CPU 1 and migrates PID 1034 to CPU 3 at 291044.200105.
• sched_switch: batch_job:8401 [120] R ==> worker-task:1034: CPU 3 finally performs a context switch away from a CPU-bound process (batch_job) to run worker-task at timestamp 291044.204510.
• Latency Calculation: 291044.204510 - 291044.200100 = 0.004410 seconds (4,410 microseconds). The thread sat runnable on the run-queue for 4.41ms waiting for an available CPU core.

Explicit Next Action

The engineer shields the latency-sensitive worker threads by moving them to dedicated CPU cores via CPU sets, raising their scheduling policy to SCHED_FIFO, or pinning the process:

sudo chrt -f -p 99 1034
sudo taskset -cp 2,3 1034

3. Isolating Kernel Network Stack Bottlenecks

Scenario

An ingress load balancer experiences dropped UDP packets and TCP retransmissions during traffic bursts exceeding 800,000 packets per second. Metrics show soft interrupt processing (ksoftirqd) consuming 100% of CPU 0, while all other cores remain underutilized, indicating single-queue Interrupt Request (IRQ) affinity bottlenecks and NAPI poll budget exhaustion.

Command

sudo trace-cmd record \
  -e net:netif_receive_skb \
  -e net:net_dev_xmit \
  -e napi:napi_poll \
  -e irq:softirq_entry \
  -e irq:softirq_exit \
  -b 8192 \
  -- sleep 2

Realistic Terminal Output

Run trace-cmd report to trace packet flow through the softirq layer:

          <idle>-0     [000] 410293.501200: softirq_entry:       vec=3 [NET_RX]
          <idle>-0     [000] 410293.501205: napi_poll:           napi poll on dev eth0 queue 0 work 64 budget 64
          <idle>-0     [000] 410293.501210: netif_receive_skb:   dev=eth0 skbaddr=0xffff888123ab4000 len=1420
          <idle>-0     [000] 410293.501215: netif_receive_skb:   dev=eth0 skbaddr=0xffff888123ab4800 len=1420
          <idle>-0     [000] 410293.501280: napi_poll:           napi poll on dev eth0 queue 0 work 64 budget 64
          <idle>-0     [000] 410293.503400: softirq_exit:        vec=3 [NET_RX]

Line-by-Line Technical Analysis

• softirq_entry: vec=3 [NET_RX]: Core 0 enters network receive softirq processing (NET_RX) from an idle state.
• napi_poll: ... work 64 budget 64: The network driver's NAPI poll routine processes 64 packets—exhausting its entire allocated budget (work == budget). This forces the kernel to yield and reschedule NAPI rather than processing the remaining hardware descriptor ring in one pass.
• netif_receive_skb: ... len=1420: Socket buffers (sk_buff) are parsed serially on CPU 0.
• softirq_exit: vec=3 [NET_RX]: The NET_RX softirq takes 2.2ms (410293.503400 - 410293.501200), monopolizing the core and inducing ring-buffer drops at the Network Interface Card (NIC) level.

Explicit Next Action

The engineer enables Receive Side Scaling (RSS) and Receive Packet Steering (RPS) to distribute network interrupt hashing across all available logical CPU cores:

# Distribute RPS across CPUs 0-7 for eth0 rx queue 0
echo "ff" | sudo tee /sys/class/net/eth0/queues/rx-0/rps_cpus
# Increase the system-wide netdev budget
sudo sysctl -w net.core.netdev_budget=600

4. Targeted PID Filtering with Dynamic Function Probes

Scenario

A microservice running inside a production container (PID 4120) fails intermittently when opening configuration files and dynamic assets under peak load. System administrators need to isolate file path resolution latencies for this single process without tracing system-wide file opens, which would overwhelm the trace buffer and degrade host performance.

Command

sudo trace-cmd record -p function \
  -l 'do_sys_openat2' \
  --filter 'common_pid == 4120' \
  -b 4096 \
  -- sleep 10

Realistic Terminal Output

Extract the filtered trace using trace-cmd report:

   java-service-4120  [004] 512089.102340: function:       do_sys_openat2 <-- __x64_sys_openat
   java-service-4120  [004] 512089.102345: function:       do_sys_openat2 <-- __x64_sys_openat
   java-service-4120  [004] 512089.108910: function:       do_sys_openat2 <-- __x64_sys_openat

To see both the entry point and the full stack backtrace for these invocations:

sudo trace-cmd record -p function \
  -l 'do_sys_openat2:traceoff' \
  --filter 'common_pid == 4120' \
  -b 4096 \
  -- sleep 5

   java-service-4120  [004] 512089.102340: function:       do_sys_openat2
   java-service-4120  [004] 512089.102342: kernel_stack:   <stack trace>
 => do_sys_openat2 (0xffffffff81345a20)
 => __x64_sys_openat (0xffffffff81345c80)
 => do_syscall_64 (0xffffffff81c00210)
 => entry_SYSCALL_64_after_hwframe (0xffffffff81e00090)

Line-by-Line Technical Analysis

• java-service-4120 [004] 512089.102340: function: do_sys_openat2: Demonstrates that kernel dynamically patched only the do_sys_openat2 symbol.
• --filter 'common_pid == 4120': The kernel's internal event filtering engine discards all calls from other system processes directly inside the kernel ring buffer, preserving buffer space.
• <stack trace>: Unwinds the kernel call frame, showing the exact user-to-kernel transition from entry_SYSCALL_64_after_hwframe down through the standard 64-bit system call multiplexer (do_syscall_64).

Explicit Next Action

The engineer inspects the time delta between subsequent file descriptor allocations to confirm whether file descriptor leaks or directory lock contention on local mounts are causing the delays:

# Correlate with system-wide file descriptor allocation limits
cat /proc/sys/fs/file-nr

5. Remote Live Network Tracing and Post-Mortem Report Analysis

Scenario

An embedded server node or stateless Kubernetes worker lacks local disk space to write multi-gigabyte trace files during an intermittent cluster degradation. The engineer must stream trace data over the network in real time to a centralized analysis workstation, capturing scheduler and interrupt events without contaminating the target node's local storage pipeline.

Commands

On the Central Analyzer Host (192.168.1.50):

trace-cmd listen -p 8083 -D

On the Target Node (192.168.1.105):

sudo trace-cmd record \
  -N 192.168.1.50:8083 \
  -e sched:sched_switch \
  -e irq:irq_handler_entry \
  -b 4096 \
  -- sleep 10

On the Central Analyzer Host (After Collection):

trace-cmd report -i trace.192.168.1.105:8083.dat --stat
trace-cmd report -i trace.192.168.1.105:8083.dat --delta

Realistic Terminal Output

Receiver output on Analyzer:
Connected to 192.168.1.105:42190
Recording trace data from client...
Client finished sending. Saved to 'trace.192.168.1.105:8083.dat'.

Analysis Report via `trace-cmd report --delta`:
           <idle>-0     [000] 601204.100100: irq_handler_entry: irq=27 name=nvme0q1
           <idle>-0     [000] 601204.100115: (+0.000015s) irq_handler_exit:  irq=27 ret=handled
           <idle>-0     [000] 601204.100120: (+0.000005s) sched_switch:      swapper/0:0 [120] R ==> app-worker:9021 [120]
       app-worker-9021  [000] 601204.100850: (+0.000730s) sched_switch:      app-worker:9021 [120] S ==> swapper/0:0 [120]

Line-by-Line Technical Analysis

• trace-cmd listen -p 8083 -D: Spawns a background listener daemon on port 8083, ready to accept binary network trace streams.
• -N 192.168.1.50:8083: Instructs the target node's trace-cmd engine to bypass local file I/O and stream raw per-CPU memory pages directly over a TCP socket.
• (+0.000015s): The --delta flag prints relative timestamps between consecutive events on each core. NVMe interrupt processing completed in 15 microseconds.
• (+0.000730s): The app-worker thread ran for 730 microseconds before voluntarily relinquishing the CPU (S for TASK_INTERRUPTIBLE), demonstrating healthy local compute phases.

Explicit Next Action

The post-mortem trace file can now be opened directly in KernelShark for graphical timeline inspection or parsed with custom automated analysis scripts using the libtracecmd C/Python APIs.

What Can Go Wrong: Operational Hazards and Remediation

While trace-cmd is designed for production use, misconfigurations can degrade system performance or corrupt tracing data.

1. Unbounded Ring Buffer Memory Allocations

The Danger: Setting an excessively large buffer size via -b on systems with high core counts can consume substantial non-swappable kernel memory. Specifying -b 65536 (64MB) on a 128-core server allocates 64MB * 128 = 8.192 GB of locked kernel RAM. If the system is already under memory pressure, this can trigger immediate Out-Of-Memory (OOM) killer terminations of critical production workloads.

Mitigation & Recovery: Calculate the total memory footprint before allocating (Buffer Size * Logical Cores). In production, use standard buffer sizes between 2MB and 8MB per CPU (-b 2048 to -b 8192):

# Safe default inspection: Check available free memory first
free -m
# Allocate a conservative 4MB per core
sudo trace-cmd record -b 4096 -e sched:sched_switch -- sleep 2

2. Tracing High-Frequency Functions Without Filters

The Danger: Running the function or function_graph tracer globally without restricting symbols via -l or -g causes Ftrace to intercept tens of millions of function calls per second across every kernel subsystem (e.g., spinlocks, memory allocators, timer ticks). This can induce a 20% to 50% CPU throughput penalty and rapidly overflow the ring buffers, dropping events (events lost errors).

Mitigation & Recovery: Never execute trace-cmd record -p function without targeting specific functions. Use wildcard filters to match specific functional domains:

# Verify how many functions match your filter before starting
trace-cmd list -f 'ext4_*' | wc -l

# Trace only targeted subsystem functions
sudo trace-cmd record -p function -l 'ext4_*' -- sleep 2

3. Orphaned Tracers and Dangling Trace Instances

The Danger: If a trace-cmd process is terminated unexpectedly via SIGKILL (kill -9), the kernel may leave dynamic tracepoints active and per-CPU ring buffers allocated. This causes ongoing trace collection in the background, consuming CPU cycles and filling memory buffers.

Mitigation & Recovery: The ArchWiki Ftrace Guide and upstream manuals recommend running trace-cmd reset to return the kernel to its default state:

# Reset all tracer engines, clear all filters, and free allocated buffers
sudo trace-cmd reset

# Verify the tracer is completely disabled (should return 'nop')
cat /sys/kernel/tracing/current_tracer

Technical Summary of Core Commands

Today's Takeaway

To start using trace-cmd on your machine right now in five minutes, open a terminal and run trace-cmd list -e to explore the thousands of static kernel tracepoints already available on your running operating system. Next, take an instantaneous five-second snapshot of active CPU thread scheduling by executing sudo trace-cmd record -e sched:sched_switch -- sleep 5 && trace-cmd report --stat. This safe, non-intrusive command confirms that your per-CPU ring buffers are functioning properly and shows the exact distribution of thread switches across your processor cores—giving you immediate, zero-overhead visibility into the Linux kernel without putting production workloads at risk.

Authoritative Technical References

• Official Linux Kernel Ftrace Documentation — The authoritative upstream guide to kernel tracing infrastructure.
• trace-cmd(1) Linux Manual Page — Complete command-line interface specification and flag reference.
• LWN.net: Secrets of the Ftrace function tracer — Deep-dive architectural breakdown of dynamic code patching and trampolines by Steven Rostedt.
• KernelShark Official Portal — Graphical user interface for deep post-mortem analysis of trace-cmd binary datasets.
• Brendan Gregg's Ftrace Performance Analysis Guide — Real-world systems performance benchmarking and tracing methodology.