Improve timers

src/polysolve/nonlinear/Solver.cpp

@@ -332,10 +332,14 @@ namespace polysolve::nonlinear
 
             // --- Update direction --------------------------------------------
 
-            const bool ok = compute_update_direction(objFunc, x, grad, delta_x);
-            m_current.xDelta = delta_x.norm();
+            bool update_direction_successful;
+            {
+                POLYSOLVE_SCOPED_STOPWATCH("compute update direction", update_direction_time, m_logger);
+                update_direction_successful = compute_update_direction(objFunc, x, grad, delta_x);
+            }
 
-            if (!ok || std::isnan(m_current.xDelta))
+            m_current.xDelta = delta_x.norm();
+            if (!update_direction_successful || std::isnan(m_current.xDelta))
             {
                 const auto current_name = descent_strategy_name();
                 if (!m_strategies[m_descent_strategy]->handle_error())
@@ -400,7 +404,12 @@ namespace polysolve::nonlinear
                 m_current.iterations, energy, m_current.gradNorm);
 
             // Perform a line_search to compute step scale
-            double rate = m_line_search->line_search(x, delta_x, objFunc);
+            double rate;
+            {
+                POLYSOLVE_SCOPED_STOPWATCH("line search", line_search_time, m_logger);
+                rate = m_line_search->line_search(x, delta_x, objFunc);
+            }
+
             if (std::isnan(rate))
             {
                 const auto current_name = descent_strategy_name();
@@ -428,7 +437,6 @@ namespace polysolve::nonlinear
             // if we did enough lower strategy, we revert back to normal
             if (m_descent_strategy != 0 && current_strategy_iter >= m_iter_per_strategy[m_descent_strategy])
             {
-
                 const auto current_name = descent_strategy_name();
                 const std::string prev_strategy_name = descent_strategy_name();
 
@@ -514,14 +522,13 @@ namespace polysolve::nonlinear
     void Solver::reset_times()
     {
         total_time = 0;
+        obj_fun_time = 0;
         grad_time = 0;
+        update_direction_time = 0;
         line_search_time = 0;
-        obj_fun_time = 0;
         constraint_set_update_time = 0;
         if (m_line_search)
-        {
             m_line_search->reset_times();
-        }
         for (auto &s : m_strategies)
             s->reset_times();
     }
@@ -538,47 +545,30 @@ namespace polysolve::nonlinear
         double per_iteration = m_current.iterations ? m_current.iterations : 1;
 
         solver_info["total_time"] = total_time;
+        solver_info["time_obj_fun"] = obj_fun_time / per_iteration;
         solver_info["time_grad"] = grad_time / per_iteration;
+        // Do not save update_direction_time as it is redundant with the strategies
         solver_info["time_line_search"] = line_search_time / per_iteration;
         solver_info["time_constraint_set_update"] = constraint_set_update_time / per_iteration;
-        solver_info["time_obj_fun"] = obj_fun_time / per_iteration;
 
         for (auto &s : m_strategies)
             s->update_solver_info(solver_info, per_iteration);
-
         if (m_line_search)
-        {
-            solver_info["line_search_iterations"] = m_line_search->iterations();
-
-            solver_info["time_checking_for_nan_inf"] =
-                m_line_search->checking_for_nan_inf_time / per_iteration;
-            solver_info["time_broad_phase_ccd"] =
-                m_line_search->broad_phase_ccd_time / per_iteration;
-            solver_info["time_ccd"] = m_line_search->ccd_time / per_iteration;
-            // Remove double counting
-            solver_info["time_classical_line_search"] =
-                (m_line_search->classical_line_search_time
-                 - m_line_search->constraint_set_update_time)
-                / per_iteration;
-            solver_info["time_line_search_constraint_set_update"] =
-                m_line_search->constraint_set_update_time / per_iteration;
-        }
+            m_line_search->update_solver_info(solver_info, per_iteration);
     }
 
-    void Solver::log_times()
+    void Solver::log_times() const
     {
         m_logger.debug(
-            "[{}] grad {:.3g}s, "
-            "line_search {:.3g}s, constraint_set_update {:.3g}s, "
-            "obj_fun {:.3g}s, checking_for_nan_inf {:.3g}s, "
-            "broad_phase_ccd {:.3g}s, ccd {:.3g}s, "
-            "classical_line_search {:.3g}s",
+            "[{}] f: {:.2e}s, grad_f: {:.2e}s, update_direction: {:.2e}s, "
+            "line_search: {:.2e}s, constraint_set_update: {:.2e}s",
             fmt::format(fmt::fg(fmt::terminal_color::magenta), "timing"),
-            grad_time, line_search_time,
-            constraint_set_update_time + (m_line_search ? m_line_search->constraint_set_update_time : 0),
-            obj_fun_time, m_line_search ? m_line_search->checking_for_nan_inf_time : 0,
-            m_line_search ? m_line_search->broad_phase_ccd_time : 0, m_line_search ? m_line_search->ccd_time : 0,
-            m_line_search ? m_line_search->classical_line_search_time : 0);
+            obj_fun_time, grad_time, update_direction_time, line_search_time,
+            constraint_set_update_time);
+        for (auto &s : m_strategies)
+            s->log_times();
+        if (m_line_search)
+            m_line_search->log_times();
     }
 
     void Solver::verify_gradient(Problem &objFunc, const TVector &x, const TVector &grad)

