Tracing and Debugging

Coverage: ftrace (function/function_graph) → tracepoints → kprobes → perf events → eBPF tracing (bpftrace/bcc) → kdump/crash → KGDB → printk and dynamic debugging Kernel versions: 2.6 ~ 6.x

ftrace: Built-in Kernel Tracer

Function Tracer

# List available tracers
cat /sys/kernel/debug/tracing/available_tracers

# function: trace all function calls (very high overhead, for debugging only)
echo function > /sys/kernel/debug/tracing/current_tracer
echo "tcp_v4_rcv" > /sys/kernel/debug/tracing/set_ftrace_filter
echo 1 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace_pipe

Function Graph: With Timing

echo function_graph > /sys/kernel/debug/tracing/current_tracer
# Output:
# 0)               |  tcp_v4_rcv() {
# 0)   0.234 us    |    tcp_checksum_complete();
# 0)   0.567 us    |    tcp_v4_do_rcv() {
# 0)   1.234 us    |      tcp_rcv_established();
# 0)   2.345 us    |    }
# 0)   3.456 us    |  }

Dynamic ftrace: Enable/Disable at Runtime

# Dynamic function probes (via debugfs):
echo 'p:tcp_probe tcp_rcv_established state+0x12(%di):u8' \
     > /sys/kernel/debug/tracing/kprobe_events
echo 1 > /sys/kernel/debug/tracing/events/kprobes/tcp_probe/enable
cat /sys/kernel/debug/tracing/trace_pipe

Tracepoints: Stable Probe Points

# All available tracepoints
ls /sys/kernel/debug/tracing/events/
# sched/  syscalls/  net/  block/  irq/  timer/  ...

# Trace all exec calls:
echo 1 > /sys/kernel/debug/tracing/events/syscalls/sys_enter_execve/enable
cat trace_pipe

# Trace scheduler:
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable

# Trace block IO:
echo 1 > /sys/kernel/debug/tracing/events/block/block_rq_issue/enable
echo 1 > /sys/kernel/debug/tracing/events/block/block_rq_complete/enable

Perf Events: Hardware Performance Counters

# perf stat: Count hardware events during program execution
perf stat -e cycles,instructions,cache-misses,branch-misses -- ls /

# perf record: Sampling (basis for flame graphs)
perf record -e cycles -g -- sleep 10
perf report

# perf top: Real-time hotspots
perf top -e cycles

# Hardware events:
#   cycles, instructions, cache-references, cache-misses,
#   branch-instructions, branch-misses, bus-cycles,
#   stalled-cycles-frontend, stalled-cycles-backend

eBPF Tracing: bpftrace

# bpftrace: High-level tracing language in DTrace style
# One-line tracing:
bpftrace -e 'kprobe:vfs_read { @[comm] = count(); }'
bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args->filename)); }'

# Histograms:
bpftrace -e 'kprobe:vfs_read { @usecs[comm] = hist(nsecs / 1000); }'
bpftrace -e 'kprobe:submit_bio { @latency = hist(nsecs); @count = count(); }'

# Aggregation:
bpftrace -e 'kretprobe:vfs_read /retval > 0/ { @bytes[comm] = sum(retval); }'

bcc Toolset

# bcc: Pre-compiled toolset using Python + BPF (/usr/share/bcc/tools/)
execsnoop        # Trace all exec() calls
opensnoop        # Trace all open() calls
biolatency       # Block IO latency histogram (by device/process)
tcptop           # Real-time top for TCP traffic
tcpretrans       # TCP retransmission statistics
cachestat        # Page cache hit rate
runqlat          # Scheduler latency (time waiting for CPU)

printk and Dynamic Debugging

printk Log Levels

// include/linux/kern_levels.h
#define KERN_EMERG   "<0>"  // System is unusable
#define KERN_ALERT   "<1>"  // Action must be taken immediately
#define KERN_CRIT    "<2>"  // Critical conditions
#define KERN_ERR     "<3>"  // Error conditions
#define KERN_WARNING "<4>"  // Warning conditions
#define KERN_NOTICE  "<5>"  // Normal but significant
#define KERN_INFO    "<6>"  // Informational
#define KERN_DEBUG   "<7>"  // Debug-level messages

// Control console log level at runtime:
echo 4 > /proc/sys/kernel/printk  // Show only ERROR and above

Dynamic Debug (dyndbg)

# Enable debug output for specific modules at runtime (no recompilation needed)
echo "module nfs file fs/nfs/* +p" > /sys/kernel/debug/dynamic_debug/control
echo "func tcp_rcv_established +p" > /sys/kernel/debug/dynamic_debug/control

# View currently enabled dynamic debug entries
cat /sys/kernel/debug/dynamic_debug/control | grep "=p"

kdump: Crash Dump

# 1. Load capture kernel (at boot or runtime)
kexec -p /boot/vmlinuz-capture --initrd=/boot/initrd-capture \
      --command-line="root=... irqpoll nr_cpus=1 reset_devices"

# 2. Trigger panic → capture kernel starts → vmcore generated
# 3. Analyze:
crash /usr/lib/debug/boot/vmlinux-$(uname -r) /var/crash/vmcore

# crash commands:
crash> bt          # Kernel stacks for all processes
crash> log         # printk buffer at panic time
crash> ps          # Process list at panic time
crash> foreach bt  # Stack backtraces for all tasks

KGDB: Kernel Debugger

Remote kernel debugging via serial port (similar to gdb server):
  → Set breakpoints, step execution, read registers, read memory
  → However, only usable in development/debugging environments (requires special configuration)

Enable: kgdboc=ttyS0,115200 kgdbwait (boot parameter)
Connect: gdb vmlinux → target remote /dev/ttyS0

Practice: Steps for Diagnosing Performance Issues

1. Use perf top to identify CPU hotspots
2. Use bpftrace/bcc to examine latency distributions (biolatency, runqlat, tcpretrans)
3. Use ftrace function_graph to trace call timing in critical paths
4. Use tracepoints to validate hypotheses (e.g., is sched_switch frequency too high?)
5. Write custom tools with eBPF (if necessary)

References

• Source Code: kernel/trace/, kernel/kexec_core.c, kernel/printk/
• Books: "BPF Performance Tools" (Brendan Gregg), "Systems Performance" (same author)
• Tools: perf, bpftrace, bcc, crash, trace-cmd (ftrace frontend)

Keywords: ftrace, function_graph, tracepoint, kprobe, perf, bpftrace, bcc, kdump, crash, dynamic debug, KGDB