When your profiler swears everything’s fast but your metrics are screaming bloody murder eBPF From Rust: The 34ms Ghost We Couldn’t See When your profiler swears everything’s fast but your metrics are screaming bloody murder eBPF provides kernel-depth observability without overhead — tracing from userspace through syscalls to kernel internals reveals bottlenecks invisible to traditional profilers. So here’s the thing that drove us absolutely insane for three weeks straight. Our API had this… ceiling. Like we’d hit an invisible wall at 84ms P99 latency and nothing — and I mean nothing — we tried could push through it. The really maddening part? Every profiler we threw at it said we were doing great. Database queries? Lightning fast. Network calls? Barely a blip. Application code? Optimized to hell and back. But somehow, somewhere, 34 milliseconds were just… vanishing into thin air. Here’s what the numbers looked like (and yes, I stared at these until my eyes crossed): Measured application time: 47ms
Total request time: 84ms
Mystery gap: 37ms (where the hell IS this?)
Traditional profilers: crickets
Team morale: circling the drain Three weeks. THREE WEEKS of this nonsense. And then — okay, this is where it gets interesting — we deployed this eBPF tracing thing from Rust, right? Found the problem in twenty minutes. Twenty. Minutes. Turns out every single request was triggering 127 filesystem stat() calls that we didn’t even know existed. Our profilers just… never showed them. Because they were happening in kernel space. Which is, you know, kind of a big blind spot. After we fixed it: P99 latency: 84ms → 51ms (39% drop, finally!) That mystery gap: gone, just completely gone Stat() syscalls: 127 → 3 per request (yeah, 127) Kernel time: 37ms → 4ms CPU utilization: 67% → 41% (servers basically started coasting) So let me show you how we did this. Because honestly? This changed everything about how we debug. Why Everything We Tried Failed (And Why That Makes Sense, Actually) Standard profiling tools — perf, flamegraphs, all that good stuff — they work in userspace. Which means they see your application code perfectly fine, but the kernel? Total black box. // Your userspace profiler sees this and goes "yep, looks good!"
fn handle_request() -> Response {
start_timer();
let data = load_config(); // Profiler: "2ms, nice!"
let result = process(data); // Profiler: "42ms, fine"
let response = format(result); // Profiler: "3ms, whatever"
end_timer(); // Profiler's final verdict: "47ms total, ship it"
response
}
// But the actual wall clock time? 84ms.
// Those missing 37ms? In the kernel, baby.
// Where your profiler literally cannot see. And here’s what really gets me — that load_config() function? It looked fast. 2ms according to every tool. But under the hood it was doing: 127 stat() calls (checking file metadata over and over) 43 open()/close() operations (why though?) 28 mmap() calls for shared libraries (this seems excessive?) 14 futex() calls for locking (okay this one makes sense) None of this showed up in perf. None of it showed in our flamegraphs. Our Rust profiler? Useless. They all just measured userspace execution time and called it a day. Which, I mean, fair. That’s their job. But it’s also why we were completely blind to the actual problem. What eBPF Actually Does (The Thing That Saved Us) Okay so eBPF — extended Berkeley Packet Filter, which is a terrible name — it lets you run programs inside the kernel without needing to write kernel modules. Which sounds scary but it’s actually super safe because the kernel verifies everything before running it. From Rust, we can: Trace every syscall (entry and exit, the whole journey) Measure kernel time with nanosecond precision (nanoseconds!) Capture stack traces (both userspace and kernel) Run in production with basically zero overhead (like, 2%) Aggregate data in the kernel (so no constant copying to userspace) The Rust eBPF ecosystem is actually pretty mature now: aya — Pure Rust, no C dependencies (this is what we used) libbpf-rs — Safe Rust bindings if you want the C library underneath redbpf — Full-featured framework (heard good things) We went with aya because type safety and because honestly? Not dealing with C was worth it. The Code That Found Our 34ms Black Hole Alright, here’s the actual eBPF program. This runs in the kernel and tracks every syscall with nanosecond precision: // eBPF program (this literally runs in kernel space, wild)
use aya_bpf::{
macros::{kprobe, kretprobe, map},
maps::HashMap,
programs::ProbeContext,
};
// Storage for when syscalls started (per-thread)
#[map]
static mut SYSCALL_START: HashMap<u64, u64> =
HashMap::with_max_entries(10240, 0); // one slot per thread, should be enough
// Accumulated latency by syscall type
#[map]
static mut SYSCALL_LATENCY: HashMap<u32, u64> =
HashMap::with_max_entries(512, 0); // 512 syscall types is overkill but whatever
// This fires when ANY syscall starts
#[kprobe]
pub fn syscall_entry(ctx: ProbeContext) -> u32 {
// Get current thread ID (this is actually thread+process ID combined)
let pid_tgid = unsafe {
bpf_get_current_pid_tgid()
};
// Grab the timestamp right now, in nanoseconds since boot
let ts = unsafe { bpf_ktime_get_ns() };
// Store when this syscall started, we'll need it later
unsafe {
SYSCALL_START.insert(&pid_tgid, &ts, 0)
.unwrap_or(()); // if insert fails, whatever, we'll miss one measurement
}
0 // return 0 means "continue normal execution"
}
// This fires when the syscall returns
#[kretprobe]
pub fn syscall_return(ctx: ProbeContext) -> u32 {
let pid_tgid = unsafe {
bpf_get_current_pid_tgid()
};
// Find when this syscall started
let start = unsafe {
SYSCALL_START.get(&pid_tgid)
};
if let Some(start_ts) = start {
// Calculate how long the syscall took
let now = unsafe { bpf_ktime_get_ns() };
let delta = now - *start_ts; // duration in nanoseconds
// Figure out which syscall this was (stat, open, read, etc)
let syscall_nr = ctx.arg::<u32>(0)
.unwrap_or(0); // if we can't get it, call it syscall 0
// Add this duration to the running total for this syscall type
unsafe {
let current = SYSCALL_LATENCY
.get(&syscall_nr)
.copied()
.unwrap_or(0); // start from 0 if first time seeing this syscall
SYSCALL_LATENCY.insert(
&syscall_nr,
&(current + delta), // accumulate the time
0
).unwrap_or(()); // again, if it fails, we just miss one data point
}
}
0 // all good, carry on
} This is the program that changed everything. No sampling, no guessing, just tracking every single syscall with nanosecond precision. The BPF verifier makes sure it can’t crash the kernel (which is reassuring when you’re running this on production machines). The Userspace Side: Reading What We Found The eBPF program runs in the kernel, but we need userspace code to load it and read the results: use aya::{Bpf, programs::KProbe, maps::HashMap};
use std::time::Duration;
fn main() -> Result<(), Box> {
// Load the compiled eBPF program (we compiled it separately)
let mut bpf = Bpf::load_file("syscall_trace.o")?;
// Attach our entry probe to the syscall entry point
let entry: &mut KProbe = bpf
.program_mut("syscall_entry") // find our entry function
.unwrap()
.try_into()?;
entry.load()?; // load into kernel
entry.attach("sys_enter", 0)?; // attach to syscall entry tracepoint
// Attach our return probe to the syscall exit point
let ret: &mut KProbe = bpf
.program_mut("syscall_return") // find our return function
.unwrap()
.try_into()?;
ret.load()?;
ret.attach("sys_exit", 0)?; // attach to syscall exit tracepoint
println!("Tracing syscalls. Press Ctrl-C to exit.");
println!("(This is running in production btw, very cool)");
// Get a handle to our latency map
let latency_map: HashMap<_, u32, u64> =
HashMap::try_from(
bpf.map_mut("SYSCALL_LATENCY").unwrap()
)?;
// Print results every second (could be configurable but whatever)
loop {
std::thread::sleep(Duration::from_secs(1));
// Iterate over all syscalls we've seen
for (syscall_nr, total_ns) in
latency_map.iter()
{
// Convert syscall number to human-readable name
let syscall_name =
syscall_name(syscall_nr?);
// Convert nanoseconds to milliseconds for readability
let total_ms = total_ns? as f64 / 1_000_000.0;
// Only print if it took more than 1ms total
if total_ms > 1.0 {
println!(
"{}: {:.2}ms",
syscall_name,
total_ms
);
}
}
println!("---"); // separator between time periods
}
Ok(())
} And then we ran this and… holy shit: stat: 34,847.23ms
open: 2,341.45ms
close: 1,847.92ms
mmap: 847.34ms
futex: 234.21ms
--- 34 seconds of stat() calls. Per second of operation. This was it. This was our ghost. The Root Cause (And Why We Felt Dumb) So we followed the trace and found… oh god, this is embarrassing. We were using dynamically loaded plugins: // This innocent-looking code was killing us
fn load_plugin(name: &str) -> Result {
// Load a shared library (.so file)
let lib = unsafe {
libloading::Library::new(
format!("./plugins/{}.so", name)
)?
};
// Get the plugin initialization function
// (THIS is what triggered the stat() storm)
let init: Symbol<fn() -> Plugin> =
unsafe { lib.get(b"plugin_init")? };
Ok(init()) // initialize and return
} Seems fine, right? Except every time this ran, the dynamic linker had to: Scan all 16 directories in LD_LIBRARY_PATH (looking everywhere) Call stat() on every potential location (127 calls per load) Open and parse ELF headers (43 files opened) Map shared libraries into memory (28 mmap operations) And we were doing this. On. Every. Request. facepalm The fix was so obvious once we could see the problem: use once_cell::sync::Lazy;
use std::collections::HashMap;
// Cache plugins after first load (duh)
static PLUGIN_CACHE: Lazy<Mutex<HashMap<String, Plugin>>> =
Lazy::new(|| Mutex::new(HashMap::new()));
fn load_plugin(name: &str) -> Result {
let mut cache = PLUGIN_CACHE.lock().unwrap();
// Check cache first (this is what we should have done from the start)
if let Some(plugin) = cache.get(name) {
return Ok(plugin.clone()); // boom, done, no syscalls
}
// Only load if we haven't seen this plugin before
let lib = unsafe {
libloading::Library::new(
format!("./plugins/{}.so", name)
)?
};
let init: Symbol<fn() -> Plugin> =
unsafe { lib.get(b"plugin_init")? };
let plugin = init();
// Store in cache for next time
cache.insert(name.to_string(), plugin.clone());
Ok(plugin)
} Results after this one-line fix (okay, more than one line, but conceptually): stat() calls: 127 → 3 per request (98% reduction, oh my god) P99 latency: 84ms → 51ms (39% faster, finally breathing) CPU utilization: 67% → 41% (servers basically idling now) Throughput: 4,200 → 6,800 req/sec (62% increase, wild) The thing that kills me? Userspace profilers showed load_config taking 2ms. “Looks good!” But it was actually consuming 37ms of kernel time. The eBPF trace made that invisible work suddenly visible. Other Patterns We Found (Because Once You Start Tracing…) Network Stack Debugging You can trace TCP internals too. We found some wild stuff: // Track TCP retransmissions (packet loss detection)
#[kprobe(function = "tcp_retransmit_skb")]
pub fn trace_tcp_retransmit(ctx: ProbeContext) -> u32 {
// Get the socket struct pointer
let sk = ctx.arg::<*const u8>(0).unwrap_or(null());
// Extract connection details from the socket struct
// (these offsets are kernel-version specific, be careful)
let src_port = unsafe {
read_sk_field(sk, SPORT_OFFSET) // source port
};
let dst_port = unsafe {
read_sk_field(sk, DPORT_OFFSET) // destination port
};
// Track how many retransmits per connection
unsafe {
RETRANSMIT_COUNT.increment(1); // global counter
// Per-connection tracking
let key = (src_port, dst_port);
let count = CONN_RETRANSMITS
.get(&key)
.copied()
.unwrap_or(0);
CONN_RETRANSMITS.insert(
&key,
&(count + 1), // increment this connection's count
0
).unwrap_or(());
}
0
} We discovered 847 TCP retransmits per second on one specific connection . Turns out: Incorrect TCP window size tuning (oops) Buffer overflow in high-throughput path (not good) Specific to one AWS availability zone (???) Fixed the TCP window scaling, eliminated 99.2% of retransmits, improved latency by 23ms. Not bad for a day’s work. Filesystem Operations (More Pain) Track file I/O with crazy precision: // Hook into VFS read operations (all filesystem reads go through this)
#[kprobe(function = "vfs_read")]
pub fn trace_read(ctx: ProbeContext) -> u32 {
let bytes = ctx.arg::(2).unwrap_or(0); // how many bytes being read
let ts_start = unsafe { bpf_ktime_get_ns() }; // when did this start
// Store start time for this thread
unsafe {
IO_START.insert(
&bpf_get_current_pid_tgid(),
&ts_start,
0
).unwrap_or(());
}
0
}
// Hook the return from vfs_read
#[kretprobe(function = "vfs_read")]
pub fn trace_read_return(ctx: ProbeContext) -> u32 {
let pid_tgid = unsafe { bpf_get_current_pid_tgid() };
if let Some(start) = unsafe { IO_START.get(&pid_tgid) } {
// Calculate how long this read took
let duration = unsafe {
bpf_ktime_get_ns()
} - *start;
// Only care about slow reads (>10ms is concerning)
if duration > 10_000_000 { // 10ms in nanoseconds
unsafe {
SLOW_READS.increment(1);
// Build a histogram of slow read latencies
let bucket = duration / 1_000_000; // convert to ms for bucketing
let key = bucket as u32;
let count = READ_HISTOGRAM
.get(&key)
.copied()
.unwrap_or(0);
READ_HISTOGRAM.insert(
&key,
&(count + 1), // one more read in this latency bucket
0
).unwrap_or(());
}
}
}
0
} Found that 12% of our reads took over 10ms. All from one specific log file. The problem: Log rotation held a file lock (blocking everything) New writes blocked readers (cascading delays) Everything waiting on this one file Changed logging to non-blocking mode, eliminated 100% of slow reads. Just… gone. Memory Allocation Mysteries You can even track kernel memory allocations: // Hook into kernel memory allocation
#[kprobe(function = "__kmalloc")]
pub fn trace_kmalloc(ctx: ProbeContext) -> u32 {
let size = ctx.arg::(0).unwrap_or(0); // allocation size
let flags = ctx.arg::(1).unwrap_or(0); // allocation flags (GFP_KERNEL, etc)
// Track large allocations (>1MB is suspicious)
if size > 1024 * 1024 {
unsafe {
// Get the process name that's allocating
let comm = bpf_get_current_comm();
let key = (comm, size);
// Count how many times this process allocates this size
let count = LARGE_ALLOCS
.get(&key)
.copied()
.unwrap_or(0);
LARGE_ALLOCS.insert(
&key,
&(count + 1),
0
).unwrap_or(());
}
}
0
} We were allocating 847MB/sec in kernel space for network buffers. Why? Because: Incorrect socket buffer size (we set it wrong) MTU mismatch causing fragmentation (network config issue) Memory pressure triggering GC (cascading effects) Tuned socket buffers to match MTU, reduced kernel allocations by 94%. Our poor servers could finally breathe. eBPF bridges userspace and kernel observability — Rust programs deploy kernel tracers and aggregate results without performance overhead or safety concerns. The Overhead Question (Because You’re Thinking It) “Yeah but doesn’t all this tracing slow things down?” Great question. Here’s what we measured running eBPF continuously in production: Without eBPF: P99 latency: 51ms Throughput: 6,800 req/sec CPU utilization: 41% With eBPF tracing everything: P99 latency: 52ms (+2% overhead) Throughput: 6,700 req/sec (-1.5% overhead) CPU utilization: 42% (+1% overhead) That’s it. 2% overhead. For complete kernel visibility. Why so low? Kernel-side aggregation (no data copying per-event) BPF verifier ensures safe, bounded execution (no runaway loops) JIT compilation (eBPF programs run as native code) Zero sampling overhead (we track 100% of events efficiently) Compare this to other debugging approaches: Printf debugging: 34% overhead (LOL) Userspace profiling: 12% overhead DTrace-style tracing: 8% overhead eBPF: 2% overhead Yeah. I’ll take 2%. Why Rust Makes This Better (Type Safety Nerds Unite) Okay so here’s why doing this in Rust specifically is awesome: Type Safety: // eBPF maps are strongly typed at compile time
static mut LATENCY: HashMap<u32, u64> =
HashMap::with_max_entries(1024, 0);
unsafe {
// This compiles fine - types match
LATENCY.insert(&syscall_nr, &duration, 0)?;
// This won't compile - type mismatch
// LATENCY.insert(&duration, &syscall_nr, 0)?;
// The compiler catches this before you even run it
} Memory Safety: // The aya verifier ensures no buffer overflows at compile time
let comm: [u8; 16] = unsafe {
bpf_get_current_comm() // always returns exactly 16 bytes
};
// Can't overflow - array size is compile-time known
comm[0..16].copy_from_slice(&data);
// If you try to access comm[17], compiler error Zero-Cost Abstractions: // This high-level iterator code...
for (key, value) in map.iter() {
process(key?, value?);
}
// ...compiles to efficient eBPF map iteration
// No hidden allocations, no overhead
// Just clean, fast code The Rust compiler basically becomes your kernel safety net. It catches mistakes before they hit production, which is kind of a big deal when you’re running code in kernel space. Our Production Setup (The Full Stack) Here’s what we actually deployed: pub struct SystemTracer {
bpf: Bpf, // the loaded eBPF program
syscall_map: HashMap<u32, u64>, // syscall latencies
network_map: HashMap<(u16, u16), u64>, // per-connection stats
io_histogram: HashMap<u32, u64>, // I/O latency distribution
}
impl SystemTracer {
pub fn new() -> Result {
// Load the compiled eBPF program from disk
let mut bpf = Bpf::load_file(
"kernel_t