src/polysolve/nonlinear/Solver.hpp

@@ -145,16 +145,17 @@ namespace polysolve::nonlinear
 
         void update_solver_info(const double energy);
         void reset_times();
-        void log_times();
+        void log_times() const;
 
         json solver_info;
 
         // Timers
         double total_time;
+        double obj_fun_time;
         double grad_time;
+        double update_direction_time;
         double line_search_time;
         double constraint_set_update_time;
-        double obj_fun_time;
 
         // ====================================================================
         //                                 END

src/polysolve/nonlinear/descent_strategies/DescentStrategy.hpp

@@ -25,6 +25,7 @@ namespace polysolve::nonlinear
         virtual void reset(const int ndof) {}
         virtual void reset_times() {}
         virtual void update_solver_info(json &solver_info, const double per_iteration) {}
+        virtual void log_times() const {}
 
         virtual bool is_direction_descent() { return true; }
         virtual bool handle_error() { return false; }

src/polysolve/nonlinear/descent_strategies/Newton.cpp

@@ -2,6 +2,8 @@
 
 #include <polysolve/Utils.hpp>
 
+#include <spdlog/fmt/bundled/color.h>
+
 namespace polysolve::nonlinear
 {
 
@@ -57,14 +59,14 @@
                    const double characteristic_length,
                    spdlog::logger &logger)
         : Superclass(solver_params, characteristic_length, logger),
-          is_sparse(sparse), m_characteristic_length(characteristic_length), m_residual_tolerance(residual_tolerance)
+          is_sparse(sparse), characteristic_length(characteristic_length), residual_tolerance(residual_tolerance)
     {
         linear_solver = polysolve::linear::Solver::create(linear_solver_params, logger);
         if (linear_solver->is_dense() == sparse)
             log_and_throw_error(logger, "Newton linear solver must be {}, instead got {}", sparse ? "sparse" : "dense", linear_solver->name());
 
-        if (m_residual_tolerance <= 0)
-            log_and_throw_error(logger, "Newton residual_tolerance must be > 0, instead got {}", m_residual_tolerance);
+        if (residual_tolerance <= 0)
+            log_and_throw_error(logger, "Newton residual_tolerance must be > 0, instead got {}", residual_tolerance);
     }
 
     Newton::Newton(
@@ -139,10 +141,10 @@
             is_sparse ? solve_sparse_linear_system(objFunc, x, grad, direction)
                       : solve_dense_linear_system(objFunc, x, grad, direction);
 
-        if (std::isnan(residual) || residual > m_residual_tolerance * m_characteristic_length)
+        if (std::isnan(residual) || residual > residual_tolerance * characteristic_length)
         {
             m_logger.debug("[{}] large (or nan) linear solve residual {}>{} (||∇f||={})",
-                           name(), residual, m_residual_tolerance * m_characteristic_length, grad.norm());
+                           name(), residual, residual_tolerance * characteristic_length, grad.norm());
 
             return false;
         }
@@ -156,8 +158,6 @@
 
     // =======================================================================
 
-    // =======================================================================
-
     double Newton::solve_sparse_linear_system(Problem &objFunc,
                                               const TVector &x,
                                               const TVector &grad,
@@ -326,6 +326,22 @@
         solver_info["time_inverting"] = inverting_time / per_iteration;
     }
 
+    void Newton::reset_times()
+    {
+        assembly_time = 0;
+        inverting_time = 0;
+    }
+
+    void Newton::log_times() const
+    {
+        if (assembly_time <= 0 && inverting_time <= 0)
+            return; // nothing to log
+        m_logger.debug(
+            "[{}][{}] assembly: {:.2e}s; linear_solve: {:.2e}s",
+            fmt::format(fmt::fg(fmt::terminal_color::magenta), "timing"),
+            name(), assembly_time, inverting_time);
+    }
+
     // =======================================================================
 
 } // namespace polysolve::nonlinear

