cros_tracing_analyser: Add feature for flamegraph

Extract name and latency of all events output it to json file

BUG=b:297954291
TEST= Run the tool with a trace.dat collected by trace-cmd.

Change-Id: Iea72e4aebaaecc4b11e7289af771540c32938d71
Reviewed-on: https://chromium-review.googlesource.com/c/crosvm/crosvm/+/4839555
Reviewed-by: Takaya Saeki <takayas@chromium.org>
Reviewed-by: Keiichi Watanabe <keiichiw@chromium.org>
Reviewed-by: Ryuichiro Chiba <chibar@chromium.org>
Commit-Queue: Natsuko Mineno <natsukomineno@google.com>
This commit is contained in:
Natsuko Mineno 2023-09-05 04:05:12 +00:00 committed by crosvm LUCI
parent ab9ee8cadb
commit c2967a6ede
6 changed files with 286 additions and 28 deletions

View file

@ -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",

View file

@ -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"

View file

@ -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.

View file

@ -0,0 +1,26 @@
<!-- Copyright 2023 The ChromiumOS Authors
Use of this source code is governed by a BSD-style license that can be
found in the LICENSE file. -->
<head>
<link rel="stylesheet" type="text/css" href="https://cdn.jsdelivr.net/npm/d3-flame-graph@4.1.3/dist/d3-flamegraph.css">
</head>
<body>
<div id="chart"></div>
<script type="text/javascript" src="https://d3js.org/d3.v7.js"></script>
<script type="text/javascript" src="https://cdn.jsdelivr.net/npm/d3-flame-graph@4.1.3/dist/d3-flamegraph.min.js"></script>
<script type="text/javascript">
var chart = flamegraph()
.width(960);
chart.selfValue(true);
d3.json("tracing_data.json")
.then(data => {
d3.select("#chart")
.datum(data)
.call(chart);
}).catch(error => {
return console.warn(error);
});
</script>
</body>

View file

@ -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 */
```

View file

@ -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<String>,
stats: Vec<EventInformation>,
@ -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<String, u64> {
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::<Vec<&str>>();
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::<Vec<&str>>();
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<LatencyInformation>,
}
impl LatencyData {
fn calculate_root_layer_events(&self, eventdata: &EventData) -> Vec<LayerData> {
let mut base_layer_data: Vec<LayerData> = Vec::new();
for i in 0..self.stats.len() {
let mut layer_data: Vec<LayerData> = 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<LayerData>,
mut index_counter: &mut HashSet<usize>,
) {
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<LayerData> = 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<LayerData>,
}
// 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<T: serde::Serialize>(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());
}