pounce_common/
timing.rs

1//! Per-task timing accumulator.
2//!
3//! Mirrors `Common/IpTimedTask.hpp` (`Common/IpDebug.{hpp,cpp}` is
4//! omitted — debug tracing is replaced by the journalist).
5
6use crate::types::Number;
7use crate::utils::{cpu_time, sys_time, wallclock_time};
8use std::cell::Cell;
9
10/// Equivalent to `Ipopt::TimedTask`. Use [`TimedTask::start`] /
11/// [`TimedTask::end`] around a section to accumulate cpu/system/wall
12/// time. [`TimedTask::end_if_started`] is the exception-safe variant.
13#[derive(Debug)]
14pub struct TimedTask {
15    enabled: Cell<bool>,
16    start_called: Cell<bool>,
17    end_called: Cell<bool>,
18    start_cpu: Cell<Number>,
19    start_sys: Cell<Number>,
20    start_wall: Cell<Number>,
21    total_cpu: Cell<Number>,
22    total_sys: Cell<Number>,
23    total_wall: Cell<Number>,
24}
25
26impl Default for TimedTask {
27    fn default() -> Self {
28        Self {
29            enabled: Cell::new(true),
30            start_called: Cell::new(false),
31            end_called: Cell::new(true),
32            start_cpu: Cell::new(0.0),
33            start_sys: Cell::new(0.0),
34            start_wall: Cell::new(0.0),
35            total_cpu: Cell::new(0.0),
36            total_sys: Cell::new(0.0),
37            total_wall: Cell::new(0.0),
38        }
39    }
40}
41
42impl TimedTask {
43    pub fn new() -> Self {
44        Self::default()
45    }
46
47    pub fn enable(&self) {
48        self.enabled.set(true);
49    }
50    pub fn disable(&self) {
51        self.enabled.set(false);
52    }
53    pub fn is_enabled(&self) -> bool {
54        self.enabled.get()
55    }
56    pub fn is_started(&self) -> bool {
57        self.start_called.get()
58    }
59
60    pub fn reset(&self) {
61        self.total_cpu.set(0.0);
62        self.total_sys.set(0.0);
63        self.total_wall.set(0.0);
64        self.start_called.set(false);
65        self.end_called.set(true);
66    }
67
68    pub fn start(&self) {
69        if !self.enabled.get() {
70            return;
71        }
72        self.end_called.set(false);
73        self.start_called.set(true);
74        self.start_cpu.set(cpu_time());
75        self.start_sys.set(sys_time());
76        self.start_wall.set(wallclock_time());
77    }
78
79    pub fn end(&self) {
80        if !self.enabled.get() {
81            return;
82        }
83        self.end_called.set(true);
84        self.start_called.set(false);
85        self.total_cpu
86            .set(self.total_cpu.get() + cpu_time() - self.start_cpu.get());
87        self.total_sys
88            .set(self.total_sys.get() + sys_time() - self.start_sys.get());
89        self.total_wall
90            .set(self.total_wall.get() + wallclock_time() - self.start_wall.get());
91    }
92
93    pub fn end_if_started(&self) {
94        if !self.enabled.get() {
95            return;
96        }
97        if self.start_called.get() {
98            self.end();
99        }
100    }
101
102    pub fn total_cpu_time(&self) -> Number {
103        self.total_cpu.get()
104    }
105    pub fn total_sys_time(&self) -> Number {
106        self.total_sys.get()
107    }
108    pub fn total_wallclock_time(&self) -> Number {
109        self.total_wall.get()
110    }
111
112    /// Running wallclock seconds since `start()` plus accumulated total
113    /// from prior start/end cycles. When the task is not currently
114    /// started this is the same as [`Self::total_wallclock_time`].
115    /// Used by `OptErrorConvCheck` to gate `max_wall_time` mid-solve
116    /// without forcing a `start()`/`end()` round-trip every iter.
117    pub fn live_wallclock_time(&self) -> Number {
118        if self.enabled.get() && self.start_called.get() {
119            self.total_wall.get() + wallclock_time() - self.start_wall.get()
120        } else {
121            self.total_wall.get()
122        }
123    }
124
125    /// Live counterpart of [`Self::total_cpu_time`]; see
126    /// [`Self::live_wallclock_time`] for the contract.
127    pub fn live_cpu_time(&self) -> Number {
128        if self.enabled.get() && self.start_called.get() {
129            self.total_cpu.get() + cpu_time() - self.start_cpu.get()
130        } else {
131            self.total_cpu.get()
132        }
133    }
134
135    /// RAII-style guard: start the timer immediately, end it when the
136    /// returned value is dropped (or when [`TimedGuard::stop`] is
137    /// called). Survives early returns / `?` in the caller scope.
138    pub fn guard(&self) -> TimedGuard<'_> {
139        self.start();
140        TimedGuard { task: Some(self) }
141    }
142}
143
144/// Drop-on-end guard returned by [`TimedTask::guard`]. Calls
145/// [`TimedTask::end_if_started`] in its destructor so a function with
146/// many exit paths can wrap a section with a single line.
147#[must_use = "the guard ends the timer when dropped; bind it to a variable"]
148pub struct TimedGuard<'a> {
149    task: Option<&'a TimedTask>,
150}
151
152impl<'a> TimedGuard<'a> {
153    /// End the timer immediately. Useful when you want to stop timing
154    /// before the natural scope exit (e.g. before a long-running
155    /// follow-up that should not be attributed to this section).
156    pub fn stop(mut self) {
157        if let Some(t) = self.task.take() {
158            t.end_if_started();
159        }
160    }
161}
162
163impl<'a> Drop for TimedGuard<'a> {
164    fn drop(&mut self) {
165        if let Some(t) = self.task.take() {
166            t.end_if_started();
167        }
168    }
169}
170
171/// Aggregate of per-subsystem [`TimedTask`] counters. Mirrors
172/// `Algorithm/IpTimingStatistics.{hpp,cpp}`. Owned by `IpoptApplication`
173/// and shared (via `Rc`) with the algorithm, NLP, and KKT solver so each
174/// subsystem can bump its own field. Reported at the end of a solve
175/// when `print_timing_statistics yes`.
176#[derive(Debug, Default)]
177pub struct TimingStatistics {
178    pub overall_alg: TimedTask,
179    pub print_problem_statistics: TimedTask,
180    pub initialize_iterates: TimedTask,
181    pub update_hessian: TimedTask,
182    pub output_iteration: TimedTask,
183    pub update_barrier_parameter: TimedTask,
184    pub compute_search_direction: TimedTask,
185    pub compute_acceptable_trial_point: TimedTask,
186    pub accept_trial_point: TimedTask,
187    pub check_convergence: TimedTask,
188
189    pub linear_system_factorization: TimedTask,
190    pub linear_system_back_solve: TimedTask,
191    pub linear_system_structure_converter: TimedTask,
192    pub linear_system_structure_converter_init: TimedTask,
193    pub quality_function_search: TimedTask,
194    pub total_callback_time: TimedTask,
195    pub total_function_evaluation_time: TimedTask,
196    pub eval_obj: TimedTask,
197    pub eval_grad_obj: TimedTask,
198    pub eval_constr: TimedTask,
199    pub eval_constr_jac: TimedTask,
200    pub eval_lag_hess: TimedTask,
201}
202
203impl TimingStatistics {
204    pub fn new() -> Self {
205        Self::default()
206    }
207
208    /// Format a per-subsystem timing report (wall-clock seconds, mirroring
209    /// upstream `IpoptApplication`'s end-of-run "Timing Statistics" block
210    /// but with sys/cpu columns omitted — pounce only tracks wall time).
211    /// Lines are indented to reflect the upstream visual nesting
212    /// (OverallAlgorithm → its phases; TotalFunctionEvaluations → its
213    /// per-callback breakdown). Returns a multi-line string ending in a
214    /// trailing newline so callers can `print!` it directly.
215    pub fn report(&self) -> String {
216        use std::fmt::Write as _;
217        let mut s = String::new();
218        let row = |s: &mut String, label: &str, t: &TimedTask| {
219            let _ = writeln!(
220                s,
221                "{label:<42} {wall:>10.3}s",
222                wall = t.total_wallclock_time()
223            );
224        };
225        s.push_str("\nTiming Statistics:\n");
226        row(
227            &mut s,
228            "OverallAlgorithm....................:",
229            &self.overall_alg,
230        );
231        row(
232            &mut s,
233            " InitializeIterates.................:",
234            &self.initialize_iterates,
235        );
236        row(
237            &mut s,
238            " UpdateHessian......................:",
239            &self.update_hessian,
240        );
241        row(
242            &mut s,
243            " OutputIteration....................:",
244            &self.output_iteration,
245        );
246        row(
247            &mut s,
248            " UpdateBarrierParameter.............:",
249            &self.update_barrier_parameter,
250        );
251        row(
252            &mut s,
253            " ComputeSearchDirection.............:",
254            &self.compute_search_direction,
255        );
256        row(
257            &mut s,
258            " ComputeAcceptableTrialPoint........:",
259            &self.compute_acceptable_trial_point,
260        );
261        row(
262            &mut s,
263            " AcceptTrialPoint...................:",
264            &self.accept_trial_point,
265        );
266        row(
267            &mut s,
268            " CheckConvergence...................:",
269            &self.check_convergence,
270        );
271        row(
272            &mut s,
273            "LinearSystemFactorization...........:",
274            &self.linear_system_factorization,
275        );
276        row(
277            &mut s,
278            "LinearSystemBackSolve...............:",
279            &self.linear_system_back_solve,
280        );
281        row(
282            &mut s,
283            "QualityFunctionSearch...............:",
284            &self.quality_function_search,
285        );
286        row(
287            &mut s,
288            "TotalFunctionEvaluations............:",
289            &self.total_function_evaluation_time,
290        );
291        row(
292            &mut s,
293            " ObjectiveFunctionEvaluations.......:",
294            &self.eval_obj,
295        );
296        row(
297            &mut s,
298            " ObjectiveGradientEvaluations.......:",
299            &self.eval_grad_obj,
300        );
301        row(
302            &mut s,
303            " ConstraintEvaluations..............:",
304            &self.eval_constr,
305        );
306        row(
307            &mut s,
308            " ConstraintJacobianEvaluations......:",
309            &self.eval_constr_jac,
310        );
311        row(
312            &mut s,
313            " LagrangianHessianEvaluations.......:",
314            &self.eval_lag_hess,
315        );
316        s
317    }
318
319    /// Reset all counters. Mirrors upstream `ResetTimes()`.
320    pub fn reset(&self) {
321        self.overall_alg.reset();
322        self.print_problem_statistics.reset();
323        self.initialize_iterates.reset();
324        self.update_hessian.reset();
325        self.output_iteration.reset();
326        self.update_barrier_parameter.reset();
327        self.compute_search_direction.reset();
328        self.compute_acceptable_trial_point.reset();
329        self.accept_trial_point.reset();
330        self.check_convergence.reset();
331        self.linear_system_factorization.reset();
332        self.linear_system_back_solve.reset();
333        self.linear_system_structure_converter.reset();
334        self.linear_system_structure_converter_init.reset();
335        self.quality_function_search.reset();
336        self.total_callback_time.reset();
337        self.total_function_evaluation_time.reset();
338        self.eval_obj.reset();
339        self.eval_grad_obj.reset();
340        self.eval_constr.reset();
341        self.eval_constr_jac.reset();
342        self.eval_lag_hess.reset();
343    }
344}
345
346#[cfg(test)]
347mod tests {
348    use super::*;
349
350    #[test]
351    fn start_end_accumulates_nonneg() {
352        let t = TimedTask::new();
353        t.start();
354        for _ in 0..1000 {
355            std::hint::black_box(0u64);
356        }
357        t.end();
358        assert!(t.total_wallclock_time() >= 0.0);
359    }
360
361    #[test]
362    fn disabled_is_noop() {
363        let t = TimedTask::new();
364        t.disable();
365        t.start();
366        t.end();
367        assert_eq!(t.total_wallclock_time(), 0.0);
368    }
369
370    #[test]
371    fn end_if_started_handles_unstarted() {
372        let t = TimedTask::new();
373        t.end_if_started();
374        assert_eq!(t.total_wallclock_time(), 0.0);
375    }
376}
pounce_common/timing.rs

pounce_common/
timing.rs
