1 // Copyright 2023 The ChromiumOS Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 use std::collections::HashMap;
6 use std::collections::HashSet;
7 use std::ffi::OsStr;
8 use std::io::Write;
9
10 use anyhow::anyhow;
11 use argh::FromArgs;
12 use libtracecmd::Event;
13 use libtracecmd::Handler;
14 use libtracecmd::Input;
15 use libtracecmd::Record;
16 use log::warn;
17 use serde::Deserialize;
18 use serde::Serialize;
19
20 #[derive(FromArgs, Debug)]
21 /// Command line parameters.
22 struct Config {
23 #[argh(subcommand)]
24 /// decide mode(average,flamegraph)
25 mode: Mode,
26 }
27
28 #[derive(FromArgs, PartialEq, Debug)]
29 #[argh(subcommand)]
30 enum Mode {
31 Average(Average),
32 Flamegraph(Flamegraph),
33 List(List),
34 Histogram(Histogram),
35 }
36
37 #[derive(FromArgs, PartialEq, Debug)]
38 /// print average latency of each cros_tracing event.
39 #[argh(subcommand, name = "average")]
40 struct Average {
41 #[argh(option)]
42 /// path to the input .dat file
43 input: String,
44 }
45
46 #[derive(FromArgs, PartialEq, Debug)]
47 /// output data for flamegraph.
48 #[argh(subcommand, name = "flamegraph")]
49 struct Flamegraph {
50 #[argh(option)]
51 /// path to the input .dat file
52 input: String,
53 #[argh(option)]
54 /// path to the output JSON file
55 output_json: String,
56 #[argh(option)]
57 /// decide which function to focus on
58 /// unspecified: output flamegraph for all event
59 function: Option<String>,
60 #[argh(option)]
61 /// top <n> time consuming events
62 /// unspecified: output flamegraph for all event
63 count: Option<u64>,
64 }
65
66 #[derive(FromArgs, PartialEq, Debug)]
67 /// print the total value and number of appearances
68 /// for the top 10 cros_tracing events of the total value of value
69 #[argh(subcommand, name = "list")]
70 struct List {
71 #[argh(option)]
72 /// path to the input .dat file
73 input: String,
74 #[argh(option)]
75 /// top <n> time consuming events
76 /// unspecified: output list for all event
77 count: Option<usize>,
78 }
79
80 #[derive(FromArgs, PartialEq, Debug)]
81 /// output json file for histogram
82 #[argh(subcommand, name = "histogram")]
83 struct Histogram {
84 #[argh(option)]
85 /// path to the input .dat file
86 input: String,
87 #[argh(option)]
88 /// path to the output JSON file
89 output_json: String,
90 }
91
92 #[derive(Debug, Clone, Serialize, Deserialize)]
93 struct EventInformation {
94 pid: i32,
95 cpu: i32,
96 name: String,
97 time_stamp: u64,
98 details: String,
99 }
100
101 #[derive(Default, Debug, Clone, Serialize, Deserialize)]
102 struct EventData {
103 event_names: HashSet<String>,
104 stats: Vec<EventInformation>,
105 }
106
107 impl EventData {
108 // Populates all cros_tracing events in event_names
populate_event_names(&mut self)109 fn populate_event_names(&mut self) {
110 let mut event_names = HashSet::<String>::new();
111 for stat in &self.stats {
112 if stat.details.contains("Enter") {
113 let split = stat.details.split_whitespace().collect::<Vec<&str>>();
114 let name = split[4];
115 event_names.insert(name.to_string());
116 }
117 }
118 self.event_names = event_names;
119 }
120
121 // Calculates average latency and count of each cros_tracing event
calculate_function_time(&self) -> HashMap<String, (u64, u64)>122 fn calculate_function_time(&self) -> HashMap<String, (u64, u64)> {
123 let mut values = HashMap::new();
124 for event in self.event_names.iter() {
125 let mut count = 0;
126 let mut sum_time = 0;
127 let enter = format!("Enter: {event}");
128 let exit = format!("Exit: {event}");
129 for i in 0..self.stats.len() {
130 if self.stats[i].details.contains(&enter) {
131 let split_enter = self.stats[i]
132 .details
133 .split_whitespace()
134 .collect::<Vec<&str>>();
135 let enter_id = split_enter[1];
136 for j in i + 1..self.stats.len() {
137 if self.stats[j].details.contains(&exit) {
138 let split_exit = self.stats[j]
139 .details
140 .split_whitespace()
141 .collect::<Vec<&str>>();
142 let exit_id = split_exit[1];
143 if enter_id == exit_id {
144 let time = self.stats[j].time_stamp - self.stats[i].time_stamp;
145 sum_time += time;
146 count += 1;
147 break;
148 }
149 }
150 }
151 }
152 }
153
154 if count == 0 {
155 warn!("No exit event found for {}", event);
156 continue;
157 }
158 let latency = sum_time / count;
159 values.insert(String::from(event), (latency, count));
160 }
161 values
162 }
163
164 // Populates all cros_tracing events name and latency in LatencyData
calculate_latency_data(&self) -> LatencyData165 fn calculate_latency_data(&self) -> LatencyData {
166 let mut latency_data: LatencyData = Default::default();
167 let mut histogram_data = HashMap::new();
168 for i in 0..self.stats.len() {
169 if self.stats[i].details.contains("Enter") {
170 let split_enter = self.stats[i]
171 .details
172 .split_whitespace()
173 .collect::<Vec<&str>>();
174 let event_name = split_enter[4];
175 let enter_id = split_enter[1];
176 for j in i + 1..self.stats.len() {
177 if self.stats[j].details.contains("Exit") {
178 let split_exit = self.stats[j]
179 .details
180 .split_whitespace()
181 .collect::<Vec<&str>>();
182 let exit_id = split_exit[1];
183 if enter_id == exit_id {
184 let time = self.stats[j].time_stamp - self.stats[i].time_stamp;
185 let element = LatencyInformation {
186 event_name: event_name.to_string(),
187 enter_index: i,
188 exit_index: j,
189 latency: time,
190 };
191 latency_data.stats.push(element);
192 histogram_data
193 .entry(event_name.to_string())
194 .or_insert_with(Vec::new)
195 .push(time);
196 break;
197 }
198 }
199 }
200 }
201 }
202 latency_data.histogram = histogram_data;
203 latency_data
204 }
205 }
206
207 #[derive(Default, Debug, Clone, Serialize, Deserialize, PartialEq)]
208 struct LatencyInformation {
209 event_name: String,
210 enter_index: usize,
211 exit_index: usize,
212 latency: u64,
213 }
214
215 #[derive(Default, Debug, Clone, Serialize, Deserialize, PartialEq)]
216 struct LatencyData {
217 stats: Vec<LatencyInformation>,
218 histogram: HashMap<String, Vec<u64>>,
219 }
220
221 impl LatencyData {
calculate_root_layer_events( &self, eventdata: &EventData, function_filter: Option<String>, count_filter: Option<u64>, ) -> Vec<LayerData>222 fn calculate_root_layer_events(
223 &self,
224 eventdata: &EventData,
225 function_filter: Option<String>,
226 count_filter: Option<u64>,
227 ) -> Vec<LayerData> {
228 let mut base_layer_data: Vec<LayerData> = Vec::new();
229 let filtered_stats = if let Some(f) = &function_filter {
230 self.stats
231 .clone()
232 .into_iter()
233 .filter(|s| s.event_name.contains(f))
234 .collect()
235 } else {
236 self.stats.clone()
237 };
238 for stat in filtered_stats {
239 let mut layer_data: Vec<LayerData> = Vec::new();
240 let mut index_counter = HashSet::new();
241 let pid = eventdata.stats[stat.enter_index].pid;
242 LatencyData::create_layer(
243 eventdata,
244 stat.enter_index,
245 stat.exit_index,
246 pid,
247 &mut layer_data,
248 &mut index_counter,
249 );
250 let data = LayerData {
251 name: stat.event_name.clone(),
252 value: stat.latency,
253 children: layer_data,
254 };
255 base_layer_data.push(data);
256 }
257 if let Some(count_filter) = count_filter {
258 base_layer_data.sort_by(|a, b| b.value.cmp(&a.value));
259 if count_filter <= base_layer_data.len() as u64 {
260 base_layer_data = base_layer_data[..count_filter as usize].to_vec();
261 }
262 }
263 base_layer_data
264 }
265
266 // Collect syscall data for flamegraph recursively
create_layer( eventdata: &EventData, enter_index: usize, exit_index: usize, pid: i32, layer_data: &mut Vec<LayerData>, mut index_counter: &mut HashSet<usize>, )267 fn create_layer(
268 eventdata: &EventData,
269 enter_index: usize,
270 exit_index: usize,
271 pid: i32,
272 layer_data: &mut Vec<LayerData>,
273 mut index_counter: &mut HashSet<usize>,
274 ) {
275 for i in enter_index + 1..exit_index {
276 // calculate the nested syscalls
277 if index_counter.contains(&i) {
278 continue;
279 }
280 if eventdata.stats[i].pid != pid {
281 continue;
282 }
283 let sys_enter_pid = eventdata.stats[i].pid;
284 // example log: name: "sys_enter_write"
285 if let Some(m) = eventdata.stats[i].name.find("enter") {
286 index_counter.insert(i);
287 // "m" represents e(nter),
288 // m + "enter".len() - 1 represents the first character of syscall_name
289 // example: write
290 let syscall_name = &eventdata.stats[i].name[m + "enter".len() - 1..];
291 let name = format!("sys_{syscall_name}");
292 let exit_name = format!("sys_exit_{syscall_name}");
293 println!("{:?}", name);
294 for j in i + 1..exit_index {
295 if eventdata.stats[j].pid != sys_enter_pid {
296 continue;
297 }
298 if !eventdata.stats[j].name.contains(&exit_name) {
299 continue;
300 }
301 index_counter.insert(j);
302 let layer_time = eventdata.stats[j].time_stamp - eventdata.stats[i].time_stamp;
303 let mut new_layer: Vec<LayerData> = Vec::new();
304 LatencyData::create_layer(
305 eventdata,
306 i,
307 j,
308 sys_enter_pid,
309 &mut new_layer,
310 &mut index_counter,
311 );
312 let data = LayerData {
313 name: name.clone(),
314 value: layer_time,
315 children: new_layer,
316 };
317 layer_data.push(data);
318 break;
319 }
320 } else {
321 let data = LayerData {
322 name: eventdata.stats[i].name.clone(),
323 value: eventdata.stats[i + 1].time_stamp - eventdata.stats[i].time_stamp,
324 children: Vec::new(),
325 };
326 index_counter.insert(i);
327 layer_data.push(data);
328 }
329 }
330 }
331 }
332
333 #[derive(Default, Debug, Clone, Serialize, Deserialize, PartialEq)]
334 struct LayerData {
335 name: String,
336 value: u64,
337 children: Vec<LayerData>,
338 }
339
340 // Struct that we implement `libtracecmd::Handler` for.
341 // Unit struct
342 struct HandlerImplement;
343
344 impl Handler for HandlerImplement {
345 /// Type of data passed to the callback to accumulate data.
346 type AccumulatedData = EventData;
347 /// Callback that processes each trace event `rec` and accumulate statistics to `data`.
348 /// This callback is called for each trace event one by one.
callback( input: &mut Input, rec: &mut Record, cpu: i32, data: &mut Self::AccumulatedData, ) -> i32349 fn callback(
350 input: &mut Input,
351 rec: &mut Record,
352 cpu: i32,
353 data: &mut Self::AccumulatedData, //use for output
354 ) -> i32 {
355 let event: Event = input.find_event(rec).unwrap();
356 let pid = input.handle_ref().unwrap().pid(rec);
357 let time_stamp = rec.ts();
358 let details = event.get_fields(rec);
359 let name = event.name;
360 let element = EventInformation {
361 pid,
362 cpu,
363 name,
364 time_stamp,
365 details,
366 };
367 data.stats.push(element);
368 0
369 }
370 }
371
main() -> anyhow::Result<()>372 fn main() -> anyhow::Result<()> {
373 let cfg: Config = argh::from_env();
374
375 let mode = cfg.mode;
376 match mode {
377 Mode::Average(average) => {
378 let mut input = Input::new(&average.input)?;
379 let mut stats = HandlerImplement::process(&mut input).unwrap();
380 stats.populate_event_names();
381 let data = stats.calculate_function_time();
382 let mut average = Vec::new();
383 for (name, (latency, _)) in &data {
384 average.push((name, latency));
385 }
386 average.sort_by(|a, b| b.1.cmp(&a.1));
387 for i in 0..average.len() {
388 println!("#{}: {}: {} usec", i, average[i].0, average[i].1)
389 }
390 }
391
392 Mode::Flamegraph(flamegraph) => {
393 let mut input = Input::new(&flamegraph.input)?;
394 let stats = HandlerImplement::process(&mut input).unwrap();
395 let output = flamegraph.output_json;
396 if std::path::Path::new(&output)
397 .extension()
398 .and_then(OsStr::to_str)
399 != Some("json")
400 {
401 return Err(anyhow!("file extension must be .json"));
402 }
403 let latency_data = stats.calculate_latency_data();
404 let layer_data = latency_data.calculate_root_layer_events(
405 &stats,
406 flamegraph.function.clone(),
407 flamegraph.count,
408 );
409 let data: LayerData = LayerData {
410 name: "root".to_string(),
411 // set root value to 0 because we don't need it
412 value: 0,
413 children: layer_data,
414 };
415 write_to_file(data, &output)?;
416 }
417 Mode::List(list) => {
418 let mut input = Input::new(&list.input)?;
419 // if count is None, return top 10 events.
420 let count = list.count.unwrap_or(10);
421 let mut stats = HandlerImplement::process(&mut input).unwrap();
422 stats.populate_event_names();
423 let data = stats.calculate_function_time();
424 let mut list = Vec::new();
425 for (name, (latency, count)) in &data {
426 let sum = latency * count;
427 list.push((name, sum, count));
428 }
429 list.sort_by(|a, b| b.1.cmp(&a.1));
430 // print top {count} events of the total value
431 if list.len() >= count {
432 list.truncate(count);
433 }
434 println!("name, total (us), count");
435 for (name, sum, cnt) in list {
436 println!("{name}, {sum}, {cnt}");
437 }
438 return Ok(());
439 }
440 Mode::Histogram(histogram) => {
441 let mut input = Input::new(&histogram.input)?;
442 let stats = HandlerImplement::process(&mut input).unwrap();
443 let output = histogram.output_json;
444 if std::path::Path::new(&output)
445 .extension()
446 .and_then(OsStr::to_str)
447 != Some("json")
448 {
449 return Err(anyhow!("file extension must be .json"));
450 }
451 let histogram_data = stats.calculate_latency_data().histogram;
452
453 write_to_file(histogram_data, &output)?;
454 }
455 }
456 Ok(())
457 }
458
write_to_file<T: serde::Serialize>(data: T, output: &str) -> anyhow::Result<()>459 fn write_to_file<T: serde::Serialize>(data: T, output: &str) -> anyhow::Result<()> {
460 let mut fout = std::fs::OpenOptions::new()
461 .write(true)
462 .create(true)
463 .truncate(true)
464 .open(&output)
465 .unwrap();
466 let serialized = serde_json::to_string(&data).unwrap();
467 fout.write_all(serialized.as_bytes())?;
468 Ok(())
469 }
470
471 #[cfg(test)]
472 mod tests {
473 use super::*;
474
475 // example data
setup() -> EventData476 fn setup() -> EventData {
477 let stats = vec![
478 EventInformation{
479 pid: 100,
480 cpu: 1,
481 name: "print".to_string(),
482 time_stamp: 100,
483 details: " ip=tracing_mark_write buf=32256 VirtioFs Enter: lookup - (self.tag: \"mtdroot\")(parent: 5358)(name: \"LC_MESSAGES\")\n".to_string()
484 },
485 EventInformation {
486 pid: 100,
487 cpu: 1,
488 name: "sys_enter_write".to_string(),
489 time_stamp: 200,
490 details: " __syscall_nr=1 fd=0x00000021 buf=0x7f21e4e0a02f count=0x00000001"
491 .to_string(),
492 },
493 EventInformation {
494 pid: 100,
495 cpu: 1,
496 name: "sys_enter_read".to_string(),
497 time_stamp: 300,
498 details: " __syscall_nr=0 fd=0x00000011 buf=0x7f21ef3fc688 count=0x00000001"
499 .to_string(),
500 },
501 EventInformation {
502 pid: 100,
503 cpu: 1,
504 name: "sys_exit_read".to_string(),
505 time_stamp: 400,
506 details: " __syscall_nr=0 ret=0x1".to_string(),
507 },
508 EventInformation {
509 pid: 100,
510 cpu: 1,
511 name: "sys_exit_write".to_string(),
512 time_stamp: 500,
513 details: " __syscall_nr=1 ret=0x1".to_string(),
514 },
515 EventInformation {
516 pid: 100,
517 cpu: 1,
518 name: "print".to_string(),
519 time_stamp: 600,
520 details: " ip=tracing_mark_write buf=32256 VirtioFs Exit: lookup\n".to_string(),
521 },
522 ];
523 let event_names = HashSet::<String>::new();
524 EventData { event_names, stats }
525 }
526
527 #[test]
populate_event_names_test()528 fn populate_event_names_test() {
529 let mut data = setup();
530 data.populate_event_names();
531 assert_eq!(data.event_names, HashSet::from(["lookup".to_string()]));
532 }
533
534 #[test]
calculate_latency_data_test()535 fn calculate_latency_data_test() {
536 let data = setup();
537 let latency_data = data.calculate_latency_data();
538 let expected_vec = vec![500];
539 let expected_hashmap: HashMap<String, Vec<u64>> =
540 HashMap::from([("lookup".to_string(), expected_vec)]);
541 let expected_data = LatencyData {
542 stats: [LatencyInformation {
543 event_name: "lookup".to_string(),
544 enter_index: 0,
545 exit_index: 5,
546 latency: 500,
547 }]
548 .to_vec(),
549 histogram: expected_hashmap,
550 };
551 assert_eq!(latency_data, expected_data);
552 }
553
554 #[test]
create_layer_test()555 fn create_layer_test() {
556 let data = setup();
557 let mut test_layer_data: Vec<LayerData> = Vec::new();
558 let mut test_index_counter = HashSet::new();
559 LatencyData::create_layer(
560 &data,
561 0,
562 5,
563 100,
564 &mut test_layer_data,
565 &mut test_index_counter,
566 );
567 let expected_data = vec![LayerData {
568 name: "sys_write".to_string(),
569 value: 300,
570 children: [LayerData {
571 name: "sys_read".to_string(),
572 value: 100,
573 children: vec![].to_vec(),
574 }]
575 .to_vec(),
576 }];
577 assert_eq!(test_layer_data, expected_data);
578 }
579 }
580