diff --git a/tools/contrib/cros_tracing_analyser/Cargo.lock b/tools/contrib/cros_tracing_analyser/Cargo.lock index 319f8f8998..d19e96c663 100644 --- a/tools/contrib/cros_tracing_analyser/Cargo.lock +++ b/tools/contrib/cros_tracing_analyser/Cargo.lock @@ -13,9 +13,9 @@ dependencies = [ [[package]] name = "anyhow" -version = "1.0.72" +version = "1.0.75" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3b13c32d80ecc7ab747b80c3784bce54ee8a7a0cc4fbda9bf4cda2cf6fe90854" +checksum = "a4668cab20f66d8d020e1fbc0ebe47217433c1b6c8f2040faf858554e394ace6" [[package]] name = "argh" @@ -107,6 +107,7 @@ dependencies = [ name = "cros_tracing_analyser" version = "0.1.0" dependencies = [ + "anyhow", "argh", "libtracecmd", "once_cell", diff --git a/tools/contrib/cros_tracing_analyser/Cargo.toml b/tools/contrib/cros_tracing_analyser/Cargo.toml index f7f518aabc..d3123790f6 100644 --- a/tools/contrib/cros_tracing_analyser/Cargo.toml +++ b/tools/contrib/cros_tracing_analyser/Cargo.toml @@ -6,6 +6,7 @@ edition = "2021" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] +anyhow = "1.0.75" argh = "*" libtracecmd = ">=0.2.0" once_cell = "1.18.0" diff --git a/tools/contrib/cros_tracing_analyser/README.md b/tools/contrib/cros_tracing_analyser/README.md new file mode 100644 index 0000000000..d41eb44041 --- /dev/null +++ b/tools/contrib/cros_tracing_analyser/README.md @@ -0,0 +1,31 @@ +# Analyzes cros_tracing event + +Extract event_data and timestamp from input file from `trace-cmd record` and calculate average +latency of cros_tracing events + +## How to calculate event average latency + +``` +$ cargo run -- average --input trace.dat --output-json tracing_data.json +``` + +calculate the average latency for each virtiofs event and output it to json file + +## How to generate flamegraph data + +``` +$ cargo run -- flamegraph --input trace.dat --output-json tracing_data.json +``` + +Extract all events and calculate its latency and output it to a json file compatibile with d3 +flamegraph. + +To visualize the html page with the flamegraph, you need to run a local webserver. You can do this +with a simple python http server: + +``` +$ python3 -m http.server +``` + +And then open the page at http://localhost:8000/flamegraph.html and the flamegraph will be +displayed. diff --git a/tools/contrib/cros_tracing_analyser/flamegraph.html b/tools/contrib/cros_tracing_analyser/flamegraph.html new file mode 100644 index 0000000000..962005c237 --- /dev/null +++ b/tools/contrib/cros_tracing_analyser/flamegraph.html @@ -0,0 +1,26 @@ + + + + + + +
+ + + + diff --git a/tools/contrib/cros_tracing_analyser/src/README.md b/tools/contrib/cros_tracing_analyser/src/README.md deleted file mode 100644 index 6706c3bc0b..0000000000 --- a/tools/contrib/cros_tracing_analyser/src/README.md +++ /dev/null @@ -1,13 +0,0 @@ -# cros_tracing_analyser - -Extract event_data and timestamp from input file from `trace-cmd record` and calculate average -latency of cros_tracing event - -## Build - -Build the tool with cargo, and then run the binary with an input and output file path. - -``` -$ cargo run -$ cargo run -- --input /* path */ --output /* path */ -``` diff --git a/tools/contrib/cros_tracing_analyser/src/main.rs b/tools/contrib/cros_tracing_analyser/src/main.rs index 2ea7b86bd6..d1db296075 100644 --- a/tools/contrib/cros_tracing_analyser/src/main.rs +++ b/tools/contrib/cros_tracing_analyser/src/main.rs @@ -2,29 +2,58 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. +use anyhow::anyhow; use argh::FromArgs; use libtracecmd::Event; use libtracecmd::Handler; use libtracecmd::Input; use libtracecmd::Record; -use once_cell::sync::OnceCell; use serde::{Deserialize, Serialize}; use std::collections::HashMap; use std::collections::HashSet; +use std::ffi::OsStr; use std::io::Write; #[derive(FromArgs, Debug)] /// Command line parameters. struct Config { + #[argh(subcommand)] + /// decide mode(average,flamegraph) + mode: Mode, +} + +#[derive(FromArgs, PartialEq, Debug)] +#[argh(subcommand)] +enum Mode { + Average(Average), + Flamegraph(Flamegraph), +} + +#[derive(FromArgs, PartialEq, Debug)] +/// output average latency of each cros_tracing event. +#[argh(subcommand, name = "average")] +struct Average { #[argh(option)] /// path to the input .dat file input: String, #[argh(option)] - /// path to the output .json file - output: String, + /// path to the output JSON file + output_json: String, } -#[derive(Debug, Serialize, Deserialize)] +#[derive(FromArgs, PartialEq, Debug)] +/// output data for flamegraph. +#[argh(subcommand, name = "flamegraph")] +struct Flamegraph { + #[argh(option)] + /// path to the input .dat file + input: String, + #[argh(option)] + /// path to the output JSON file + output_json: String, +} + +#[derive(Debug, Clone, Serialize, Deserialize)] struct EventInformation { pid: i32, cpu: i32, @@ -33,7 +62,7 @@ struct EventInformation { details: String, } -#[derive(Default, Debug, Serialize, Deserialize)] +#[derive(Default, Debug, Clone, Serialize, Deserialize)] struct EventData { event_names: HashSet, stats: Vec, @@ -52,6 +81,7 @@ impl EventData { } self.event_names = event_names; } + // Calculates average latency of each cros_tracing event fn calculate_function_time(&self) -> HashMap { let mut values = HashMap::new(); @@ -90,6 +120,144 @@ impl EventData { } values } + + //Populates all cros_tracing events name and latency in LatencyData + fn calculate_latency_data(&self) -> LatencyData { + let mut latency_data: LatencyData = Default::default(); + for i in 0..self.stats.len() { + if self.stats[i].details.contains("Enter") { + let split_enter = self.stats[i] + .details + .split_whitespace() + .collect::>(); + let event_name = split_enter[4]; + let enter_id = split_enter[1]; + for j in i + 1..self.stats.len() { + if self.stats[j].details.contains("Exit") { + let split_exit = self.stats[j] + .details + .split_whitespace() + .collect::>(); + let exit_id = split_exit[1]; + if enter_id == exit_id { + let time = self.stats[j].time_stamp - self.stats[i].time_stamp; + let element = LatencyInformation { + event_name: event_name.to_string(), + enter_index: i, + exit_index: j, + latency: time, + }; + latency_data.stats.push(element); + break; + } + } + } + } + } + latency_data + } +} + +#[derive(Default, Debug, Clone, Serialize, Deserialize)] +struct LatencyInformation { + event_name: String, + enter_index: usize, + exit_index: usize, + latency: u64, +} + +#[derive(Default, Debug, Clone, Serialize, Deserialize)] +struct LatencyData { + stats: Vec, +} + +impl LatencyData { + fn calculate_root_layer_events(&self, eventdata: &EventData) -> Vec { + let mut base_layer_data: Vec = Vec::new(); + for i in 0..self.stats.len() { + let mut layer_data: Vec = Vec::new(); + let mut index_counter = HashSet::new(); + let pid = eventdata.stats[self.stats[i].enter_index].pid; + LatencyData::create_layer( + eventdata, + self.stats[i].enter_index, + self.stats[i].exit_index, + pid, + &mut layer_data, + &mut index_counter, + ); + let data = LayerData { + name: self.stats[i].event_name.clone(), + value: self.stats[i].latency, + children: layer_data, + }; + base_layer_data.push(data); + } + base_layer_data + } + + // collect syscall data for flamegraph recursively + fn create_layer( + eventdata: &EventData, + enter_index: usize, + exit_index: usize, + pid: i32, + layer_data: &mut Vec, + mut index_counter: &mut HashSet, + ) { + for i in enter_index + 1..exit_index { + // calculate the nested syscalls + if index_counter.contains(&i) { + continue; + } + if eventdata.stats[i].pid != pid { + continue; + } + let sys_enter_pid = eventdata.stats[i].pid; + // example log: name: "sys_enter_write" + if let Some(m) = eventdata.stats[i].name.find("enter") { + index_counter.insert(i); + // "m" represents e(nter), + // m + "enter".len() represents the first character of syscall_name + // example: write + let syscall_name = &eventdata.stats[i].name[m + "enter".len()..]; + let name = format!("sys_{syscall_name}"); + let exit_name = format!("sys_exit_{syscall_name}"); + for j in i + 1..exit_index { + if eventdata.stats[j].pid != sys_enter_pid { + continue; + } + if !eventdata.stats[j].name.contains(&exit_name) { + continue; + } + let layer_time = eventdata.stats[j].time_stamp - eventdata.stats[i].time_stamp; + let mut new_layer: Vec = Vec::new(); + LatencyData::create_layer( + eventdata, + i, + j, + sys_enter_pid, + &mut new_layer, + &mut index_counter, + ); + let data = LayerData { + name: name.clone(), + value: layer_time, + children: new_layer, + }; + layer_data.push(data); + break; + } + } + } + } +} + +#[derive(Default, Debug, Clone, Serialize, Deserialize)] +struct LayerData { + name: String, + value: u64, + children: Vec, } // Struct that we implement `libtracecmd::Handler` for. @@ -124,20 +292,64 @@ impl Handler for HandlerImplement { } } -fn main() { +fn main() -> anyhow::Result<()> { let cfg: Config = argh::from_env(); - let input = cfg.input.clone(); - let mut input = Input::new(&input).expect("input is invalid"); - let mut stats = HandlerImplement::process(&mut input).unwrap(); - stats.populate_event_names(); - let average_data = stats.calculate_function_time(); - let output = cfg.output.clone(); + let mode = cfg.mode; + match mode { + Mode::Average(average) => { + let input = average.input; + let mut input = Input::new(&input)?; + let mut stats = HandlerImplement::process(&mut input).unwrap(); + let output = average.output_json; + if std::path::Path::new(&output) + .extension() + .and_then(OsStr::to_str) + != Some("json") + { + return Err(anyhow!("file extension must be .json")); + } + + stats.populate_event_names(); + let average_data = stats.calculate_function_time(); + write_to_file(average_data, &output) + } + + Mode::Flamegraph(flamegraph) => { + let input = flamegraph.input; + let mut input = Input::new(&input)?; + let mut stats = HandlerImplement::process(&mut input).unwrap(); + let output = flamegraph.output_json; + if std::path::Path::new(&output) + .extension() + .and_then(OsStr::to_str) + != Some("json") + { + return Err(anyhow!("file extension must be .json")); + } + + let latency_data = stats.calculate_latency_data(); + let layer_data = latency_data.calculate_root_layer_events(&stats); + let data: LayerData = LayerData { + name: "root".to_string(), + // set root value to 0 because we don't need it + value: 0, + children: layer_data, + }; + write_to_file(data, &output) + } + } + + Ok(()) +} + +fn write_to_file(data: T, output: &str) { let mut fout = std::fs::OpenOptions::new() .write(true) .create(true) + .truncate(true) .open(&output) .unwrap(); - let serialized = serde_json::to_string(&average_data).unwrap(); + let serialized = serde_json::to_string(&data).unwrap(); fout.write_all(serialized.as_bytes()); }