rs_tracing/
lib.rs

1//! rs_tracing is a crate that outputs trace events to a file in the [trace event format].
2//!
3//! This format is used by chrome://tracing the output can also be converted to html
4//! with [trace2html].
5//!
6//! If the feature rs_tracing is not set in the toml file the macros expand to nothing,
7//! with the exception of trace_expr that will still execute the expression,
8//! also all crate dependencies of rs_tracing will be removed.
9//!
10//! [trace2html]: https://github.com/catapult-project/catapult/blob/master/tracing/README.md
11//! [trace event format]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#
12//!
13
14#[cfg(feature = "rs_tracing")]
15extern crate serde;
16#[cfg(feature = "rs_tracing")]
17extern crate serde_json;
18#[doc(hidden)]
19#[cfg(feature = "rs_tracing")]
20pub use serde_json::{json, json_internal};
21
22#[doc(hidden)]
23pub use internal::*;
24
25/// Activate tracing
26///
27/// # Examples
28///
29/// ```
30/// # #[macro_use] extern crate rs_tracing;
31/// # fn main() {
32/// {
33/// trace_activate!();
34/// }
35/// # }
36/// ```
37#[macro_export]
38macro_rules! trace_activate {
39    () => {
40        trace_state_change!(&$crate::TraceState::Active)
41    };
42}
43
44/// Deactivate tracing
45///
46/// # Examples
47///
48/// ```
49/// # #[macro_use] extern crate rs_tracing;
50/// # fn main() {
51/// {
52/// trace_deactivate!();
53/// }
54/// # }
55/// ```
56#[macro_export]
57macro_rules! trace_deactivate {
58    () => {
59        trace_state_change!(&$crate::TraceState::InActive)
60    };
61}
62
63/// Activates trace and opens a new trace file with the name \<pid\>.trace in the dir specified.
64///
65/// # Examples
66///
67/// ```
68/// # #[macro_use] extern crate rs_tracing;
69/// # fn main() {
70/// {
71/// open_trace_file!("/tmp").unwrap();
72/// {
73///     trace_scoped!("event name");
74///     println!("this is timed");
75/// }
76/// close_trace_file!();
77/// }
78/// # }
79/// ```
80#[macro_export]
81macro_rules! open_trace_file {
82    ($dir:expr) => {
83        trace_to_file_internal!($dir)
84    };
85}
86
87/// closes trace file
88///
89/// note will not trace the trace_scoped end trace if called from the same scope.
90#[macro_export]
91macro_rules! close_trace_file {
92    () => {
93        close_trace_file_internal!()
94    };
95}
96
97/// Trace time used from invocation until end of current scope.
98///
99/// The event type is [Complete Event (X)] with start time and duration.
100///
101/// $name: name of the trace event.
102///
103/// $json: optional custom data formated as serdes [json] macro.
104///
105/// [Complete Event (X)]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.lpfof2aylapb
106/// [json]: https://docs.serde.rs/serde_json/macro.json.html
107/// # Examples
108///
109/// ```
110/// # #[macro_use] extern crate rs_tracing;
111/// # fn main() {
112/// {
113/// trace_scoped!("event name");
114/// println!("this is timed");
115/// }
116/// # }
117/// ```
118/// ```
119/// # #[macro_use] extern crate rs_tracing;
120/// # fn main() {
121/// {
122/// trace_scoped!("event name","custom":"data","u32":4);
123/// println!("this is timed");
124/// }
125/// # }
126/// ```
127#[macro_export]
128macro_rules! trace_scoped {
129    ($name: expr) => {
130        trace_scoped_internal!($name)
131    };
132    ($name: expr, $($json:tt)+) =>{
133        trace_scoped_internal!($name, $($json)+)
134    }
135}
136
137/// trace time used for expression to finish.
138///
139/// The event type is [Complete Event (X)] with start time and duration.
140///
141/// $name: name of the trace event.
142///
143/// $expr: expression to trace.
144///
145/// $json: optional custom data formated as serdes [json] macro.
146///
147/// [Complete Event (X)]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.lpfof2aylapb
148/// [json]: https://docs.serde.rs/serde_json/macro.json.html
149/// # Examples
150///
151/// ```
152/// # #[macro_use] extern crate rs_tracing;
153/// # fn main() {
154/// let result = trace_expr!("event name", { println!("this is timed"); true});
155/// assert!(result, "result wasn't true!");
156/// # }
157/// ```
158/// ```
159/// # #[macro_use] extern crate rs_tracing;
160/// # fn main() {
161/// let result = trace_expr!("event name",{ println!("this is timed"); true},"custom":"data","u32":4);
162/// assert!(result, "result wasn't true!");
163/// # }
164/// ```
165#[macro_export]
166macro_rules! trace_expr {
167    ($name: expr, $expr: expr) => {
168        trace_expr_internal!($name, $expr)
169    };
170    ($name: expr, $expr: expr, $($json:tt)+) =>{
171        trace_expr_internal!($name, $expr, $($json)+)
172    }
173}
174
175/// Mark beginning of event, needs to be followed by corresponding trace_end.
176///
177/// The event type is [Duration Event (B)] with an instant time.
178/// Start and end of the event must be on the same thread.
179/// If you provide custom data to both the trace_begin and trace_end then
180/// the arguments will be merged.
181///
182/// $name: name of the trace event.
183///
184/// $json: optional custom data formated as serdes [json] macro.
185///
186/// [Duration Event (B)]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.nso4gcezn7n1
187/// [json]: https://docs.serde.rs/serde_json/macro.json.html
188/// # Examples
189///
190/// ```
191/// # #[macro_use] extern crate rs_tracing;
192/// # fn main() {
193/// trace_begin!("event name");
194/// println!("this is timed");
195/// trace_end!("event name");
196/// # }
197/// ```
198/// ```
199/// # #[macro_use] extern crate rs_tracing;
200/// # fn main() {
201/// trace_begin!("event name","custom":"data");
202/// println!("this is timed");
203/// trace_end!("event name","u32":4);
204/// # }
205/// ```
206#[macro_export]
207macro_rules! trace_begin {
208    ($name: expr) => {
209        trace_duration_internal!($name, $crate::EventType::DurationBegin)
210    };
211    ($name: expr, $($json:tt)+) =>{
212        trace_duration_internal!($name, $crate::EventType::DurationBegin, $($json)+)
213    }
214}
215
216/// Mark end of event, needs to be proceeded by corresponding trace_begin.
217///
218/// The event type is [Duration Event (E)] with an instant time.
219/// Start and end of the event must be on the same thread.
220/// If you provide custom data to both the trace_begin and trace_end then
221/// the arguments will be merged.
222///
223/// $name: name of the trace event.
224///
225/// $json: optional custom data formated as serdes [json] macro.
226///
227/// [Duration Event (E)]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.nso4gcezn7n1
228/// [json]: https://docs.serde.rs/serde_json/macro.json.html
229/// # Examples
230///
231/// ```
232/// # #[macro_use] extern crate rs_tracing;
233/// # fn main() {
234/// trace_begin!("event name");
235/// println!("this is timed");
236/// trace_end!("event name");
237/// # }
238/// ```
239/// ```
240/// # #[macro_use] extern crate rs_tracing;
241/// # fn main() {
242/// trace_begin!("event name","custom":"data");
243/// println!("this is timed");
244/// trace_end!("event name","u32":4);
245/// # }
246/// ```
247#[macro_export]
248macro_rules! trace_end {
249    ($name: expr) => {
250        trace_duration_internal!($name, $crate::EventType::DurationEnd)
251    };
252    ($name: expr, $($json:tt)+) =>{
253        trace_duration_internal!($name, $crate::EventType::DurationEnd, $($json)+)
254    }
255}
256
257#[cfg(feature = "rs_tracing")]
258mod internal {
259
260    use serde::ser::{Serialize, SerializeStruct, Serializer};
261    use serde_json;
262    use std::fs::{DirBuilder, File};
263    use std::io::{self, BufWriter, Write};
264    use std::mem::transmute;
265    use std::path::{Path, PathBuf};
266    use std::process;
267    use std::sync::atomic::{AtomicBool, Ordering};
268    use std::sync::Mutex;
269    use std::thread::{self, ThreadId};
270    use std::time::SystemTime;
271
272    #[derive(PartialEq)]
273    pub enum TraceState {
274        InActive,
275        Active,
276    }
277
278    static mut TRACER: Mutex<Option<BufWriter<File>>> = Mutex::new(None);
279    static mut TRACE_ACTIVE: AtomicBool = AtomicBool::new(false);
280
281    pub fn trace(event: &TraceEvent) {
282        unsafe {
283            let mut tracer = TRACER.lock().unwrap();
284            if let Some(ref mut file) = *tracer {
285                serde_json::to_writer(&mut *file, event).unwrap();
286                file.write_all(b",\n").unwrap();
287            }
288        }
289    }
290
291    pub fn set_trace_state(state: &'static TraceState) {
292        unsafe {
293            TRACE_ACTIVE.store(*state == TraceState::Active, Ordering::SeqCst);
294        }
295    }
296
297    pub fn is_trace_active() -> bool {
298        unsafe { TRACE_ACTIVE.load(Ordering::SeqCst) }
299    }
300
301    #[doc(hidden)]
302    pub enum EventType {
303        DurationBegin,
304        DurationEnd,
305        Complete,
306    }
307
308    impl Serialize for EventType {
309        #[doc(hidden)]
310        fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
311        where
312            S: Serializer,
313        {
314            match *self {
315                EventType::DurationBegin => serializer.serialize_unit_variant("EventType", 0, "B"),
316                EventType::DurationEnd => serializer.serialize_unit_variant("EventType", 1, "E"),
317                EventType::Complete => serializer.serialize_unit_variant("EventType", 2, "X"),
318            }
319        }
320    }
321
322    #[doc(hidden)]
323    pub struct TraceEvent<'a> {
324        name: &'a str,
325        ph: EventType,
326        pub ts: u128,
327        pid: u32,
328        tid: u64,
329        pub dur: Option<u128>,
330        args: Option<serde_json::Value>,
331    }
332
333    impl<'a> Serialize for TraceEvent<'a> {
334        #[doc(hidden)]
335        fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
336        where
337            S: Serializer,
338        {
339            let mut event = serializer.serialize_struct("TraceEvent", 7)?;
340            event.serialize_field("name", &self.name)?;
341            event.serialize_field("ph", &self.ph)?;
342            event.serialize_field("ts", &self.ts)?;
343            event.serialize_field("pid", &self.pid)?;
344            event.serialize_field("tid", &self.tid)?;
345            if let Some(ref dur) = self.dur {
346                event.serialize_field("dur", &dur)?;
347            }
348            if let Some(ref args) = self.args {
349                event.serialize_field("args", &args)?;
350            }
351            event.end()
352        }
353    }
354
355    impl<'a> TraceEvent<'a> {
356        #[doc(hidden)]
357        pub fn new(name: &'a str, event_type: EventType, args: Option<serde_json::Value>) -> Self {
358            TraceEvent {
359                name,
360                ph: event_type,
361                ts: precise_time_microsec(),
362                pid: process::id(),
363                tid: unsafe {
364                    // only want an unique identifier per thread think this is ok.
365                    transmute::<ThreadId, u64>(thread::current().id())
366                },
367                dur: None,
368                args,
369            }
370        }
371    }
372
373    #[doc(hidden)]
374    pub struct EventGuard<'a> {
375        event: TraceEvent<'a>,
376    }
377
378    impl<'a> EventGuard<'a> {
379        #[doc(hidden)]
380        pub fn new(name: &'a str, args: Option<serde_json::Value>) -> EventGuard<'a> {
381            EventGuard {
382                event: TraceEvent::new(name, EventType::Complete, args),
383            }
384        }
385    }
386
387    impl<'a> Drop for EventGuard<'a> {
388        #[doc(hidden)]
389        fn drop(&mut self) {
390            self.event.dur = Some(precise_time_microsec().saturating_sub(self.event.ts));
391            trace(&self.event);
392        }
393    }
394
395    pub fn init_trace_to_file<P: AsRef<Path>>(dir: P) -> io::Result<()> {
396        let mut tracer = unsafe { TRACER.lock().unwrap() };
397        let mut dir_path = PathBuf::new();
398        dir_path.push(dir);
399        let mut file_path = dir_path.clone();
400        file_path.push(process::id().to_string());
401        file_path.set_extension("trace");
402        let file = DirBuilder::new()
403            .recursive(true)
404            .create(dir_path)
405            .and(File::create(file_path))?;
406        let mut writer = BufWriter::new(file);
407        writer.write_all(b"[")?;
408        *tracer = Some(writer);
409        set_trace_state(&TraceState::Active);
410        Ok(())
411    }
412
413    pub fn close_trace_file_fn() {
414        let mut tracer = unsafe { TRACER.lock().unwrap() };
415        if let Some(ref mut file) = *tracer {
416            (*file).flush().unwrap();
417        }
418        *tracer = None;
419    }
420
421    #[doc(hidden)]
422    pub fn precise_time_microsec() -> u128 {
423        SystemTime::now()
424            .duration_since(SystemTime::UNIX_EPOCH)
425            .expect("SystemTime is before UNIX EPOCH")
426            .as_micros()
427    }
428
429    #[doc(hidden)]
430    #[macro_export]
431    macro_rules! trace_state_change {
432        ($state:expr) => {
433            $crate::set_trace_state($state)
434        };
435    }
436
437    #[doc(hidden)]
438    #[macro_export]
439    macro_rules! trace_to_file_internal {
440        ($dir:expr) => {
441            $crate::init_trace_to_file($dir)
442        };
443    }
444
445    #[doc(hidden)]
446    #[macro_export]
447    macro_rules! close_trace_file_internal {
448        () => {
449            $crate::close_trace_file_fn();
450        };
451    }
452
453    #[doc(hidden)]
454    #[macro_export]
455    macro_rules! trace_scoped_internal {
456    ($name: expr) => {
457        let _guard = if $crate::is_trace_active() {
458            Some($crate::EventGuard::new($name, None))
459        }else{
460            None
461        };
462    };
463    ($name: expr, $($json:tt)+) =>{
464        let _guard = if $crate::is_trace_active() {
465            Some($crate::EventGuard::new($name, Some(json!({$($json)+}))))
466        }else{
467            None
468        };
469    }
470}
471
472    #[doc(hidden)]
473    #[macro_export]
474    macro_rules! trace_expr_internal {
475    ($name: expr, $expr: expr) => {
476        if $crate::is_trace_active() {
477            let mut event = $crate::TraceEvent::new($name, $crate::EventType::Complete, None);
478            let result = $expr;
479            event.dur = Some($crate::precise_time_microsec() - event.ts);
480            $crate::trace(&event);
481            result
482        }else{
483            $expr
484        }
485    };
486    ($name: expr, $expr: expr, $($json:tt)+) =>{
487        if $crate::is_trace_active() {
488            let mut event = $crate::TraceEvent::new($name, $crate::EventType::Complete, Some(json!({$($json)+})));
489            let result = $expr;
490            event.dur = Some($crate::precise_time_microsec() - event.ts);
491            $crate::trace(&event);
492            result
493        }else{
494            $expr
495        }
496    }
497}
498
499    #[doc(hidden)]
500    #[macro_export]
501    macro_rules! trace_duration_internal {
502    ($name: expr, $event_type: expr) => {
503        if $crate::is_trace_active() {
504            let event = $crate::TraceEvent::new($name, $event_type, None);
505            $crate::trace(&event);
506        }
507    };
508    ($name: expr, $event_type: expr, $($json:tt)+) =>{
509        if $crate::is_trace_active() {
510            let event = $crate::TraceEvent::new($name, $event_type, Some(json!({$($json)+})));
511            $crate::trace(&event);
512        }
513    }
514}
515} // mod internal
516
517#[cfg(not(feature = "rs_tracing"))]
518mod internal {
519    #[doc(hidden)]
520    #[macro_export]
521    macro_rules! trace_state_change {
522        ($state:expr) => {};
523    }
524
525    #[doc(hidden)]
526    #[macro_export]
527    macro_rules! trace_to_file_internal {
528        ($dir:expr) => {{
529            let result: std::io::Result<()> = Ok(());
530            result
531        }};
532    }
533
534    #[doc(hidden)]
535    #[macro_export]
536    macro_rules! close_trace_file_internal {
537        () => {};
538    }
539
540    #[doc(hidden)]
541    #[macro_export]
542    macro_rules! trace_scoped_internal {
543        ($($some:tt)+) => {};
544    }
545
546    #[doc(hidden)]
547    #[macro_export]
548    macro_rules! trace_expr_internal {
549        ($name:expr, $expr:expr) => {
550            $expr
551        };
552        ($name:expr, $expr:expr, $($json:tt)+) => {
553            $expr
554        };
555    }
556
557    #[doc(hidden)]
558    #[macro_export]
559    macro_rules! trace_duration_internal {
560        ($($some:tt)+) => {};
561    }
562} // mod internal
rs_tracing/lib.rs

rs_tracing/
lib.rs
