Skip to main content

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, RefCell};
9use std::rc::Rc;
10
11/// Which time budget a [`Deadline`] check found crossed.
12#[derive(Debug, Clone, Copy, PartialEq, Eq)]
13pub enum DeadlineKind {
14    /// Wall-clock budget (`max_wall_time`) exceeded.
15    Wall,
16    /// CPU-time budget (`max_cpu_time`) exceeded.
17    Cpu,
18}
19
20/// A monotonic wall/CPU-clock deadline for a single solve (pounce#242).
21///
22/// Cheaply clonable (`Rc`-backed) so the outer loop, the KKT solver, the
23/// line search, and the *restoration inner IPM* can all check the same
24/// global budget — not just the outer-iteration convergence check. The
25/// motivating bug: `max_wall_time` was only tested between outer
26/// iterations (in `OptErrorConvCheck`), so a solve whose per-iteration
27/// cost is dominated by a single expensive step — a slow KKT
28/// factorization, or a restoration sub-solve that runs an entire nested
29/// IPM under one outer "iteration" — overshot the requested budget by up
30/// to a full iteration (~7x on the reported 1611-variable NLP). Checking
31/// this deadline at the granularity of the expensive inner steps bounds
32/// the overshoot to roughly one such step.
33///
34/// The elapsed time is measured from the instant the `Deadline` is
35/// constructed, using the same process clocks the timing subsystem uses.
36/// Unlike [`TimedTask::live_wallclock_time`] it does **not** depend on a
37/// `start()`/`end()` cycle, so it works inside the nested restoration
38/// solve — whose fresh [`TimingStatistics`] has an `overall_alg` timer
39/// that is never started, which is exactly why the inner loop used to run
40/// unbounded by wall time.
41#[derive(Debug, Clone)]
42pub struct Deadline {
43    inner: Rc<DeadlineInner>,
44}
45
46#[derive(Debug)]
47struct DeadlineInner {
48    wall_start: Number,
49    cpu_start: Number,
50    max_wall: Number,
51    max_cpu: Number,
52}
53
54impl Deadline {
55    /// Create a deadline that fires once `max_wall` wall seconds or
56    /// `max_cpu` CPU seconds have elapsed from *now*. The pounce defaults
57    /// for both budgets are `1e6`, i.e. effectively unbounded; a caller
58    /// that passes those gets a deadline that never trips in practice.
59    pub fn new(max_wall: Number, max_cpu: Number) -> Self {
60        Self {
61            inner: Rc::new(DeadlineInner {
62                wall_start: wallclock_time(),
63                cpu_start: cpu_time(),
64                max_wall,
65                max_cpu,
66            }),
67        }
68    }
69
70    /// Return `Some(kind)` if either budget has been crossed, else
71    /// `None`. CPU is tested before wall to match the branch order of
72    /// upstream `OptimalityErrorConvergenceCheck::CheckConvergence` (and
73    /// pounce's `OptErrorConvCheck`), so a solve that trips both in the
74    /// same check reports `MaximumCpuTimeExceeded` identically to the
75    /// coarse path.
76    pub fn exceeded(&self) -> Option<DeadlineKind> {
77        if cpu_time() - self.inner.cpu_start >= self.inner.max_cpu {
78            return Some(DeadlineKind::Cpu);
79        }
80        if wallclock_time() - self.inner.wall_start >= self.inner.max_wall {
81            return Some(DeadlineKind::Wall);
82        }
83        None
84    }
85
86    /// The wall-clock budget this deadline was built with.
87    pub fn max_wall(&self) -> Number {
88        self.inner.max_wall
89    }
90
91    /// The CPU-time budget this deadline was built with.
92    pub fn max_cpu(&self) -> Number {
93        self.inner.max_cpu
94    }
95
96    /// Wall-clock seconds remaining before the wall budget trips.
97    /// Negative once the budget is already crossed. Unlike
98    /// [`Self::exceeded`] this exposes *how much* budget is left, which
99    /// the KKT solver's predictive time guard (pounce#254) compares
100    /// against the observed cost of one factorization to decide whether
101    /// starting another would overshoot.
102    pub fn remaining_wall(&self) -> Number {
103        self.inner.max_wall - (wallclock_time() - self.inner.wall_start)
104    }
105
106    /// CPU-time counterpart of [`Self::remaining_wall`].
107    pub fn remaining_cpu(&self) -> Number {
108        self.inner.max_cpu - (cpu_time() - self.inner.cpu_start)
109    }
110}
111
112/// Equivalent to `Ipopt::TimedTask`. Use [`TimedTask::start`] /
113/// [`TimedTask::end`] around a section to accumulate cpu/system/wall
114/// time. [`TimedTask::end_if_started`] is the exception-safe variant.
115#[derive(Debug)]
116pub struct TimedTask {
117    enabled: Cell<bool>,
118    start_called: Cell<bool>,
119    end_called: Cell<bool>,
120    start_cpu: Cell<Number>,
121    start_sys: Cell<Number>,
122    start_wall: Cell<Number>,
123    total_cpu: Cell<Number>,
124    total_sys: Cell<Number>,
125    total_wall: Cell<Number>,
126}
127
128impl Default for TimedTask {
129    fn default() -> Self {
130        Self {
131            enabled: Cell::new(true),
132            start_called: Cell::new(false),
133            end_called: Cell::new(true),
134            start_cpu: Cell::new(0.0),
135            start_sys: Cell::new(0.0),
136            start_wall: Cell::new(0.0),
137            total_cpu: Cell::new(0.0),
138            total_sys: Cell::new(0.0),
139            total_wall: Cell::new(0.0),
140        }
141    }
142}
143
144impl TimedTask {
145    pub fn new() -> Self {
146        Self::default()
147    }
148
149    pub fn enable(&self) {
150        self.enabled.set(true);
151    }
152    pub fn disable(&self) {
153        self.enabled.set(false);
154    }
155    pub fn is_enabled(&self) -> bool {
156        self.enabled.get()
157    }
158    pub fn is_started(&self) -> bool {
159        self.start_called.get()
160    }
161
162    pub fn reset(&self) {
163        self.total_cpu.set(0.0);
164        self.total_sys.set(0.0);
165        self.total_wall.set(0.0);
166        self.start_called.set(false);
167        self.end_called.set(true);
168    }
169
170    pub fn start(&self) {
171        if !self.enabled.get() {
172            return;
173        }
174        self.end_called.set(false);
175        self.start_called.set(true);
176        self.start_cpu.set(cpu_time());
177        self.start_sys.set(sys_time());
178        self.start_wall.set(wallclock_time());
179    }
180
181    pub fn end(&self) {
182        if !self.enabled.get() {
183            return;
184        }
185        self.end_called.set(true);
186        self.start_called.set(false);
187        self.total_cpu
188            .set(self.total_cpu.get() + cpu_time() - self.start_cpu.get());
189        self.total_sys
190            .set(self.total_sys.get() + sys_time() - self.start_sys.get());
191        self.total_wall
192            .set(self.total_wall.get() + wallclock_time() - self.start_wall.get());
193    }
194
195    pub fn end_if_started(&self) {
196        if !self.enabled.get() {
197            return;
198        }
199        if self.start_called.get() {
200            self.end();
201        }
202    }
203
204    pub fn total_cpu_time(&self) -> Number {
205        self.total_cpu.get()
206    }
207    pub fn total_sys_time(&self) -> Number {
208        self.total_sys.get()
209    }
210    pub fn total_wallclock_time(&self) -> Number {
211        self.total_wall.get()
212    }
213
214    /// Running wallclock seconds since `start()` plus accumulated total
215    /// from prior start/end cycles. When the task is not currently
216    /// started this is the same as [`Self::total_wallclock_time`].
217    /// Used by `OptErrorConvCheck` to gate `max_wall_time` mid-solve
218    /// without forcing a `start()`/`end()` round-trip every iter.
219    pub fn live_wallclock_time(&self) -> Number {
220        if self.enabled.get() && self.start_called.get() {
221            self.total_wall.get() + wallclock_time() - self.start_wall.get()
222        } else {
223            self.total_wall.get()
224        }
225    }
226
227    /// Live counterpart of [`Self::total_cpu_time`]; see
228    /// [`Self::live_wallclock_time`] for the contract.
229    pub fn live_cpu_time(&self) -> Number {
230        if self.enabled.get() && self.start_called.get() {
231            self.total_cpu.get() + cpu_time() - self.start_cpu.get()
232        } else {
233            self.total_cpu.get()
234        }
235    }
236
237    /// RAII-style guard: start the timer immediately, end it when the
238    /// returned value is dropped (or when [`TimedGuard::stop`] is
239    /// called). Survives early returns / `?` in the caller scope.
240    pub fn guard(&self) -> TimedGuard<'_> {
241        self.start();
242        TimedGuard { task: Some(self) }
243    }
244}
245
246/// Drop-on-end guard returned by [`TimedTask::guard`]. Calls
247/// [`TimedTask::end_if_started`] in its destructor so a function with
248/// many exit paths can wrap a section with a single line.
249#[must_use = "the guard ends the timer when dropped; bind it to a variable"]
250pub struct TimedGuard<'a> {
251    task: Option<&'a TimedTask>,
252}
253
254impl<'a> TimedGuard<'a> {
255    /// End the timer immediately. Useful when you want to stop timing
256    /// before the natural scope exit (e.g. before a long-running
257    /// follow-up that should not be attributed to this section).
258    pub fn stop(mut self) {
259        if let Some(t) = self.task.take() {
260            t.end_if_started();
261        }
262    }
263}
264
265impl<'a> Drop for TimedGuard<'a> {
266    fn drop(&mut self) {
267        if let Some(t) = self.task.take() {
268            t.end_if_started();
269        }
270    }
271}
272
273/// Aggregate of per-subsystem [`TimedTask`] counters. Mirrors
274/// `Algorithm/IpTimingStatistics.{hpp,cpp}`. Owned by `IpoptApplication`
275/// and shared (via `Rc`) with the algorithm, NLP, and KKT solver so each
276/// subsystem can bump its own field. Reported at the end of a solve
277/// when `print_timing_statistics yes`.
278#[derive(Debug, Default)]
279pub struct TimingStatistics {
280    pub overall_alg: TimedTask,
281    pub print_problem_statistics: TimedTask,
282    pub initialize_iterates: TimedTask,
283    pub update_hessian: TimedTask,
284    pub output_iteration: TimedTask,
285    pub update_barrier_parameter: TimedTask,
286    pub compute_search_direction: TimedTask,
287    pub compute_acceptable_trial_point: TimedTask,
288    pub accept_trial_point: TimedTask,
289    pub check_convergence: TimedTask,
290    /// The per-iteration intermediate-callback fire, including the
291    /// convergence quantities `build_iter_stats` pulls to populate it.
292    /// Those pulls are lazy, so on a problem whose gradient is expensive
293    /// this is where that evaluation actually lands — upstream reaches
294    /// the same quantities from `CheckConvergence` and reports the cost
295    /// there instead. Without a guard here the phase rows do not cover
296    /// the run and the report cannot attribute a solve (gh#698).
297    pub fire_intermediate: TimedTask,
298
299    pub linear_system_symbolic_factorization: TimedTask,
300    pub linear_system_factorization: TimedTask,
301    pub linear_system_back_solve: TimedTask,
302    pub quality_function_search: TimedTask,
303    pub total_callback_time: TimedTask,
304    pub total_function_evaluation_time: TimedTask,
305    pub eval_obj: TimedTask,
306    pub eval_grad_obj: TimedTask,
307    pub eval_constr: TimedTask,
308    pub eval_constr_jac: TimedTask,
309    pub eval_lag_hess: TimedTask,
310}
311
312impl TimingStatistics {
313    pub fn new() -> Self {
314        Self::default()
315    }
316
317    /// Format a per-subsystem timing report (wall-clock seconds, mirroring
318    /// upstream `IpoptApplication`'s end-of-run "Timing Statistics" block
319    /// but with sys/cpu columns omitted — pounce only tracks wall time).
320    /// Lines are indented to reflect the upstream visual nesting
321    /// (OverallAlgorithm → its phases; TotalFunctionEvaluations → its
322    /// per-callback breakdown). Returns a multi-line string ending in a
323    /// trailing newline so callers can `print!` it directly.
324    pub fn report(&self) -> String {
325        use std::fmt::Write as _;
326        let mut s = String::new();
327        let row = |s: &mut String, label: &str, t: &TimedTask| {
328            let _ = writeln!(
329                s,
330                "{label:<42} {wall:>10.3}s",
331                wall = t.total_wallclock_time()
332            );
333        };
334        s.push_str("\nTiming Statistics:\n");
335        row(
336            &mut s,
337            "OverallAlgorithm....................:",
338            &self.overall_alg,
339        );
340        row(
341            &mut s,
342            " InitializeIterates.................:",
343            &self.initialize_iterates,
344        );
345        row(
346            &mut s,
347            " UpdateHessian......................:",
348            &self.update_hessian,
349        );
350        row(
351            &mut s,
352            " OutputIteration....................:",
353            &self.output_iteration,
354        );
355        row(
356            &mut s,
357            " UpdateBarrierParameter.............:",
358            &self.update_barrier_parameter,
359        );
360        row(
361            &mut s,
362            " ComputeSearchDirection.............:",
363            &self.compute_search_direction,
364        );
365        row(
366            &mut s,
367            " ComputeAcceptableTrialPoint........:",
368            &self.compute_acceptable_trial_point,
369        );
370        row(
371            &mut s,
372            " AcceptTrialPoint...................:",
373            &self.accept_trial_point,
374        );
375        row(
376            &mut s,
377            " CheckConvergence...................:",
378            &self.check_convergence,
379        );
380        row(
381            &mut s,
382            " FireIntermediateCallback...........:",
383            &self.fire_intermediate,
384        );
385        row(
386            &mut s,
387            "LinearSystemSymbolicFactorization...:",
388            &self.linear_system_symbolic_factorization,
389        );
390        row(
391            &mut s,
392            "LinearSystemFactorization...........:",
393            &self.linear_system_factorization,
394        );
395        row(
396            &mut s,
397            "LinearSystemBackSolve...............:",
398            &self.linear_system_back_solve,
399        );
400        row(
401            &mut s,
402            "QualityFunctionSearch...............:",
403            &self.quality_function_search,
404        );
405        row(
406            &mut s,
407            "TotalFunctionEvaluations............:",
408            &self.total_function_evaluation_time,
409        );
410        row(
411            &mut s,
412            " ObjectiveFunctionEvaluations.......:",
413            &self.eval_obj,
414        );
415        row(
416            &mut s,
417            " ObjectiveGradientEvaluations.......:",
418            &self.eval_grad_obj,
419        );
420        row(
421            &mut s,
422            " ConstraintEvaluations..............:",
423            &self.eval_constr,
424        );
425        row(
426            &mut s,
427            " ConstraintJacobianEvaluations......:",
428            &self.eval_constr_jac,
429        );
430        row(
431            &mut s,
432            " LagrangianHessianEvaluations.......:",
433            &self.eval_lag_hess,
434        );
435        s
436    }
437
438    /// Structured wall-clock breakdown (seconds) of the major solve
439    /// subsystems, as ordered `(label, seconds)` pairs. Same numbers
440    /// [`Self::report`] prints, but as data rather than formatted text,
441    /// so a programmatic consumer (e.g. the Python `Problem.solve` `info`
442    /// dict) can attribute a solve's runtime without scraping the report
443    /// or patching the solver.
444    ///
445    /// Ordered coarse→fine: the overall algorithm total; the
446    /// linear-algebra split (`linear_system_total` = symbolic
447    /// factorization + numeric factorization + back-solve, with each
448    /// part broken out alongside it); and the per-callback
449    /// function-evaluation split (objective / gradient / constraints /
450    /// Jacobian / Lagrangian Hessian). This is exactly the func /
451    /// Jacobian / Hessian time split issue #180 needs to reproduce a
452    /// Table-6-style "where did the time go" analysis for a
453    /// reduced-space / variable-aggregation solve.
454    pub fn wall_time_breakdown(&self) -> Vec<(&'static str, Number)> {
455        let symbolic = self
456            .linear_system_symbolic_factorization
457            .total_wallclock_time();
458        let factorization = self.linear_system_factorization.total_wallclock_time();
459        let back_solve = self.linear_system_back_solve.total_wallclock_time();
460        vec![
461            ("overall_alg", self.overall_alg.total_wallclock_time()),
462            ("update_hessian", self.update_hessian.total_wallclock_time()),
463            (
464                "compute_search_direction",
465                self.compute_search_direction.total_wallclock_time(),
466            ),
467            ("linear_system_total", symbolic + factorization + back_solve),
468            ("linear_system_symbolic_factorization", symbolic),
469            ("linear_system_factorization", factorization),
470            ("linear_system_back_solve", back_solve),
471            (
472                "function_evaluations_total",
473                self.total_function_evaluation_time.total_wallclock_time(),
474            ),
475            ("eval_objective", self.eval_obj.total_wallclock_time()),
476            ("eval_gradient", self.eval_grad_obj.total_wallclock_time()),
477            ("eval_constraints", self.eval_constr.total_wallclock_time()),
478            (
479                "eval_constraint_jacobian",
480                self.eval_constr_jac.total_wallclock_time(),
481            ),
482            (
483                "eval_lagrangian_hessian",
484                self.eval_lag_hess.total_wallclock_time(),
485            ),
486            (
487                "total_callback",
488                self.total_callback_time.total_wallclock_time(),
489            ),
490            (
491                "fire_intermediate",
492                self.fire_intermediate.total_wallclock_time(),
493            ),
494        ]
495    }
496
497    /// Enable or disable the *detailed* per-subsystem timers, mirroring
498    /// upstream Ipopt's `timing_statistics` gating (`IpoptApplication`
499    /// only measures the detailed function/phase timers when
500    /// `timing_statistics=yes`). When `on` is `false` every `start()` /
501    /// `end()` on these tasks becomes a no-op, so a fast-objective solve
502    /// stops paying two `getrusage` syscalls per timed section (issue
503    /// #190).
504    ///
505    /// [`Self::overall_alg`] is deliberately left untouched: its
506    /// `live_cpu_time()` feeds the `max_cpu_time` convergence check and
507    /// its total is reported regardless of the option — upstream's help
508    /// text is explicit that "the overall algorithm time is unaffected by
509    /// this option". Callers that need the detailed
510    /// [`Self::wall_time_breakdown`] populated (the Python `info["timing"]`
511    /// dict, the CLI `timing.json`) must therefore set `timing_statistics`
512    /// (or `print_timing_statistics`, which implies it) to `yes`.
513    pub fn set_detailed_enabled(&self, on: bool) {
514        let set = |t: &TimedTask| {
515            if on {
516                t.enable();
517            } else {
518                t.disable();
519            }
520        };
521        // Every field except `overall_alg`.
522        set(&self.print_problem_statistics);
523        set(&self.initialize_iterates);
524        set(&self.update_hessian);
525        set(&self.output_iteration);
526        set(&self.update_barrier_parameter);
527        set(&self.compute_search_direction);
528        set(&self.compute_acceptable_trial_point);
529        set(&self.accept_trial_point);
530        set(&self.check_convergence);
531        set(&self.fire_intermediate);
532        set(&self.linear_system_symbolic_factorization);
533        set(&self.linear_system_factorization);
534        set(&self.linear_system_back_solve);
535        set(&self.quality_function_search);
536        set(&self.total_callback_time);
537        set(&self.total_function_evaluation_time);
538        set(&self.eval_obj);
539        set(&self.eval_grad_obj);
540        set(&self.eval_constr);
541        set(&self.eval_constr_jac);
542        set(&self.eval_lag_hess);
543    }
544
545    /// Reset all counters. Mirrors upstream `ResetTimes()`.
546    pub fn reset(&self) {
547        self.overall_alg.reset();
548        self.print_problem_statistics.reset();
549        self.initialize_iterates.reset();
550        self.update_hessian.reset();
551        self.output_iteration.reset();
552        self.update_barrier_parameter.reset();
553        self.compute_search_direction.reset();
554        self.compute_acceptable_trial_point.reset();
555        self.accept_trial_point.reset();
556        self.check_convergence.reset();
557        self.fire_intermediate.reset();
558        self.linear_system_symbolic_factorization.reset();
559        self.linear_system_factorization.reset();
560        self.linear_system_back_solve.reset();
561        self.quality_function_search.reset();
562        self.total_callback_time.reset();
563        self.total_function_evaluation_time.reset();
564        self.eval_obj.reset();
565        self.eval_grad_obj.reset();
566        self.eval_constr.reset();
567        self.eval_constr_jac.reset();
568        self.eval_lag_hess.reset();
569    }
570}
571
572/// Which linear-system phase a [`ConvexTimingStatistics`] row is charging.
573/// Named after the rows [`TimingStatistics::report`] already prints, so a
574/// tool that attributes cost by phase reads one vocabulary across both
575/// solver paths.
576#[derive(Debug, Clone, Copy, PartialEq, Eq)]
577pub enum LinearSystemPhase {
578    /// Pattern analysis / ordering (`Factorization::new`'s structure pass).
579    SymbolicFactorization,
580    /// Numeric factorization of the KKT matrix.
581    Factorization,
582    /// Triangular back-substitution against an existing factor.
583    BackSolve,
584}
585
586/// Wall-clock phase accumulator for the dedicated convex (LP / QP / conic)
587/// path, the counterpart of [`TimingStatistics`] for a solve that has no
588/// callbacks, no Hessian updates and no filter line search to attribute time
589/// to.
590///
591/// gh #767: `print_timing_statistics=yes` was accepted on the convex path,
592/// reported `(used)` by `print_user_options`, and emitted nothing — so a tool
593/// attributing cost by phase read 0% everywhere on a convex-routed instance,
594/// which is indistinguishable from "already fast" rather than "not measured".
595/// A 9.8 s `bearing_400` printed no timer at all.
596///
597/// The rows this reports are the phases the convex path actually has. Four of
598/// them — `OverallAlgorithm` and the three `LinearSystem*` rows — carry the
599/// *same* labels [`TimingStatistics::report`] prints, because they are the
600/// same quantities; the rest are named for the convex driver's own stages
601/// rather than reusing NLP row names that would always read zero.
602#[derive(Debug, Default)]
603pub struct ConvexTimingStatistics {
604    /// The whole convex driver: extraction through solution recovery.
605    /// Reported regardless of the detailed-timer switch, matching
606    /// [`TimingStatistics::overall_alg`].
607    pub overall_alg: TimedTask,
608    /// Reading the `.nl` model into the standard-form convex problem.
609    pub extraction: TimedTask,
610    /// Convex presolve plus the matching postsolve lift.
611    pub presolve: TimedTask,
612    /// The engine call itself (interior-point or active-set iterations).
613    pub solve: TimedTask,
614    /// Recovering per-constraint duals and bound multipliers in the
615    /// original model's ordering.
616    pub solution_recovery: TimedTask,
617
618    pub linear_system_symbolic_factorization: TimedTask,
619    pub linear_system_factorization: TimedTask,
620    pub linear_system_back_solve: TimedTask,
621}
622
623impl ConvexTimingStatistics {
624    pub fn new() -> Self {
625        Self::default()
626    }
627
628    /// Format the per-phase report, in the row layout
629    /// [`TimingStatistics::report`] uses (label padded to 42 columns, wall
630    /// seconds right-aligned). Returns a multi-line string ending in a
631    /// trailing newline so callers can `print!` it directly.
632    pub fn report(&self) -> String {
633        use std::fmt::Write as _;
634        let mut s = String::new();
635        let row = |s: &mut String, label: &str, t: &TimedTask| {
636            let _ = writeln!(
637                s,
638                "{label:<42} {wall:>10.3}s",
639                wall = t.total_wallclock_time()
640            );
641        };
642        s.push_str("\nTiming Statistics:\n");
643        row(
644            &mut s,
645            "OverallAlgorithm....................:",
646            &self.overall_alg,
647        );
648        row(
649            &mut s,
650            " ProblemExtraction..................:",
651            &self.extraction,
652        );
653        row(
654            &mut s,
655            " Presolve...........................:",
656            &self.presolve,
657        );
658        row(&mut s, " ConvexSolve........................:", &self.solve);
659        row(
660            &mut s,
661            " SolutionRecovery...................:",
662            &self.solution_recovery,
663        );
664        row(
665            &mut s,
666            "LinearSystemSymbolicFactorization...:",
667            &self.linear_system_symbolic_factorization,
668        );
669        row(
670            &mut s,
671            "LinearSystemFactorization...........:",
672            &self.linear_system_factorization,
673        );
674        row(
675            &mut s,
676            "LinearSystemBackSolve...............:",
677            &self.linear_system_back_solve,
678        );
679        s
680    }
681
682    /// Enable or disable the *detailed* per-phase timers, mirroring
683    /// [`TimingStatistics::set_detailed_enabled`] and therefore upstream
684    /// Ipopt's `timing_statistics` gating: with the option off, every
685    /// `start()` / `end()` on these tasks is a no-op and the solve pays no
686    /// clock syscalls for them.
687    ///
688    /// [`Self::overall_alg`] is deliberately left enabled, for the same
689    /// reason it is on the NLP path — upstream's help text is explicit that
690    /// the overall algorithm time is unaffected by this option.
691    pub fn set_detailed_enabled(&self, on: bool) {
692        let set = |t: &TimedTask| {
693            if on {
694                t.enable();
695            } else {
696                t.disable();
697            }
698        };
699        set(&self.extraction);
700        set(&self.presolve);
701        set(&self.solve);
702        set(&self.solution_recovery);
703        set(&self.linear_system_symbolic_factorization);
704        set(&self.linear_system_factorization);
705        set(&self.linear_system_back_solve);
706    }
707
708    fn phase(&self, phase: LinearSystemPhase) -> &TimedTask {
709        match phase {
710            LinearSystemPhase::SymbolicFactorization => &self.linear_system_symbolic_factorization,
711            LinearSystemPhase::Factorization => &self.linear_system_factorization,
712            LinearSystemPhase::BackSolve => &self.linear_system_back_solve,
713        }
714    }
715}
716
717thread_local! {
718    /// The convex-path sink, when a [`ConvexTimingScope`] is open.
719    /// Thread-local rather than threaded through the drivers because the
720    /// factorization and back-solve rows are charged from inside
721    /// `pounce-linsol`, several crates below the driver that wants them —
722    /// the same reason `pounce-convex`'s solve deadline is thread-local.
723    static CONVEX_TIMING: RefCell<Option<Rc<ConvexTimingStatistics>>> =
724        const { RefCell::new(None) };
725}
726
727/// RAII installation of a convex-path timing sink: [`ConvexTimingScope::open`]
728/// makes `stats` the active sink, and dropping the returned guard restores
729/// whatever was installed before it.
730///
731/// A guard rather than a `with(…, closure)` wrapper because the driver that
732/// opens the scope is a long function with several early returns, and each of
733/// those must still restore the previous sink.
734///
735/// The tasks inside `stats` carry their own enabled flag, so a solve that was
736/// not asked for timing statistics pays one thread-local read per
737/// [`time_linear_system`] call and no clock syscalls at all.
738///
739/// Thread-local means exactly that: work a scope-holding thread hands to
740/// worker threads (`pounce_convex::solve_qp_batch_parallel`) is not charged,
741/// because those threads have no scope. The convex CLI driver — the only
742/// caller that opens one — solves on the thread that opened it.
743#[must_use = "the scope ends when the guard is dropped; bind it to a variable"]
744pub struct ConvexTimingScope {
745    previous: Option<Rc<ConvexTimingStatistics>>,
746}
747
748impl ConvexTimingScope {
749    pub fn open(stats: &Rc<ConvexTimingStatistics>) -> Self {
750        let previous = CONVEX_TIMING.with(|slot| slot.borrow_mut().replace(Rc::clone(stats)));
751        Self { previous }
752    }
753}
754
755impl Drop for ConvexTimingScope {
756    fn drop(&mut self) {
757        CONVEX_TIMING.with(|slot| *slot.borrow_mut() = self.previous.take());
758    }
759}
760
761/// Charge the wall time `f` takes against `phase` of the active convex-path
762/// sink. A no-op wrapper when no [`ConvexTimingScope`] is open.
763///
764/// Phases never nest (a factorization does not run inside a back-solve), so
765/// the guard cannot clobber an outer start on the same task.
766pub fn time_linear_system<T>(phase: LinearSystemPhase, f: impl FnOnce() -> T) -> T {
767    let Some(stats) = CONVEX_TIMING.with(|slot| slot.borrow().clone()) else {
768        return f();
769    };
770    let task = stats.phase(phase);
771    let _guard = task.guard();
772    f()
773}
774
775#[cfg(test)]
776mod tests {
777    use super::*;
778
779    #[test]
780    fn deadline_unbounded_never_trips() {
781        // The pounce "no budget" defaults (1e6 seconds each) must never
782        // fire in any realistic test runtime.
783        let d = Deadline::new(1e6, 1e6);
784        assert!(d.exceeded().is_none());
785        assert_eq!(d.max_wall(), 1e6);
786        assert_eq!(d.max_cpu(), 1e6);
787    }
788
789    #[test]
790    fn deadline_zero_wall_trips_wall() {
791        // Zero wall budget, effectively-unbounded CPU budget: after any
792        // wall time elapses the check reports `Wall` (CPU is tested first
793        // but its budget is not crossed).
794        let d = Deadline::new(0.0, 1e6);
795        // Busy-spin until the monotonic wall clock has advanced past the
796        // start instant, so the assertion is not racing a zero-duration
797        // `elapsed()` on a coarse clock.
798        for _ in 0..10_000 {
799            if d.exceeded().is_some() {
800                break;
801            }
802            std::hint::black_box(0u64);
803        }
804        assert_eq!(d.exceeded(), Some(DeadlineKind::Wall));
805    }
806
807    #[test]
808    fn deadline_zero_cpu_takes_priority() {
809        // Both budgets at zero: CPU is checked first, so a solve that
810        // crosses both in the same check reports `Cpu` — matching the
811        // convergence check's branch order.
812        let d = Deadline::new(0.0, 0.0);
813        for _ in 0..10_000 {
814            if d.exceeded().is_some() {
815                break;
816            }
817            std::hint::black_box(0u64);
818        }
819        assert_eq!(d.exceeded(), Some(DeadlineKind::Cpu));
820    }
821
822    #[test]
823    fn deadline_remaining_reports_budget_left() {
824        // A large budget leaves ~the whole budget remaining right after
825        // construction (a hair less, since a moment has elapsed), and it
826        // is strictly positive.
827        let d = Deadline::new(1e6, 1e6);
828        let rw = d.remaining_wall();
829        let rc = d.remaining_cpu();
830        assert!(rw > 0.0 && rw <= 1e6, "remaining_wall out of range: {rw}");
831        assert!(rc > 0.0 && rc <= 1e6, "remaining_cpu out of range: {rc}");
832    }
833
834    #[test]
835    fn deadline_remaining_goes_nonpositive_once_crossed() {
836        // A zero wall budget is crossed after any elapsed time, so the
837        // remaining wall budget must be <= 0 (mirrors `exceeded`).
838        let d = Deadline::new(0.0, 1e6);
839        for _ in 0..10_000 {
840            if d.exceeded().is_some() {
841                break;
842            }
843            std::hint::black_box(0u64);
844        }
845        assert!(
846            d.remaining_wall() <= 0.0,
847            "remaining_wall should be non-positive once the budget is crossed"
848        );
849    }
850
851    #[test]
852    fn deadline_is_cheaply_clonable_and_shares_start() {
853        // Cloning shares the same start instant / budgets (the restoration
854        // inner IPM relies on this to be bounded by the outer solve's
855        // elapsed time, not its own).
856        let d = Deadline::new(1e6, 1e6);
857        let d2 = d.clone();
858        assert_eq!(d2.max_wall(), d.max_wall());
859        assert_eq!(d2.max_cpu(), d.max_cpu());
860        assert!(d2.exceeded().is_none());
861    }
862
863    #[test]
864    fn start_end_accumulates_nonneg() {
865        let t = TimedTask::new();
866        t.start();
867        for _ in 0..1000 {
868            std::hint::black_box(0u64);
869        }
870        t.end();
871        assert!(t.total_wallclock_time() >= 0.0);
872    }
873
874    #[test]
875    fn disabled_is_noop() {
876        let t = TimedTask::new();
877        t.disable();
878        t.start();
879        t.end();
880        assert_eq!(t.total_wallclock_time(), 0.0);
881    }
882
883    #[test]
884    fn set_detailed_enabled_gates_all_but_overall_alg() {
885        let stats = TimingStatistics::new();
886        // Default: every timer enabled.
887        assert!(stats.overall_alg.is_enabled());
888        assert!(stats.eval_obj.is_enabled());
889        assert!(stats.check_convergence.is_enabled());
890
891        // Disabling the detail timers (issue #190: `timing_statistics=no`)
892        // must leave `overall_alg` alive — it feeds the `max_cpu_time`
893        // check and is always reported — while every other timer becomes
894        // a no-op that skips the `getrusage` syscalls.
895        stats.set_detailed_enabled(false);
896        assert!(stats.overall_alg.is_enabled(), "overall_alg must stay live");
897        assert!(!stats.eval_obj.is_enabled());
898        assert!(!stats.check_convergence.is_enabled());
899        assert!(!stats.total_function_evaluation_time.is_enabled());
900        assert!(!stats.linear_system_factorization.is_enabled());
901
902        // A disabled detail timer accumulates nothing even across start/end.
903        stats.eval_obj.start();
904        stats.eval_obj.end();
905        assert_eq!(stats.eval_obj.total_wallclock_time(), 0.0);
906
907        // Re-enabling restores them.
908        stats.set_detailed_enabled(true);
909        assert!(stats.eval_obj.is_enabled());
910        assert!(stats.check_convergence.is_enabled());
911    }
912
913    #[test]
914    fn end_if_started_handles_unstarted() {
915        let t = TimedTask::new();
916        t.end_if_started();
917        assert_eq!(t.total_wallclock_time(), 0.0);
918    }
919
920    #[test]
921    fn wall_time_breakdown_reports_subsystems() {
922        let stats = TimingStatistics::new();
923        // Accumulate into two distinct subsystems so the breakdown is
924        // not trivially all-zero and the linear-algebra total is the
925        // sum of its two parts.
926        stats.linear_system_factorization.start();
927        stats.linear_system_factorization.end();
928        stats.eval_lag_hess.start();
929        stats.eval_lag_hess.end();
930
931        let bd = stats.wall_time_breakdown();
932        let get = |k: &str| bd.iter().find(|(label, _)| *label == k).map(|(_, v)| *v);
933
934        // Every advertised key is present and non-negative.
935        for key in [
936            "overall_alg",
937            "linear_system_total",
938            "linear_system_factorization",
939            "linear_system_back_solve",
940            "function_evaluations_total",
941            "eval_objective",
942            "eval_gradient",
943            "eval_constraints",
944            "eval_constraint_jacobian",
945            "eval_lagrangian_hessian",
946            "linear_system_symbolic_factorization",
947            "fire_intermediate",
948        ] {
949            assert!(get(key).is_some(), "missing breakdown key {key}");
950            assert!(get(key).unwrap() >= 0.0, "negative time for {key}");
951        }
952
953        // linear_system_total == symbolic + factorization + back_solve.
954        let total = get("linear_system_total").unwrap();
955        let sym = get("linear_system_symbolic_factorization").unwrap();
956        let fact = get("linear_system_factorization").unwrap();
957        let back = get("linear_system_back_solve").unwrap();
958        assert_eq!(total, sym + fact + back);
959    }
960
961    /// gh#698: the printed report must carry a row for every phase the
962    /// solver can spend time in. `LinearSystemSymbolicFactorization` and
963    /// `FireIntermediateCallback` were the two missing ones — the first
964    /// had no row at all, the second no timer, which together were most
965    /// of why summing the phase rows fell tens of percent short of
966    /// `OverallAlgorithm`.
967    #[test]
968    fn report_carries_the_symbolic_and_intermediate_rows() {
969        let stats = TimingStatistics::new();
970        stats.linear_system_symbolic_factorization.start();
971        stats.linear_system_symbolic_factorization.end();
972        stats.fire_intermediate.start();
973        stats.fire_intermediate.end();
974
975        let text = stats.report();
976        assert!(
977            text.contains("LinearSystemSymbolicFactorization"),
978            "no symbolic-factorization row in:\n{text}"
979        );
980        assert!(
981            text.contains("FireIntermediateCallback"),
982            "no intermediate-callback row in:\n{text}"
983        );
984    }
985}