# Profi
A simple profiler for single and multithreaded applications.
Record the time it takes for a scope to end and print the timings when the program exits.
Each measurement has an overhead of ~25ns-50ns, so it shouldn't impact benchmarks.
Run the [benchmarks](https://github.com/LyonSyonII/profi/blob/main/profi/examples/benchmark.rs) example to see what's the overhead on your machine.
# Setup
`profi` is controlled by the `enable` feature, which is active by default.
When disabled, all macros and methods will become no-ops, resulting in zero impact on your code.
To disable it, add `default-features = false` to the `profi` dependency in your `Cargo.toml`.
For convenience, you can also add a custom feature:
```toml
[dependencies]
profi = { version = "*", default-features = false }
[features]
prof = ["profi/enable"]
```
And run it with `cargo run --release --features prof`
**If you use [`rayon`](https://crates.io/crates/rayon), enable the [`rayon` feature](#features)!**
# Usage
See the [`examples`](https://github.com/LyonSyonII/profi/tree/main/profi/examples) for more usage cases.
## Basic Usage
```rust
use profi::{prof, print_on_exit};
fn main() {
// Prints the timings to stdout when the program exits
// Always put at the top of the main function to ensure it's dropped last
//
// An implicit `main` guard is created to profile the whole application
print_on_exit!();
// Sleep for a bit to simulate some work
std::thread::sleep(std::time::Duration::from_millis(200));
}
```
```plaintext
┌──────────────┬────────────────────┬───────────┬──────────────┬───────┐
│ Name ┆ % Application Time ┆ Real Time ┆ Average time ┆ Calls │
╞══════════════╪════════════════════╪═══════════╪══════════════╪═══════╡
│ simple::main ┆ 100.00% ┆ 200.13ms ┆ - ┆ 1 │
└──────────────┴────────────────────┴───────────┴──────────────┴───────┘
```
## Loops
```rust
use profi::{prof, print_on_exit};
fn main() {
print_on_exit!();
for _ in 0..100 {
prof!(iteration);
std::thread::sleep(std::time::Duration::from_millis(10));
}
}
```
```plaintext
┌────────────┬────────────────────┬───────────┬──────────────┬───────┐
│ Name ┆ % Application Time ┆ Real Time ┆ Average time ┆ Calls │
╞════════════╪════════════════════╪═══════════╪══════════════╪═══════╡
│ loop::main ┆ 100.00% ┆ 1.01s ┆ - ┆ 1 │
├╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌┤
│ iteration ┆ 99.99% ┆ 1.01s ┆ 10.10ms/call ┆ 100 │
└────────────┴────────────────────┴───────────┴──────────────┴───────┘
```
## Multiple threads
```rust
use profi::{print_on_exit, prof_guard};
fn do_work(i: usize) {
// Need to bind it to a variable to ensure it isn't dropped before sleeping
let _guard = if i < 6 {
prof_guard!("6 first")
} else {
prof_guard!("4 last")
};
std::thread::sleep(std::time::Duration::from_millis(10));
// The guard goes out of scope here
}
fn main() {
print_on_exit!();
// Spawn 10 threads
std::thread::scope(|s| {
for i in 0..10 {
s.spawn(move || {
do_work(i);
});
}
});
}
```
```plaintext
┌───────────────┬────────────────────┬───────────┬────────────┬──────────┬──────────────┬───────┐
│ Name ┆ % Application Time ┆ Real Time ┆ % CPU Time ┆ CPU Time ┆ Average time ┆ Calls │
╞═══════════════╪════════════════════╪═══════════╪════════════╪══════════╪══════════════╪═══════╡
│ threads::main ┆ 100.00% ┆ 10.48ms ┆ 9.43% ┆ 10.48ms ┆ - ┆ 1 │
├╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌┤
│ 6 first ┆ 96.42% ┆ 10.11ms ┆ 54.38% ┆ 60.44ms ┆ 10.08ms/call ┆ 6 │
├╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌╌╌╌╌╌╌╌┼╌╌╌╌╌╌╌┤
│ 4 last ┆ 95.93% ┆ 10.06ms ┆ 36.19% ┆ 40.22ms ┆ 10.06ms/call ┆ 4 │
└───────────────┴────────────────────┴───────────┴────────────┴──────────┴──────────────┴───────┘
```
"CPU Time" is the combined time all threads have spent on that scope.
For example, "6 first" has a "CPU Time" of 60 milliseconds because each thread waits 10ms, and the program spawns six of them.
## Attribute
Enable the `attributes` feature to use the `profile` attribute on functions.
This will add a guard at the start of the function.
```ignore
use profi::profile;
#[profile]
fn anotated() { /* ... */ }
```
# Features
| `enable` | Activates the profiling, if not active all macros become no-ops |
| `attributes` | Enables the `#[prof]` macro |
| `deep-hierarchy` | By default `profi` merges all uses of a function, use this feature to disable this behaviour.<br/>See the [`nested` example for more information](https://github.com/LyonSyonII/profi/tree/main/profi/examples) |
| `nightly` | Enables nightly-only optimizations (unused at the moment) |
| `rayon` | Necessary if using [`rayon`](https://crates.io/crates/rayon) |