Browse Source

Finish rest of crate?

master
Jens Pitkänen 2 years ago
parent
commit
cf0d2bb541
10 changed files with 484 additions and 255 deletions
  1. +15
    -0
      COPYING.md
  2. +6
    -2
      Cargo.toml
  3. +49
    -0
      README.md
  4. +13
    -24
      examples/main.rs
  5. +8
    -0
      src/disabled.rs
  6. +123
    -0
      src/format.rs
  7. +47
    -138
      src/formatter.rs
  8. +158
    -34
      src/lib.rs
  9. +57
    -57
      src/measurement.rs
  10. +8
    -0
      src/measurement_tracker.rs

+ 15
- 0
COPYING.md View File

@@ -0,0 +1,15 @@
ISC License

Copyright (c) 2018, Jens Pitkanen

Permission to use, copy, modify, and/or distribute this software for any
purpose with or without fee is hereby granted, provided that the above
copyright notice and this permission notice appear in all copies.

THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.

+ 6
- 2
Cargo.toml View File

@@ -1,7 +1,11 @@
[package]
name = "stprof"
name = "stperf"
version = "0.1.0"
authors = ["Jens Pitkanen <jens@neon.moe>"]

[dependencies]
lazy_static = "1.0"
lazy_static = "1.0"

[features]
default = []
disabled = []

+ 49
- 0
README.md View File

