diff --git a/src/frames.rs b/src/frames.rs index eee9a3cd..acac2d1d 100644 --- a/src/frames.rs +++ b/src/frames.rs @@ -159,6 +159,17 @@ pub struct Frames { pub thread_id: u64, } +impl Frames { + /// Returns a thread identifier (name or ID) as a string. + pub fn thread_name_or_id(&self) -> String { + if !self.thread_name.is_empty() { + self.thread_name.clone() + } else { + format!("{:?}", self.thread_id) + } + } +} + impl From for Frames { fn from(frames: UnresolvedFrames) -> Self { let mut fs = Vec::new(); diff --git a/src/profiler.rs b/src/profiler.rs index 3f17b6c9..5901fc51 100644 --- a/src/profiler.rs +++ b/src/profiler.rs @@ -110,7 +110,6 @@ impl ProfilerGuardBuilder { timer: Some(Timer::new(self.frequency)), sample_rate: self.frequency, - start: std::time::SystemTime::now(), }), Err(err) => Err(err), } @@ -125,12 +124,11 @@ pub struct ProfilerGuard<'a> { timer: Option, sample_rate: c_int, - start: std::time::SystemTime, } fn trigger_lazy() { let _ = backtrace::Backtrace::new(); - let _ = PROFILER.read(); + drop(PROFILER.read()); } impl ProfilerGuard<'_> { @@ -144,8 +142,7 @@ impl ProfilerGuard<'_> { ReportBuilder::new( self.profiler, self.sample_rate, - self.start, - std::time::SystemTime::now(), + self.timer.as_ref().map(Timer::timing).unwrap_or_default(), ) } } diff --git a/src/report.rs b/src/report.rs index 16d200e2..ec153086 100644 --- a/src/report.rs +++ b/src/report.rs @@ -7,22 +7,27 @@ use parking_lot::RwLock; use crate::frames::{Frames, UnresolvedFrames}; use crate::profiler::Profiler; +use crate::timer::ReportTiming; use crate::{Error, Result}; /// The final presentation of a report which is actually an `HashMap` from `Frames` to isize (count). pub struct Report { - /// key is a backtrace captured by profiler and value is count of it. + /// Key is a backtrace captured by profiler and value is count of it. pub data: HashMap, pub sample_rate: libc::c_int, - pub start: std::time::SystemTime, - pub until: std::time::SystemTime, + + /// Collection frequency, start time, duration. + pub timing: ReportTiming, } /// The presentation of an unsymbolicated report which is actually an `HashMap` from `UnresolvedFrames` to isize (count). pub struct UnresolvedReport { /// key is a backtrace captured by profiler and value is count of it. pub data: HashMap, + + /// Collection frequency, start time, duration. + pub timing: ReportTiming, } /// A builder of `Report` and `UnresolvedReport`. It builds report from a running `Profiler`. @@ -31,10 +36,10 @@ pub struct ReportBuilder<'a> { profiler: &'a RwLock>, sample_rate: libc::c_int, - start: std::time::SystemTime, - until: std::time::SystemTime, + timing: ReportTiming, } +#[allow(clippy::non_send_fields_in_send_ty)] unsafe impl Send for ReportBuilder<'_> {} unsafe impl Sync for ReportBuilder<'_> {} unsafe impl Send for Report {} @@ -44,16 +49,13 @@ impl<'a> ReportBuilder<'a> { pub(crate) fn new( profiler: &'a RwLock>, sample_rate: libc::c_int, - start: std::time::SystemTime, - until: std::time::SystemTime, + timing: ReportTiming, ) -> Self { Self { frames_post_processor: None, profiler, - sample_rate, - start, - until, + timing, } } @@ -99,7 +101,10 @@ impl<'a> ReportBuilder<'a> { } }); - Ok(UnresolvedReport { data: hash_map }) + Ok(UnresolvedReport { + data: hash_map, + timing: self.timing.clone(), + }) } } } @@ -141,8 +146,7 @@ impl<'a> ReportBuilder<'a> { Ok(Report { data: hash_map, sample_rate: self.sample_rate, - start: self.start, - until: self.until, + timing: self.timing.clone(), }) } } @@ -221,14 +225,14 @@ mod pyroscope { // TODO: handle the error of this request let start: u64 = self - .start + .timing + .start_time .duration_since(std::time::UNIX_EPOCH) .unwrap() .as_secs(); let s_start = start - start.checked_rem(10).unwrap(); // This assumes that the interval between start and until doesn't // exceed 10s - // let until: u64 = self.until.duration_since(std::time::UNIX_EPOCH).unwrap().as_secs(); let s_until = s_start + 10; client @@ -275,11 +279,29 @@ mod flamegraph { where W: Write, { - if !self.data.is_empty() { - let mut buffer = Vec::new(); + let lines: Vec = self + .data + .iter() + .map(|(key, value)| { + let mut line = key.thread_name_or_id(); + line.push(';'); + + for frame in key.frames.iter().rev() { + for symbol in frame.iter().rev() { + line.push_str(&format!("{}", symbol)); + line.push(';'); + } + } + + line.pop().unwrap_or_default(); + line.push_str(&format!(" {}", value)); + + line + }) + .collect(); - self.fold(true, &mut buffer)?; - flamegraph::from_reader::<&[u8], _>(options, buffer.as_ref(), writer).unwrap(); + if !lines.is_empty() { + flamegraph::from_lines(options, lines.iter().map(|s| &**s), writer).unwrap(); // TODO: handle this error } @@ -293,23 +315,36 @@ mod protobuf { use super::*; use crate::protos; use std::collections::HashSet; + use std::time::SystemTime; + + const SAMPLES: &str = "samples"; + const COUNT: &str = "count"; + const CPU: &str = "cpu"; + const NANOSECONDS: &str = "nanoseconds"; + const THREAD: &str = "thread"; impl Report { - // `pprof` will generate google's pprof format report + /// `pprof` will generate google's pprof format report. pub fn pprof(&self) -> crate::Result { - let mut dudup_str = HashSet::new(); + let mut dedup_str = HashSet::new(); for key in self.data.iter().map(|(key, _)| key) { + dedup_str.insert(key.thread_name_or_id()); for frame in key.frames.iter() { for symbol in frame { - dudup_str.insert(symbol.name()); - dudup_str.insert(symbol.sys_name().into_owned()); - dudup_str.insert(symbol.filename().into_owned()); + dedup_str.insert(symbol.name()); + dedup_str.insert(symbol.sys_name().into_owned()); + dedup_str.insert(symbol.filename().into_owned()); } } } + dedup_str.insert(SAMPLES.into()); + dedup_str.insert(COUNT.into()); + dedup_str.insert(CPU.into()); + dedup_str.insert(NANOSECONDS.into()); + dedup_str.insert(THREAD.into()); // string table's first element must be an empty string let mut str_tbl = vec!["".to_owned()]; - str_tbl.extend(dudup_str.into_iter()); + str_tbl.extend(dedup_str.into_iter()); let mut strings = HashMap::new(); for (index, name) in str_tbl.iter().enumerate() { @@ -357,26 +392,44 @@ mod protobuf { locs.push(function_id); } } + let thread_name = protos::Label { + key: *strings.get(THREAD).unwrap() as i64, + str: *strings.get(&key.thread_name_or_id().as_str()).unwrap() as i64, + ..protos::Label::default() + }; let sample = protos::Sample { location_id: locs, - value: vec![*count as i64], - ..protos::Sample::default() + value: vec![ + *count as i64, + *count as i64 * 1_000_000_000 / self.timing.frequency as i64, + ], + label: vec![thread_name], }; samples.push(sample); } - let (type_idx, unit_idx) = (str_tbl.len(), str_tbl.len() + 1); - str_tbl.push("cpu".to_owned()); - str_tbl.push("count".to_owned()); - let sample_type = protos::ValueType { - r#type: type_idx as i64, - unit: unit_idx as i64, + let samples_value = protos::ValueType { + r#type: *strings.get(SAMPLES).unwrap() as i64, + unit: *strings.get(COUNT).unwrap() as i64, + }; + let time_value = protos::ValueType { + r#type: *strings.get(CPU).unwrap() as i64, + unit: *strings.get(NANOSECONDS).unwrap() as i64, }; let profile = protos::Profile { - sample_type: vec![sample_type], + sample_type: vec![samples_value, time_value.clone()], sample: samples, string_table: str_tbl, function: fn_tbl, location: loc_tbl, + time_nanos: self + .timing + .start_time + .duration_since(SystemTime::UNIX_EPOCH) + .unwrap_or_default() + .as_nanos() as i64, + duration_nanos: self.timing.duration.as_nanos() as i64, + period_type: Some(time_value), + period: 1_000_000_000 / self.timing.frequency as i64, ..protos::Profile::default() }; Ok(profile) diff --git a/src/timer.rs b/src/timer.rs index bd23d68f..a6bfa1fe 100644 --- a/src/timer.rs +++ b/src/timer.rs @@ -2,6 +2,7 @@ use std::os::raw::c_int; use std::ptr::null_mut; +use std::time::{Duration, Instant, SystemTime}; #[repr(C)] #[derive(Clone)] @@ -24,7 +25,9 @@ extern "C" { const ITIMER_PROF: c_int = 2; pub struct Timer { - _frequency: c_int, + pub frequency: c_int, + pub start_time: SystemTime, + pub start_instant: Instant, } impl Timer { @@ -48,7 +51,19 @@ impl Timer { }; Timer { - _frequency: frequency, + frequency, + start_time: SystemTime::now(), + start_instant: Instant::now(), + } + } + + /// Returns a `ReportTiming` struct having this timer's frequency and start + /// time; and the time elapsed since its creation as duration. + pub fn timing(&self) -> ReportTiming { + ReportTiming { + frequency: self.frequency, + start_time: self.start_time, + duration: self.start_instant.elapsed(), } } } @@ -72,3 +87,24 @@ impl Drop for Timer { }; } } + +/// Timing metadata for a collected report. +#[derive(Clone)] +pub struct ReportTiming { + /// Frequency at which samples were collected. + pub frequency: i32, + /// Collection start time. + pub start_time: SystemTime, + /// Collection duration. + pub duration: Duration, +} + +impl Default for ReportTiming { + fn default() -> Self { + Self { + frequency: 1, + start_time: SystemTime::UNIX_EPOCH, + duration: Default::default(), + } + } +}