| // Copyright 2019 The Chromium OS Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| use trace_events::{Argument, ArgumentValue, Label, Point, Scope, Tracer}; |
| |
| use std::fmt::Write as FmtWrite; |
| use std::fs::File; |
| use std::io::Write; |
| use std::os::unix::io::AsRawFd; |
| |
| use libc::dup2; |
| |
| const NANOS_PER_MICRO: u64 = 1000; |
| |
| // This will immediately write the record to the given file. The original implementation of this |
| // function cached records in a thread local buffer, but this complicated the usage of this library |
| // too significantly. There was no good time to flush the cache without using exotic OS alarm |
| // primitives or manually putting code to flush in every thread of the client application. |
| fn write_record<F: FnOnce(&mut String)>( |
| ph: char, |
| Label { name, category }: Label, |
| Point { |
| ts, |
| thread_ts, |
| tid, |
| pid, |
| }: Point, |
| args: &[Argument], |
| counters: &[(&str, u64)], |
| extra_props: F, |
| out_file: Option<&File>, |
| ) { |
| let mut f = match out_file { |
| Some(f) => f, |
| None => return, |
| }; |
| let mut s = String::with_capacity(4096); |
| s.push('{'); |
| |
| { |
| s.push_str(r#""name":""#); |
| s.push_str(name); |
| s.push_str(r#"","#); |
| |
| s.push_str(r#""cat":""#); |
| s.push_str(category); |
| s.push_str(r#"","#); |
| |
| s.push_str(r#""ph":""#); |
| s.push(ph); |
| s.push_str(r#"","#); |
| |
| s.push_str(r#""ts":"#); |
| let _ = write!(s, "{}", ts / NANOS_PER_MICRO); |
| s.push_str(","); |
| |
| if let Some(tts) = thread_ts { |
| s.push_str(r#""tts":"#); |
| let _ = write!(s, "{}", tts.get() / NANOS_PER_MICRO); |
| s.push_str(","); |
| } |
| |
| s.push_str(r#""pid":"#); |
| let _ = write!(s, "{}", pid); |
| s.push_str(","); |
| |
| s.push_str(r#""tid":"#); |
| let _ = write!(s, "{}", tid); |
| s.push_str(","); |
| |
| extra_props(&mut s); |
| |
| s.push_str(r#""args":{"#); |
| { |
| for arg in args { |
| s.push('"'); |
| s.push_str(arg.key); |
| s.push_str(r#"":"#); |
| match arg.value { |
| ArgumentValue::Bool(b) => s.push_str(if b { "true" } else { "false" }), |
| ArgumentValue::Sint(i) => { |
| let _ = write!(s, "{}", i); |
| } |
| ArgumentValue::Uint(i) => { |
| let _ = write!(s, "{}", i); |
| } |
| ArgumentValue::Float(f) => { |
| let _ = write!(s, "{}", f); |
| } |
| ArgumentValue::String(v) => { |
| let _ = write!(s, "{:?}", v); |
| } |
| } |
| s.push(','); |
| } |
| for (key, value) in counters { |
| s.push('"'); |
| s.push_str(key); |
| s.push_str(r#"":"#); |
| let _ = write!(s, "{}", value); |
| s.push(','); |
| } |
| // Remove trailing comma |
| if !args.is_empty() || !counters.is_empty() { |
| s.pop(); |
| } |
| } |
| s.push_str("}"); |
| } |
| |
| s.push_str("},\n"); |
| let _ = f.write(s.as_bytes()); |
| } |
| |
| /// A tracer that outputs to a file in the [Json Trace Event Format](https://docs.google.com/document/u/1/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view). |
| /// |
| /// The most convenient viewer is the one builtin to Chrome: `chrome://tracing`. |
| #[derive(Default)] |
| pub struct JsonTracer { |
| out_file: Option<File>, |
| } |
| |
| impl JsonTracer { |
| /// Creates a new `JsonTracer` with no output. |
| pub fn new() -> JsonTracer { |
| Default::default() |
| } |
| |
| /// Sets the file that tracing output will be written to. |
| /// |
| /// The given file will immediately start being written to in order to output prefix data. |
| pub fn set_out_file(&mut self, mut out_file: File) { |
| let _ = out_file.write(b"[\n"); |
| self.out_file = Some(out_file); |
| } |
| |
| /// Closes the previously set file and outputs to the given `out_file`, returning `true` on |
| /// success. |
| /// |
| /// This will fail if `set_out_file` was never called previously. Internally, this uses `dup2` |
| /// to atomically clone the given file to the already set file, allowing `JsonTracer` to be |
| /// lock-free. |
| /// |
| /// This is most useful for closing the previously set file after tracing is finished while |
| /// still allowing any outstanding flushes to safely write to `out_file`, often `/dev/null`. |
| pub fn reset_out_file(&self, out_file: &File) -> bool { |
| match self.out_file.as_ref() { |
| Some(f) => unsafe { dup2(out_file.as_raw_fd(), f.as_raw_fd()) == 0 }, |
| None => false, |
| } |
| } |
| } |
| |
| impl Tracer for JsonTracer { |
| fn duration_begin(&self, label: Label, begin: Point, args: &[Argument]) { |
| write_record('B', label, begin, args, &[], |_| {}, self.out_file.as_ref()); |
| } |
| |
| fn duration_end(&self, label: Label, end: Point, args: &[Argument]) { |
| write_record('E', label, end, args, &[], |_| {}, self.out_file.as_ref()); |
| } |
| |
| fn duration(&self, label: Label, begin: Point, duration: u64, args: &[Argument]) { |
| write_record( |
| 'X', |
| label, |
| begin, |
| args, |
| &[], |
| |s| { |
| s.push_str(r#""dur":"#); |
| let _ = write!(s, "{}", duration / NANOS_PER_MICRO); |
| s.push_str(r#","#); |
| }, |
| self.out_file.as_ref(), |
| ); |
| } |
| |
| fn instant(&self, label: Label, instant: Point, scope: Scope, args: &[Argument]) { |
| let scope_ty = match scope { |
| Scope::Global => 'g', |
| Scope::Process => 'p', |
| Scope::Thread => 't', |
| }; |
| write_record( |
| 'i', |
| label, |
| instant, |
| args, |
| &[], |
| |s| { |
| s.push_str(r#""scope":""#); |
| s.push(scope_ty); |
| s.push_str(r#"","#); |
| }, |
| self.out_file.as_ref(), |
| ); |
| } |
| |
| fn counter(&self, label: Label, instant: Point, counters: &[(&str, u64)]) { |
| write_record( |
| 'C', |
| label, |
| instant, |
| &[], |
| counters, |
| |_| {}, |
| self.out_file.as_ref(), |
| ); |
| } |
| } |
| |
| #[cfg(test)] |
| mod tests { |
| use super::*; |
| use libc::{c_char, syscall, SYS_memfd_create}; |
| use serde_json::{json, Value}; |
| use std::fs::File; |
| use std::io::{Read, Seek, SeekFrom}; |
| use std::os::unix::io::{FromRawFd, RawFd}; |
| |
| /// Creates a pair of memfds pointing to the same backing. |
| fn memfd_create_pair() -> (File, File) { |
| let f1 = unsafe { |
| let fd = syscall( |
| SYS_memfd_create, |
| b"/json_memfd\0".as_ptr() as *const c_char, |
| 0, |
| ); |
| assert!(fd >= 0, "failed to create memfd"); |
| File::from_raw_fd(fd as RawFd) |
| }; |
| let f2 = f1.try_clone().expect("failed to clone memfd"); |
| (f1, f2) |
| } |
| |
| /// Reads the contents of a file prior to its current cursor and terminates the trace for parsing. |
| fn read_out(mut f: &File) -> String { |
| let cursor = f |
| .seek(SeekFrom::Current(0)) |
| .expect("failed to find file cursor"); |
| let mut s = String::with_capacity(cursor as usize); |
| f.seek(SeekFrom::Start(0)) |
| .expect("failed to seek file cursor to beginning"); |
| f.read_to_string(&mut s) |
| .expect("failed to read file to string"); |
| s.truncate(s.len() - 2); |
| s.push(']'); |
| s |
| } |
| |
| /// Creates a `JsonTracer` with its output set to a file, along with a duplication of that file |
| /// intended for reading later. |
| fn init_json_tracer() -> (JsonTracer, File) { |
| let (f1, f2) = memfd_create_pair(); |
| let mut t = JsonTracer::new(); |
| t.set_out_file(f1); |
| (t, f2) |
| } |
| |
| #[test] |
| fn duration() { |
| let (t, out_file) = init_json_tracer(); |
| let label = Label::new("test", "duration"); |
| let begin = Point::from_timestamp(45600); |
| let duration = 10000; |
| t.duration(label, begin, duration, &[]); |
| let out = read_out(&out_file); |
| println!("out = {}", out); |
| let out_val: Value = serde_json::from_str(&out).unwrap(); |
| assert_eq!( |
| out_val, |
| json!([{ |
| "name": label.name, |
| "cat": label.category, |
| "ph": "X", |
| "ts": begin.ts / NANOS_PER_MICRO, |
| "dur": duration / NANOS_PER_MICRO, |
| "pid": begin.pid, |
| "tid": begin.tid, |
| "args": {} |
| }]) |
| ); |
| } |
| |
| #[test] |
| fn instant() { |
| let (t, out_file) = init_json_tracer(); |
| let label = Label::new("test", "instant"); |
| let point = Point::from_timestamp(45600); |
| let scope = Scope::Global; |
| t.instant( |
| label, |
| point, |
| scope, |
| &[ |
| Argument::new("apples", 2), |
| Argument::new("cost", 5.1), |
| Argument::new("paid", true), |
| Argument::new("invalid", false), |
| Argument::new("special", "spicy"), |
| ], |
| ); |
| let out = read_out(&out_file); |
| println!("out = {}", out); |
| let out_val: Value = serde_json::from_str(&out).unwrap(); |
| assert_eq!( |
| out_val, |
| json!([{ |
| "name": label.name, |
| "cat": label.category, |
| "ph": "i", |
| "ts": point.ts / NANOS_PER_MICRO, |
| "pid": point.pid, |
| "tid": point.tid, |
| "scope": "g", |
| "args": { |
| "apples": 2, |
| "cost": 5.1, |
| "paid": true, |
| "invalid": false, |
| "special": "spicy", |
| } |
| }]) |
| ); |
| } |
| |
| #[test] |
| fn counter() { |
| let (t, out_file) = init_json_tracer(); |
| let label = Label::new("test", "duration"); |
| let instant = Point::from_timestamp(420000); |
| t.counter(label, instant, &[("blocks", 123), ("ducks", 456)]); |
| let out = read_out(&out_file); |
| println!("out = {}", out); |
| let out_val: Value = serde_json::from_str(&out).unwrap(); |
| assert_eq!( |
| out_val, |
| json!([{ |
| "name": label.name, |
| "cat": label.category, |
| "ph": "C", |
| "ts": instant.ts / NANOS_PER_MICRO, |
| "pid": instant.pid, |
| "tid": instant.tid, |
| "args": { |
| "blocks": 123, |
| "ducks": 456, |
| } |
| }]) |
| ); |
| } |
| } |