@@ -0,0 +1,49 @@
# stper
[![Crates.io](https://img.shields.io/crates/d/stperf.svg)](https://crates.io/crates/minreq)
[![Documentation](https://docs.rs/stperf/badge.svg)](https://docs.rs/minreq)
[![CI](https://img.shields.io/travis/neonmoe/stperf/0.1.0.svg)](https://travis-ci.org/neonmoe/minreq)

stpref (**s**ingle-**t**hreaded **prof**iler) is a very simple
profiling utility for single-threaded applications, inspired by
[`hprof`](https://crates.io/crates/hprof).

## Usage
Check out the [docs](https://docs.rs/stperf).

```rust
#[macro_use]
extern crate stperf;

fn main() {
use std::thread;
use std::time::Duration;

let process = || {
perf_measure!("processing");
thread::sleep(Duration::from_millis(100));
};

for _ in 0..2 {
perf_measure!("main");
for _ in 0..2 {
perf_measure!("inner operations");
process();
}
process();
}

stperf::print();
}
```

Will print out:

```
╶──┬╼ main - 100.0%, 300 ms/loop, 2 samples
├──┬╼ inner operations - 66.7%, 200 ms/loop, 4 samples
│ └───╼ processing - 100.0%, 200 ms/loop, 4 samples
└───╼ processing - 33.3%, 100 ms/loop, 2 samples
```

## License
This crate is distributed under the terms of the [ISC license](COPYING.md).

+ 13
- 24
examples/main.rs View File

@@ -1,34 +1,23 @@
#[macro_use]
extern crate stprof;
extern crate stperf;

fn main() {
use std::thread;
use std::time::Duration;

let process = || thread::sleep(Duration::from_millis(100));
for _ in 0..1 {
prof_measure!("main");
for _ in 0..1 {
prof_measure!("physics simulation");
for _ in 0..1 {
prof_measure!("moving things");
process();
}
for _ in 0..1 {
prof_measure!("resolving collisions");
process();
}
}
for _ in 0..1 {
prof_measure!("rendering");
let process = || {
perf_measure!("processing");
thread::sleep(Duration::from_millis(100));
};

for _ in 0..2 {
perf_measure!("main");
for _ in 0..2 {
perf_measure!("inner operations");
process();
}
process();
}
stprof::print();
// Prints out:
// ╶──┬╼ main - 100.0%, 300 ms/loop
// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
// │ ├─╼ moving things - 50.0%, 100 ms/loop
// │ └─╼ resolving collisions - 50.0%, 100 ms/loop
// └─╼ rendering - 33.3%, 100 ms/loop

stperf::print();
}

+ 8
- 0
src/disabled.rs View File

@@ -0,0 +1,8 @@
use format::*;

/// A print that actually does nothing. Exists for the `disabled`-feature.
pub fn print() {}
/// A print that actually does nothing. Exists for the `disabled`-feature.
pub fn print_with_format(format: FormattingOptions, decimals: u32) {}
/// A reset that actually does nothing. Exists for the `disabled`-feature.
pub fn reset() {}

+ 123
- 0
src/format.rs View File

@@ -0,0 +1,123 @@
//! Formats for making the formatted outputs (see
//! [`get_formatted_string`](../fn.get_formatted_string.html))

/// A very streamlined format. This is the default format.
///
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
/// │ ├───╼ moving things - 50.0%, 100 ms/loop
/// │ └───╼ resolving collisions - 50.0%, 100 ms/loop
/// └───╼ rendering - 33.3%, 100 ms/loop
/// ```
pub static STREAMLINED: FormattingOptions = FormattingOptions {
starting_branch: "╶",
continuing_branch: "│",
branching_branch: "├",
turning_branch: "└",
ending_branch: "───╼",
turning_ending_branch: "──┬╼",
};

/// Like `STREAMLINED` except with rounded corners.
///
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
/// │ ├───╼ moving things - 50.0%, 100 ms/loop
/// │ ╰───╼ resolving collisions - 50.0%, 100 ms/loop
/// ╰───╼ rendering - 33.3%, 100 ms/loop
/// ```
pub static STREAMLINED_ROUNDED: FormattingOptions = FormattingOptions {
starting_branch: "╶",
continuing_branch: "│",
branching_branch: "├",
turning_branch: "╰",
ending_branch: "───╼",
turning_ending_branch: "──┬╼",
};

/// A format made out of -'s and |'s. Very compatible with small charsets!
///
/// ```text
/// ----- main - 100.0%, 300 ms/loop
/// |---- physics simulation - 66.7%, 200 ms/loop
/// | |---- moving things - 50.0%, 100 ms/loop
/// | \---- resolving collisions - 50.0%, 100 ms/loop
/// \---- rendering - 33.3%, 100 ms/loop
/// ```
pub static COMPATIBLE: FormattingOptions = FormattingOptions {
starting_branch: "-",
continuing_branch: "|",
branching_branch: "|",
turning_branch: "\\",
ending_branch: "----",
turning_ending_branch: "----",
};

/// This format is for those who like their lines doubled.
///
/// ```text
/// ═══╦═ main - 100.0%, 300 ms/loop
/// ╠══╦═ physics simulation - 66.7%, 200 ms/loop
/// ║ ╠════ moving things - 50.0%, 100 ms/loop
/// ║ ╚════ resolving collisions - 50.0%, 100 ms/loop
/// ╚════ rendering - 33.3%, 100 ms/loop
/// ```
pub static DOUBLED: FormattingOptions = FormattingOptions {
starting_branch: "═",
continuing_branch: "║",
branching_branch: "╠",
turning_branch: "╚",
ending_branch: "════",
turning_ending_branch: "══╦═",
};

/// This format is for debugging the formatting functionality.
///
/// ```text
/// >,,,, main - 100.0%, 300 ms/loop
/// +,,,, physics simulation - 66.7%, 200 ms/loop
/// | +.... moving things - 50.0%, 100 ms/loop
/// | -.... resolving collisions - 50.0%, 100 ms/loop
/// -.... rendering - 33.3%, 100 ms/loop
/// ```
pub static DEBUGGING: FormattingOptions = FormattingOptions {
starting_branch: ">",
continuing_branch: "|",
branching_branch: "+",
turning_branch: "-",
ending_branch: "....",
turning_ending_branch: ",,,,",
};

/// Defines the parts which are used to print out the formatted
/// string.
///
/// See the [`format`](format/index.html) module for options. You
/// can make your own, if you can parse the sparse instructions
/// below.
///
/// # Reference print (see Fields)
/// ```text
/// >,,,, main - 100.0%, 300 ms/loop
/// +,,,, physics simulation - 66.7%, 200 ms/loop
/// | +.... moving things - 50.0%, 100 ms/loop
/// | -.... resolving collisions - 50.0%, 100 ms/loop
/// -.... rendering - 33.3%, 100 ms/loop
/// ```
#[derive(Clone, Copy)]
pub struct FormattingOptions {
/// See the reference-print, `starting_branch` is represented by ">"
pub starting_branch: &'static str,
/// See the reference-print, `continuing_branch` is represented by "|"
pub continuing_branch: &'static str,
/// See the reference-print, `branching_branch` is represented by "+"
pub branching_branch: &'static str,
/// See the reference-print, `turning_branch` is represented by "-"
pub turning_branch: &'static str,
/// See the reference-print, `ending_branch` is represented by "...."
pub ending_branch: &'static str,
/// See the reference-print, `turning_ending_branch` is represented by ",,,,"
pub turning_ending_branch: &'static str,
}

+ 47
- 138
src/formatter.rs View File

@@ -1,141 +1,47 @@
use measurement::{self, Measurement};
use format::{self, FormattingOptions};

/// Formats for making the formatted outputs (see
/// [`get_formatted_string`](fn.get_formatted_string.html))
pub mod format {
use super::FormattingOptions;

/// A very streamlined format. This is the default format.
///
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ inner thing - 66.7%, 200 ms/loop
/// │ ├─╼ innest thing a - 50.0%, 100 ms/loop
/// │ └─╼ innest thing b - 50.0%, 100 ms/loop
/// └─╼ inner thing 2 - 33.3%, 100 ms/loop
/// ```
pub static STREAMLINED: FormattingOptions = FormattingOptions {
starting_branch: "╶",
continuing_branch: "│",
branching_branch: "├",
turning_branch: "└",
ending_branch: "─╼",
turning_ending_branch: "──┬╼",
};

/// Like `STREAMLINED` except with rounded corners.
///
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ inner thing - 66.7%, 200 ms/loop
/// │ ├─╼ innest thing a - 50.0%, 100 ms/loop
/// │ ╰─╼ innest thing b - 50.0%, 100 ms/loop
/// ╰─╼ inner thing 2 - 33.3%, 100 ms/loop
/// ```
pub static STREAMLINED_ROUNDED: FormattingOptions = FormattingOptions {
starting_branch: "╶",
continuing_branch: "│",
branching_branch: "├",
turning_branch: "╰",
ending_branch: "─╼",
turning_ending_branch: "──┬╼",
};

/// A format made out of +'s, -'s and |'s. Very compatible with small charsets!
///
/// ```text
/// ---+- main - 100.0%, 300 ms/loop
/// +--+- inner thing - 66.7%, 200 ms/loop
/// | +-- innest thing a - 50.0%, 100 ms/loop
/// | +-- innest thing b - 50.0%, 100 ms/loop
/// +-- inner thing 2 - 33.3%, 100 ms/loop
/// ```
pub static COMPATIBLE: FormattingOptions = FormattingOptions {
starting_branch: "-",
continuing_branch: "|",
branching_branch: "+",
turning_branch: "+",
ending_branch: "--",
turning_ending_branch: "--+-",
};

/// This format is for those who like their lines doubled.
///
/// ```text
/// ═══╦═ main - 100.0%, 300 ms/loop
/// ╠══╦═ inner thing - 66.7%, 200 ms/loop
/// ║ ╠═══ innest thing a - 50.0%, 100 ms/loop
/// ║ ╚═══ innest thing b - 50.0%, 100 ms/loop
/// ╚═══ inner thing 2 - 33.3%, 100 ms/loop
/// ```
pub static DOUBLED: FormattingOptions = FormattingOptions {
starting_branch: "═",
continuing_branch: "║",
branching_branch: "╠",
turning_branch: "╚",
ending_branch: "═══",
turning_ending_branch: "══╦═",
};

/// This format is for debugging the formatting functionality.
///
/// ```text
/// >,,,, main - 100.0%, 300 ms/loop
/// +,,,, inner thing - 66.7%, 200 ms/loop
/// | +... innest thing a - 50.0%, 100 ms/loop
/// | -... innest thing b - 50.0%, 100 ms/loop
/// -... inner thing 2 - 33.3%, 100 ms/loop
/// ```
pub static DEBUGGING: FormattingOptions = FormattingOptions {
starting_branch: ">",
continuing_branch: "|",
branching_branch: "+",
turning_branch: "-",
ending_branch: "...",
turning_ending_branch: ",,,,",
};

}

/// Defines the parts which are used to print out the formatted string. See the [`format`](format/index.html) module for options. You can make your own, if you can parse the sparse instructions below.
/// Prints out the data gathered by the profiler. Uses
/// [`format::STREAMLINED`](format/static.STREAMLINED.html) as the
/// default format.
///
/// # Reference print (see Fields)
/// Prints out something like this:
/// ```text
/// >,,,, main - 100.0%, 300 ms/loop
/// +,,,, inner thing - 66.7%, 200 ms/loop
/// | +... innest thing a - 50.0%, 100 ms/loop
/// | -... innest thing b - 50.0%, 100 ms/loop
/// -... inner thing 2 - 33.3%, 100 ms/loop
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
/// │ ├───╼ moving things - 50.0%, 100 ms/loop
/// │ └───╼ resolving collisions - 50.0%, 100 ms/loop
/// └───╼ rendering - 33.3%, 100 ms/loop
/// ```
#[derive(Clone, Copy)]
pub struct FormattingOptions {
/// See the reference-print, `starting_branch` is represented by ">"
pub starting_branch: &'static str,
/// See the reference-print, `continuing_branch` is represented by "|"
pub continuing_branch: &'static str,
/// See the reference-print, `branching_branch` is represented by "+"
pub branching_branch: &'static str,
/// See the reference-print, `turning_branch` is represented by "-"
pub turning_branch: &'static str,
/// See the reference-print, `ending_branch` is represented by "..."
pub ending_branch: &'static str,
/// See the reference-print, `turning_ending_branch` is represented by ",,,,"
pub turning_ending_branch: &'static str,
}

/// Prints out the data gathered by the profiler. Uses
/// `FORMAT_STREAMLINED_ROUNDED` as the default format.
pub fn print() {
print_with_format(format::STREAMLINED, 0);
}

/// Prints out the data gathered by the profiler using a given format.
///
/// Prints out something like this:
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
/// │ ├───╼ moving things - 50.0%, 100 ms/loop
/// │ └───╼ resolving collisions - 50.0%, 100 ms/loop
/// └───╼ rendering - 33.3%, 100 ms/loop
/// ```
pub fn print_with_format(ops: FormattingOptions, decimals: usize) {
println!("{}", get_formatted_string(ops, decimals));
}

/// Returns what [`print`](fn.print.html) prints, if you want to put it somewhere else
/// than stdout.
///
/// Which is something like this:
/// ```text
/// ╶──┬╼ main - 100.0%, 300 ms/loop
/// ├──┬╼ physics simulation - 66.7%, 200 ms/loop
/// │ ├───╼ moving things - 50.0%, 100 ms/loop
/// │ └───╼ resolving collisions - 50.0%, 100 ms/loop
/// └───╼ rendering - 33.3%, 100 ms/loop
/// ```
pub fn get_formatted_string(ops: FormattingOptions, decimals: usize) -> String {
let mut result = String::new();
let children = measurement::get_measures();
@@ -164,7 +70,7 @@ pub fn get_formatted_string(ops: FormattingOptions, decimals: usize) -> String {
}
} else {
let width =
ops.ending_branch.chars().count() + ops.continuing_branch.chars().count();
ops.ending_branch.chars().count() - ops.continuing_branch.chars().count();
let mut branch_part = format!("{:width$}", "", width = width);

let generation = (measurement.depth - 1 - d) as u32;
@@ -211,12 +117,15 @@ pub fn get_formatted_string(ops: FormattingOptions, decimals: usize) -> String {
continue;
}

if let Some(duration) = measurement.get_avg_duration_ns() {
let branch = construct_tree_branch(&measurement);
let branch = construct_tree_branch(&measurement);
let info_line;
if let Some(duration) = measurement.get_duration_ns() {
let count = measurement.durations.len();

let parent_duration = if measurement.depth > 1 {
let parent = measurement.parent.unwrap();
let parent = parent.lock().unwrap();
match parent.get_avg_duration_ns() {
match parent.get_duration_ns() {
Some(duration) => duration, // Parent has duration, use it
None => duration, // Parent has no duration, use own
}
@@ -224,28 +133,28 @@ pub fn get_formatted_string(ops: FormattingOptions, decimals: usize) -> String {
duration // No parent, use own
};

let count = measurement.durations.len();
if measurement.depth == 1 {
main_count = count;
}

let info_line = &format!(
"{:5.1}%, {:width$.decimals$} ms/loop",
info_line = format!(
"{:5.1}%, {:width$.decimals$} ms/loop, {} samples",
100.0 * (duration as f64 / parent_duration as f64),
(duration * count as u32 / main_count as u32) as f64 / 1_000_000.0,
(duration / main_count as u64) as f64 / 1_000_000.0,
count,
width = decimals + 3,
decimals = decimals
);

result += &format!(
"{:max_width$} - {}\n",
branch,
info_line,
max_width = max_width
);
} else {
result += &format!(" {}\n", measurement.name);
info_line = String::from("no data");
}

result += &format!(
"{:max_width$} - {}\n",
branch,
info_line,
max_width = max_width
);
index += 1;
}
result


+ 158
- 34
src/lib.rs View File

@@ -1,61 +1,185 @@
//! # stprof
//! stprof (**s**ingle-**t**hreaded **prof**iler) is a very simple
//! profiling utility for single-threaded applications. Mostly
//! intended for games.
//! # stpref
//!
//! stpref (**s**ingle-**t**hreaded **prof**iler) is a very simple
//! profiling utility for single-threaded applications, inspired by
//! [`hprof`](https://crates.io/crates/hprof). Mostly intended for
//! games. Before using this crate, be sure to check the
//! [Warning](#warning) section.
//!
//! # Usage
//!
//! Using the crate consists of two parts: measuring and
//! analyzing.
//!
//! The measurement part consists of calling the `perf_measure!` macro
//! at the start of every code block we want to measure, and giving it
//! an identifiable name.
//!
//! ```no_run
//! # #[macro_use] extern crate stperf; fn main() {
//! let process = |n| std::thread::sleep(std::time::Duration::from_millis(n));
//!
//! perf_measure!("top level processing");
//! {
//! perf_measure!("light initial processing");
//! process(100);
//! }
//! for _ in 0..5 {
//! perf_measure!("heavy processing");
//! process(100); // "heavy processing"
//! }
//! # }
//! ```
//!
//! The analysis part starts with printing out the information in any
//! of the following ways.
//!
//! ```
//! # #[macro_use] extern crate stperf; fn main() {
//! // Simply print out the data with some sensible defaults for configuration.
//! stperf::print();
//!
//! // Print out the data, but configure the output. In this case, we
//! // use a different format, and specify that we want to see the
//! // timings with 3 decimals.
//! stperf::print_with_format(stperf::format::COMPATIBLE, 3);
//!
//! // Just get the formatted string like with print_with_format,
//! // except it's a String so you can print it out somewhere else than
//! // stdout(). (A GUI, for example.)
//! let s = stperf::get_formatted_string(stperf::format::STREAMLINED, 2);
//! # }
//! ```
//!
//! And then you get to ponder the deeper meaning of a graph like this:
//!
//! ```text
//! ╶──┬╼ top level processing - 100.0%, 600 ms/loop, 1 samples
//! ├───╼ light initial processing - 16.7%, 100 ms/loop, 1 samples
//! └───╼ heavy processing - 83.3%, 500 ms/loop, 5 samples
//! ```
//!
//! ## How to read the graph
//!
//! The graph will show scopes inside scopes in a tree-like
//! structure, with each indentation implying a deeper scope, and the
//! branches illustrating who is whose child and sibling.
//!
//! * The percents represent the fraction of the time the process took
//! from its parent's processing time.
//!
//! * The ms/loop represents the total time the process took to finish
//! inside the shallowest scope ("root scope"); the graph above shows
//! 500ms for "heavy processing" even though a single process took
//! 100ms, since it was ran 5 times inside "top level processing" (the
//! shallowest scope, or "root scope").
//!
//! * The samples show how many perf_measure!'s were ran for this row
//! of data.
//!
//! # Overhead
//!
//! The crate has a bit of performance overhead. Here's a few specific
//! causes, with performance measured on the machine this crate was
//! developed on (i7-6700k @ 4.1GHz):
//!
//! * The print/string formatting functions are quite heavy, as they go
//! through all the measurement data. One call measures at about 3.0ms
//! for 100k samples.
//!
//! * The [`perf_measure!`](macro.perf_measure.html) macro is pretty
//! light, but when used in large quantities, may be noticeable. One
//! call measures at about 200ns with a --release flag, 1µs
//! without. However, stprof can track its own overhead to a degree,
//! so the reported overhead is only about 50ns with --release, and
//! 360ns without.
//!
//! All this said, it's important to note: the most useful information
//! this profiler gives you is the percents, not the absolute timing
//! value.
//!
//! # Warning
//!
//! The crate accumulates a pretty large amount of data in a small
//! amount of time, if you're using it in a realtime application. A
//! recommended way of displaying and handling the measurement data is
//! as follows:
//! 1. Set an update interval, eg. 1 second.
//! 2. Every interval, print out the data (eg. `stperf::print()`), and
//! cleanup (`stperf::reset()`).
//! This way, you'll always have quite a few samples (1 second is a
//! long amount of time to gather data), and they'll be fresh. And
//! you'll avoid filling up your ram.
//!
//! # Examples
//! ```
//! # #[macro_use]
//! # extern crate stprof;
//! # fn main() {
//! # #[macro_use] extern crate stperf; fn main() {
//! use std::thread;
//! use std::time::Duration;
//!
//! // An arbitrary "do something" function
//! let process = || thread::sleep(Duration::from_millis(100));
//! for _ in 0..1 {
//! prof_measure!("main");
//! for _ in 0..1 {
//! prof_measure!("physics simulation");
//! for _ in 0..1 {
//! prof_measure!("moving things");
//! process();
//! }
//! for _ in 0..1 {
//! prof_measure!("resolving collisions");
//! process();
//! }
//! }
//! for _ in 0..1 {
//! prof_measure!("rendering");
//! let process = || {
//! perf_measure!("processing");
//! thread::sleep(Duration::from_millis(100));
//! };
//!
//! for _ in 0..2 {
//! perf_measure!("main");
//! for _ in 0..2 {
//! perf_measure!("inner operations");
//! process();
//! }
//! process();
//! }
//! stprof::print();
//!
//! stperf::print();
//! // Prints out:
//! // ╶──┬╼ main - 100.0%, 300 ms/loop
//! // ├──┬╼ physics simulation - 66.7%, 200 ms/loop
//! // │ ├─╼ moving things - 50.0%, 100 ms/loop
//! // │ └─╼ resolving collisions - 50.0%, 100 ms/loop
//! // └─╼ rendering - 33.3%, 100 ms/loop
//! // ╶──┬╼ main - 100.0%, 300 ms/loop, 2 samples
//! // ├──┬╼ inner operations - 66.7%, 200 ms/loop, 4 samples
//! // │ └───╼ processing - 100.0%, 200 ms/loop, 4 samples
//! // └───╼ processing - 33.3%, 100 ms/loop, 2 samples
//! # }
//! ```

#![deny(missing_docs)]

#[cfg(not(feature = "disabled"))]
#[macro_use]
extern crate lazy_static;

pub mod measurement;
pub mod format;
#[allow(dead_code, unused_variables)]
mod measurement_tracker;
pub use measurement_tracker::MeasurementTracker;

#[cfg(not(feature = "disabled"))]
mod measurement;
#[cfg(not(feature = "disabled"))]
pub use measurement::{measure, reset};
#[cfg(not(feature = "disabled"))]
mod formatter;
pub use formatter::*;
#[cfg(not(feature = "disabled"))]
pub use formatter::{get_formatted_string, print, print_with_format};

#[cfg(feature = "disabled")]
#[allow(dead_code, unused_variables)]
mod disabled;
#[cfg(feature = "disabled")]
pub use disabled::*;

/// Logs the time between this call and the end of the current scope.
#[cfg(not(feature = "disabled"))]
#[macro_export]
macro_rules! prof_measure {
macro_rules! perf_measure {
($s: expr) => {
use std::time::Instant;
#[allow(unused_variables)]
let measurement = stprof::measurement::measure($s);
let measurement = stperf::measure(Instant::now(), $s);
};
}

/// Logs the time between this call and the end of the current scope.
#[cfg(feature = "disabled")]
#[macro_export]
macro_rules! perf_measure {
($s: expr) => {};
}

+ 57
- 57
src/measurement.rs View File

@@ -3,14 +3,16 @@
use std::sync::{Arc, Mutex};
use std::time::{Duration, Instant};

use measurement_tracker::MeasurementTracker;

lazy_static! {
pub(crate) static ref MEASUREMENT_STACK: Mutex<Vec<Arc<Mutex<Measurement>>>> =
Mutex::new(vec![Measurement::new("root".to_string(), 0, None)]);
}

/// Starts a measurement in the current scope.
pub fn measure<T: Into<String>>(measurement_name: T) -> MeasurementTracker {
let now = Instant::now();
/// Starts a measurement in the current scope. **Don't use this, use
/// the [`perf_measure!`](macro.perf_measure.html) macro.**
pub fn measure<T: Into<String>>(now: Instant, measurement_name: T) -> MeasurementTracker {
let name = measurement_name.into();
let mut stack = MEASUREMENT_STACK.lock().unwrap();
let depth = stack.len();
@@ -26,7 +28,34 @@ pub fn measure<T: Into<String>>(measurement_name: T) -> MeasurementTracker {
parent.children_names.push(name);
}

MeasurementTracker { start_time: now }
MeasurementTracker {
start_time: now,
overhead: Instant::now() - now,
}
}

impl Drop for MeasurementTracker {
fn drop(&mut self) {
let latter_overhead_start = Instant::now();
let mut stack = MEASUREMENT_STACK.lock().unwrap();
let measurement = stack.pop().unwrap();
let mut measurement = measurement.lock().unwrap();
measurement.overhead += self.overhead;
measurement.durations.push(Instant::now() - self.start_time);
measurement.overhead += Instant::now() - latter_overhead_start;
}
}

/// Resets the measurement data.
///
/// Warning: This will wipe all measurements from the memory!
pub fn reset() {
let mut stack = MEASUREMENT_STACK.lock().unwrap();
stack.split_off(1);
let root = stack.get(0).unwrap();
let mut root = root.lock().unwrap();
root.children.clear();
root.children_names.clear();
}

/// Returns a `Vec` of all the
@@ -34,7 +63,7 @@ pub fn measure<T: Into<String>>(measurement_name: T) -> MeasurementTracker {
///
/// **Warning**: This function is pretty heavy, especially as the
/// amount of samples rises, as it clones every one of them.
pub fn get_measures() -> Vec<Measurement> {
pub(crate) fn get_measures() -> Vec<Measurement> {
let stack = MEASUREMENT_STACK.lock().unwrap();
let root = stack.get(0).unwrap().lock().unwrap();
root.collect_all_children()
@@ -42,9 +71,10 @@ pub fn get_measures() -> Vec<Measurement> {

/// Represents a scope's running time.
#[derive(Clone)]
pub struct Measurement {
pub(crate) struct Measurement {
pub(crate) name: String,
pub(crate) depth: usize,
pub(crate) overhead: Duration,
pub(crate) durations: Vec<Duration>,
pub(crate) parent: Option<Arc<Mutex<Measurement>>>,
children: Vec<Arc<Mutex<Measurement>>>,
@@ -60,6 +90,7 @@ impl Measurement {
Arc::new(Mutex::new(Measurement {
name,
depth,
overhead: Duration::new(0, 0),
durations: Vec::new(),
parent: parent.into(),
children: Vec::new(),
@@ -67,35 +98,6 @@ impl Measurement {
}))
}

/// Returns the name of the measurement (the string passed to the
/// `measure!` macro).
pub fn name(&self) -> &str {
&self.name
}

/// Returns the depth of the measurement. The first `measure!`
/// call will have a depth of 1, and each `measure!` inside
/// another `measure!` will increment the depth by 1. Consider
/// the following:
/// ```
/// #[macro_use]
/// extern crate stprof;
///
/// fn main() {
/// prof_measure!("main"); /* Depth == 1 */
/// { prof_measure!("inner"); } /* Depth == 2 */
/// { prof_measure!("another inner"); } /* Depth == 2 */
/// {
/// prof_measure!("third inner"); /* Depth == 2 */
/// { prof_measure!("even more inner"); } /* Depth == 3 */
/// }
/// { prof_measure!("last inner"); } /* Depth == 2 */
/// }
/// ```
pub fn depth(&self) -> usize {
self.depth
}

pub(crate) fn get_ancestor(&self, generation: u32) -> Option<Arc<Mutex<Measurement>>> {
if generation == 0 {
if let Some(ref parent) = self.parent {
@@ -143,17 +145,33 @@ impl Measurement {
collection
}

pub(crate) fn get_avg_duration_ns(&self) -> Option<u32> {
pub(crate) fn get_duration_ns(&self) -> Option<u64> {
let count = self.durations.len();
if count == 0 {
None
} else {
let mut total = 0;
let mut total: u64 = 0;
for duration in &self.durations {
total += duration.subsec_nanos();
total += duration.subsec_nanos() as u64;
}
if total < self.get_overhead_ns() {
// This should never happen, but technically it's possible.
Some(0)
} else {
Some(total - self.get_overhead_ns())
}
}
}

pub(crate) fn get_overhead_ns(&self) -> u64 {
let mut overhead =
self.overhead.as_secs() * 1_000_000_000 + self.overhead.subsec_nanos() as u64;
for child in &self.children {
if let Ok(child) = child.try_lock() {
overhead += child.get_overhead_ns();
}
Some(total / count as u32)
}
overhead
}

fn get_child(&mut self, name: &str) -> Option<Arc<Mutex<Measurement>>> {
@@ -163,26 +181,8 @@ impl Measurement {
if child_name == name {
drop(child_lock);
return Some(child.clone());
} else if let Some(result) = child_lock.get_child(name) {
drop(child_lock);
return Some(result);
}
}
None
}
}

/// Represents a started measurement. When dropped, it will log the
/// duration into memory.
pub struct MeasurementTracker {
start_time: Instant,
}

impl Drop for MeasurementTracker {
fn drop(&mut self) {
let mut stack = MEASUREMENT_STACK.lock().unwrap();
let measurement = stack.pop().unwrap();
let mut measurement = measurement.lock().unwrap();
measurement.durations.push(Instant::now() - self.start_time);
}
}

+ 8
- 0
src/measurement_tracker.rs View File

@@ -0,0 +1,8 @@
use std::time::{Duration, Instant};

/// Represents a started measurement. When dropped, it will log the
/// duration into memory.
pub struct MeasurementTracker {
pub(crate) start_time: Instant,
pub(crate) overhead: Duration,
}

Loading…
Cancel
Save