New latency tracer tool

 - Requires new tracepoint, sched_blocked, that returns the time a task
   wasn't running for

 - Runs a command with tracing enabled, recording stack traces, then
   gives events and aggregated totals

Signed-off-by: Kent Overstreet <kent.overstreet@linux.dev>

3 files changed, 232 insertions, 0 deletions

diff --git a/.gitignore b/.gitignore
new file mode 100644
index 0000000..ea8c4bf
--- /dev/null
+++ b/.gitignore
@@ -0,0 +1 @@
+/target
diff --git a/Cargo.toml b/Cargo.toml
new file mode 100644
index 0000000..b4a09d7
--- /dev/null
+++ b/Cargo.toml
@@ -0,0 +1,8 @@
+[package]
+name = "latency-tracer"
+version = "0.1.0"
+edition = "2021"
+
+# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
+
+[dependencies]
diff --git a/src/main.rs b/src/main.rs
new file mode 100644
index 0000000..30ed4b4
--- /dev/null
+++ b/src/main.rs
@@ -0,0 +1,223 @@
+use std::env;
+use std::fmt;
+use std::fs::File;
+use std::io;
+use std::io::prelude::*;
+use std::io::BufReader;
+use std::process::Command;
+
+#[derive(Debug, Clone)]
+struct BlockedEvent {
+    ns:             u64,
+    stacktrace:     Vec<String>,
+}
+
+const TIME_UNITS: &[&str] = &[
+    "ns",
+    "us",
+    "ms",
+    "sec",
+]; 
+
+impl fmt::Display for BlockedEvent {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        let mut ns = self.ns as f64;
+        let mut u = 0;
+
+        while ns > 10000.0 && u + 1 < TIME_UNITS.len() {
+            ns /= 1000.0;
+            u += 1;
+        }
+
+        write!(f, "{:>6.1}{}", ns, TIME_UNITS[u])?;
+
+        for (idx, e) in self.stacktrace.iter().enumerate() {
+            if idx != 0 {
+                write!(f, " =>")?;
+            }
+            write!(f, " {}", e)?;
+        }
+
+        Ok(())
+    }
+}
+
+const STACK_START_FILTER: &[&str] = &[
+    "trace_event_raw_event_sched_blocked",
+    "__schedule",
+    "_schedule",
+    "schedule",
+]; 
+
+const STACK_END_FILTER: &[&str] = &[
+    "entry_SYSCALL_64_after_hwframe",
+    "do_syscall_64",
+    "__x86_sys_",
+    "ret_from_fork",
+    "kthread",
+    "worker_thread",
+]; 
+
+const STACK_FILTER: &[&[&str]] = &[
+    &["schedule_idle",      "do_idle"],
+    &["read_events",        "do_io_getevents"],
+    &["schedule_idle",      "do_idle"],
+    &["__cond_resched",     "process_one_work"],
+    &["schedule_timeout",   "rcu_gp_fqs_loop",    "rcu_gp_kthread"],
+    &["ring_buffer_wait",   "tracing_wait_pipe"],
+    &["do_epoll_wait"],
+    &["worker_thread"],
+    &["smpboot_thread_fn"],
+]; 
+
+fn should_skip_event(ev: &BlockedEvent) -> bool {
+    if ev.stacktrace.is_empty() {
+        return true;
+    }
+
+    for i in STACK_FILTER {
+        if !i.iter()
+            .zip(ev.stacktrace.iter())
+            .find(|(l, r)| !r.starts_with(*l)).is_some() {
+            return true;
+        }
+    }
+
+    false
+}
+
+fn string_matches(a: &[&str], v: &str) -> bool {
+    for i in a {
+        if v.starts_with(i) {
+            return true;
+        }
+    }
+
+    false
+}
+
+fn event_trim(ev: &mut BlockedEvent) {
+    while ev.stacktrace.len() > 1 {
+        let l = ev.stacktrace.last().unwrap();
+
+        if string_matches(STACK_END_FILTER, &l[..]) {
+            ev.stacktrace.pop();
+        } else {
+            break;
+        }
+    }
+}
+
+fn read_trace(mut child: std::process::Child) -> io::Result<Vec<BlockedEvent>> {
+    let tracepoint_name = "sched_blocked: ";
+    let trace_pipe = File::open("/sys/kernel/debug/tracing/trace_pipe")
+        .map_err(|e| {eprintln!("error opening trace: {}", e); e})?;
+    let mut lines = BufReader::new(trace_pipe)
+        .lines()
+        .filter_map(|i| i.ok())
+        .peekable();
+
+    let mut evs: Vec<BlockedEvent> = Vec::new();
+
+    while let Some(line) = lines.next() {
+        let idx = line.rfind(tracepoint_name);
+        if idx.is_none() {
+            continue;
+        }
+
+        let idx = idx.unwrap() + tracepoint_name.len();
+        let mut ev = BlockedEvent {
+            ns:         line[idx..].parse().unwrap(),
+            stacktrace: Vec::new(),
+        };
+
+        let line = lines.next_if(|i| i.find("<stack trace>").is_some());
+        if line.is_none() {
+            continue;
+        }
+
+        while let Some(line) = lines.next_if(|i| i.starts_with(" => ")) {
+            let func = &line[4..];
+
+            if !ev.stacktrace.is_empty() ||
+                !string_matches(STACK_START_FILTER, func) {
+                    ev.stacktrace.push(func.to_string());
+            }
+        }
+
+        event_trim(&mut ev);
+
+        if !should_skip_event(&ev) {
+            evs.push(ev);
+        }
+
+        match child.try_wait() {
+            Err(_e)             => break,
+            Ok(Some(_status))   => break,
+            Ok(None)            => continue,
+        }
+    }
+
+    Ok(evs)
+}
+
+fn run_trace(args: Vec<String>) -> io::Result<()> {
+    std::fs::write("/sys/kernel/debug/tracing/trace",                               "")
+        .map_err(|e| {eprintln!("error clearing trace: {}", e); e})?;
+    std::fs::write("/sys/kernel/debug/tracing/buffer_size_kb",                      "8192")
+        .map_err(|e| {eprintln!("error writing buffer size: {}", e); e})?;
+    std::fs::write("/sys/kernel/debug/tracing/set_event",                           "sched:sched_blocked")
+        .map_err(|e| {eprintln!("error setting event: {}", e); e})?;
+    std::fs::write("/sys/kernel/debug/tracing/events/sched/sched_blocked/trigger",  "stacktrace").ok();
+    std::fs::write("/sys/kernel/debug/tracing/trace_options",                       "sym-offset")
+        .map_err(|e| {eprintln!("error setting sym-offset: {}", e); e})?;
+    std::fs::write("/sys/kernel/debug/tracing/tracing_on",                          "1")
+        .map_err(|e| {eprintln!("error enabling tracing: {}", e); e})?;
+
+    let child = Command::new(&args[0])
+        .args(&args[1..])
+        .spawn()
+        .expect(&format!("Failed to start child process {}", args[0]));
+
+    let mut evs = read_trace(child)?;
+
+    evs.sort_by(|l, r| l.ns.cmp(&r.ns));
+
+    println!("\nIndividual events:");
+    for i in evs.iter().rev().take(30) {
+        println!("{}", i);
+    }
+
+    evs.sort_by(|l, r| l.stacktrace.cmp(&r.stacktrace));
+
+    let mut evs_folded: Vec<BlockedEvent> = Vec::new();
+
+    for i in evs.iter() {
+        if let Some(l) = evs_folded.last_mut() {
+            if l.stacktrace == i.stacktrace {
+                l.ns += i.ns;
+            } else {
+                evs_folded.push(i.clone());
+            }
+        } else {
+            evs_folded.push(i.clone());
+        }
+    }
+
+    evs_folded.sort_by(|l, r| l.ns.cmp(&r.ns));
+
+    println!("\nAggregate blocked time:");
+    for i in evs_folded.iter().rev().take(30) {
+        println!("{}", i);
+    }
+
+    Ok(())
+}
+
+fn main() {
+    let args = env::args();
+
+    let args: Vec<String> = args.skip(1).collect();
+
+    run_trace(args).ok();
+}