src/polysolve/nonlinear/descent_strategies/Newton.hpp

@@ -47,8 +47,8 @@ namespace polysolve::nonlinear
         json internal_solver_info = json::array();
 
         const bool is_sparse;
-        const double m_characteristic_length;
-        double m_residual_tolerance;
+        const double characteristic_length;
+        double residual_tolerance;
 
         std::unique_ptr<polysolve::linear::Solver> linear_solver; ///< Linear solver used to solve the linear system
 
@@ -71,12 +71,8 @@ namespace polysolve::nonlinear
 
         void reset(const int ndof) override;
         void update_solver_info(json &solver_info, const double per_iteration) override;
-
-        void reset_times() override
-        {
-            assembly_time = 0;
-            inverting_time = 0;
-        }
+        void reset_times() override;
+        void log_times() const override;
     };
 
     class ProjectedNewton : public Newton

src/polysolve/nonlinear/line_search/Armijo.hpp

@@ -13,7 +13,7 @@ namespace polysolve::nonlinear::line_search
 
         Armijo(const json &params, spdlog::logger &logger);
 
-        virtual std::string name() override { return "Armijo"; }
+        virtual std::string name() const override { return "Armijo"; }
 
     protected:
         virtual void init_compute_descent_step_size(

src/polysolve/nonlinear/line_search/Backtracking.hpp

@@ -13,7 +13,7 @@ namespace polysolve::nonlinear::line_search
 
         Backtracking(const json &params, spdlog::logger &logger);
 
-        virtual std::string name() override { return "Backtracking"; }
+        virtual std::string name() const override { return "Backtracking"; }
 
         double compute_descent_step_size(
             const TVector &x,

src/polysolve/nonlinear/line_search/LineSearch.cpp

@@ -9,7 +9,7 @@
 
 #include <polysolve/Types.hpp>
 
-#include <spdlog/spdlog.h>
+#include <spdlog/fmt/bundled/color.h>
 
 #include <cfenv>
 
@@ -117,7 +117,7 @@ namespace polysolve::nonlinear::line_search
         }
 
         {
-            POLYSOLVE_SCOPED_STOPWATCH("CCD narrow-phase", ccd_time, m_logger);
+            POLYSOLVE_SCOPED_STOPWATCH("CCD narrow-phase", narrow_phase_ccd_time, m_logger);
             m_logger.trace("Performing narrow-phase CCD");
             step_size = compute_collision_free_step_size(x, delta_x, objFunc, step_size);
             if (std::isnan(step_size))
@@ -246,4 +246,33 @@ namespace polysolve::nonlinear::line_search
 
         return step_size;
     }
+
+    void LineSearch::update_solver_info(json &solver_info, const double per_iteration)
+    {
+        solver_info["line_search_iterations"] = iterations();
+        solver_info["time_checking_for_nan_inf"] = checking_for_nan_inf_time / per_iteration;
+        solver_info["time_broad_phase_ccd"] = broad_phase_ccd_time / per_iteration;
+        solver_info["time_ccd"] = narrow_phase_ccd_time / per_iteration;
+        solver_info["time_classical_line_search"] = (classical_line_search_time - constraint_set_update_time) / per_iteration; // Remove double counting
+        solver_info["time_line_search_constraint_set_update"] = constraint_set_update_time / per_iteration;
+    }
+
+    void LineSearch::reset_times()
+    {
+        checking_for_nan_inf_time = 0;
+        broad_phase_ccd_time = 0;
+        narrow_phase_ccd_time = 0;
+        constraint_set_update_time = 0;
+        classical_line_search_time = 0;
+    }
+
+    void LineSearch::log_times() const
+    {
+        m_logger.debug(
+            "[{}][{}] constraint_set_update {:.2e}s, checking_for_nan_inf {:.2e}s, "
+            "broad_phase_ccd {:.2e}s, narrow_phase_ccd {:.2e}s, classical_line_search {:.2e}s",
+            fmt::format(fmt::fg(fmt::terminal_color::magenta), "timing"),
+            name(), constraint_set_update_time, checking_for_nan_inf_time,
+            broad_phase_ccd_time, narrow_phase_ccd_time, classical_line_search_time);
+    }
 } // namespace polysolve::nonlinear::line_search