Add TimingContext to measure execution time

Cargo.toml

@@ -36,6 +36,7 @@ documented = "0.9.2"
 dirs = "6.0.0"
 edit = "0.1.5"
 erased-serde = "0.4.10"
+context_manager = "0.1.3"
 
 [dev-dependencies]
 assert_cmd = "2.2.2"

src/lib.rs

@@ -42,6 +42,7 @@ pub mod region;
 pub mod settings;
 pub mod simulation;
 pub mod time_slice;
+pub mod timeit;
 pub mod units;
 
 #[cfg(test)]

src/simulation.rs

@@ -4,8 +4,10 @@ use crate::model::Model;
 use crate::output::DataWriter;
 use crate::process::ProcessMap;
 use crate::simulation::prices::{Prices, calculate_prices};
+use crate::timeit::TimingContext;
 use crate::units::Capacity;
 use anyhow::{Context, Result};
+use context_manager;
 use log::info;
 use std::path::Path;
 use std::rc::Rc;
@@ -158,6 +160,7 @@ pub fn run(model: &Model, output_path: &Path, debug_model: bool) -> Result<()> {
 }
 
 // Run dispatch to get flows and prices for a milestone year
+#[context_manager::wrap(TimingContext)]
 fn run_dispatch_for_year(
     model: &Model,
     assets: &[AssetRef],

src/simulation/investment.rs

@@ -8,8 +8,10 @@ use crate::output::DataWriter;
 use crate::region::RegionID;
 use crate::simulation::prices::Prices;
 use crate::time_slice::{TimeSliceID, TimeSliceInfo, TimeSliceLevel, TimeSliceSelection};
+use crate::timeit::TimingContext;
 use crate::units::{ActivityPerCapacity, Capacity, Dimensionless, Flow, FlowPerCapacity};
 use anyhow::{Result, ensure};
+use context_manager;
 use indexmap::IndexMap;
 use itertools::Itertools;
 use log::{debug, warn};
@@ -43,6 +45,7 @@ pub type AllDemandMap = IndexMap<(CommodityID, RegionID, TimeSliceID), Flow>;
 ///
 /// The assets selected (including retained commissioned assets) for the given planning `year` or an
 /// error.
+#[context_manager::wrap(TimingContext)]
 pub fn perform_agent_investment(
     model: &Model,
     year: u32,

src/timeit.rs

@@ -0,0 +1,26 @@
+//! Implement a context manager for timing the decorated function
+use context_manager::{CallerContext, SyncWrapContext};
+use log::info;
+use std::time::Instant;
+
+/// Context for time a function call
+pub struct TimingContext {
+    start: Instant,
+}
+
+impl<T> SyncWrapContext<T> for TimingContext {
+    fn new() -> Self {
+        Self {
+            start: Instant::now(),
+        }
+    }
+
+    fn after(self, caller_context: &CallerContext, _result: &T) {
+        let elapsed = self.start.elapsed();
+        info!(
+            "[Timer] '{}' completed in {:.3}ms",
+            caller_context.fn_name(),
+            elapsed.as_secs_f64() * 1000.0,
+        );
+    }
+}