Merge pull request #1087 from PowerGridModel/feature/timer-using-codes

Refactor calculation-info: timer using codes

Author: mgovers

power_grid_model_c/power_grid_model/include/power_grid_model/common/calculation_info.hpp

@@ -4,13 +4,15 @@
 
 #pragma once
 
+#include "logging.hpp"
+
 #include <cstddef>
 #include <functional>
 #include <map>
 #include <string>
 
 namespace power_grid_model {
 
-using CalculationInfo = std::map<std::string, double, std::less<>>;
+using CalculationInfo = std::map<LogEvent, double>;
 
 } // namespace power_grid_model

power_grid_model_c/power_grid_model/include/power_grid_model/common/logging.hpp

@@ -0,0 +1,50 @@
+// SPDX-FileCopyrightText: Contributors to the Power Grid Model project <[email protected]>
+//
+// SPDX-License-Identifier: MPL-2.0
+
+#pragma once
+
+#include "common.hpp"
+
+#include <string_view>
+
+namespace power_grid_model {
+namespace common::logging {
+
+enum class LogEvent : int16_t {
+    unknown = -1,
+    total = 0000,       // TODO(mgovers): find other error code?
+    build_model = 1000, // TODO(mgovers): find other error code?
+    total_single_calculation_in_thread = 0100,
+    total_batch_calculation_in_thread = 0200,
+    copy_model = 1100,
+    update_model = 1200,
+    restore_model = 1201,
+    scenario_exception = 1300,
+    recover_from_bad = 1400,
+    prepare = 2100,
+    create_math_solver = 2210,
+    math_calculation = 2200,
+    math_solver = 2220,
+    initialize_calculation = 2221,
+    preprocess_measured_value = 2231, // TODO(mgovers): find other error code + make plural?
+    prepare_matrix = 2222,
+    prepare_matrix_including_prefactorization = 2232, // TODO(mgovers): find other error code
+    prepare_matrices = 2242,                          // TODO(mgovers): find other error code
+    initialize_voltages = 2223,
+    calculate_rhs = 2224,
+    prepare_lhs_rhs = 2244, // TODO(mgovers): find other error code
+    solve_sparse_linear_equation = 2225,
+    solve_sparse_linear_equation_prefactorized = 2235, // TODO(mgovers): find other error code
+    iterate_unknown = 2226,
+    calculate_math_result = 2227,
+    produce_output = 3000,
+    iterative_pf_solver_max_num_iter = 2246, // TODO(mgovers): find other error code
+    max_num_iter = 2248,                     // TODO(mgovers): find other error code
+};
+
+} // namespace common::logging
+
+using common::logging::LogEvent;
+
+} // namespace power_grid_model

power_grid_model_c/power_grid_model/include/power_grid_model/common/timer.hpp

@@ -6,6 +6,7 @@
 
 #include "calculation_info.hpp"
 #include "common.hpp"
+#include "logging.hpp"
 
 #include <chrono>
 #include <iomanip>
@@ -19,15 +20,12 @@ using Duration = std::chrono::duration<double>;
 class Timer {
   private:
     CalculationInfo* info_;
-    int code_;
-    std::string name_;
+    LogEvent code_;
     Clock::time_point start_;
 
   public:
-    Timer() : info_(nullptr), code_{-1} {};
-
-    Timer(CalculationInfo& info, int code, std::string name)
-        : info_{&info}, code_{code}, name_{std::move(name)}, start_{Clock::now()} {}
+    Timer() : info_(nullptr), code_{LogEvent::unknown} {};
+    Timer(CalculationInfo& info, LogEvent code) : info_{&info}, code_{code}, start_{Clock::now()} {}
 
     Timer(Timer const&) = delete;
     Timer(Timer&&) = default;
@@ -40,7 +38,6 @@ class Timer {
         // Copy/move members
         info_ = timer.info_;
         code_ = timer.code_;
-        name_ = std::move(timer.name_);
         start_ = timer.start_;
 
         // Disable original timer
@@ -60,24 +57,10 @@ class Timer {
         if (info_ != nullptr) {
             auto const now = Clock::now();
             auto const duration = Duration(now - start_);
-            info_->operator[](Timer::make_key(code_, name_)) += (double)duration.count();
+            info_->operator[](code_) += static_cast<double>(duration.count());
             info_ = nullptr;
         }
     }
-
-    static std::string make_key(int code, std::string_view name) {
-        std::stringstream ss;
-        ss << std::setw(4) << std::setfill('0') << code << ".";
-        auto key = ss.str();
-        for (size_t i = 0, n = key.length() - 1; i < n; ++i) {
-            if (key[i] == '0') {
-                break;
-            }
-            key += "\t";
-        }
-        key += name;
-        return key;
-    }
 };
 
 } // namespace power_grid_model

power_grid_model_c/power_grid_model/include/power_grid_model/job_dispatch.hpp

@@ -60,22 +60,22 @@ class JobDispatch {
             assert(n_scenarios <= narrow_cast<Idx>(exceptions.size()));
             CalculationInfo thread_info;
 
-            Timer t_total(thread_info, 0200, "Total batch calculation in thread");
+            Timer t_total{thread_info, LogEvent::total_batch_calculation_in_thread};
 
             auto const copy_adapter_functor = [&base_adapter, &thread_info]() {
-                Timer const t_copy_adapter_functor(thread_info, 1100, "Copy model");
+                Timer const t_copy_adapter_functor{thread_info, LogEvent::copy_model};
                 return Adapter{base_adapter};
             };
 
             auto adapter = copy_adapter_functor();
 
             auto setup = [&adapter, &update_data, &thread_info](Idx scenario_idx) {
-                Timer const t_update_model(thread_info, 1200, "Update model");
+                Timer const t_update_model{thread_info, LogEvent::update_model};
                 adapter.setup(update_data, scenario_idx);
             };
 
             auto winddown = [&adapter, &thread_info]() {
-                Timer const t_restore_model(thread_info, 1201, "Restore model");
+                Timer const t_restore_model{thread_info, LogEvent::restore_model};
                 adapter.winddown();
             };
 
@@ -95,7 +95,7 @@ class JobDispatch {
                 scenario_exception_handler(adapter, exceptions, thread_info), std::move(recover_from_bad));
 
             for (Idx scenario_idx = start; scenario_idx < n_scenarios; scenario_idx += stride) {
-                Timer const t_total_single(thread_info, 0100, "Total single calculation in thread");
+                Timer const t_total_single{thread_info, LogEvent::total_single_calculation_in_thread};
                 calculate_scenario(scenario_idx);
             }
 

power_grid_model_c/power_grid_model/include/power_grid_model/main_core/calculation_info.hpp

@@ -11,7 +11,9 @@
 namespace power_grid_model::main_core {
 
 inline CalculationInfo& merge_into(CalculationInfo& destination, CalculationInfo const& source) {
-    static auto const key = Timer::make_key(2226, "Max number of iterations");
+    static constexpr auto key =
+        LogEvent::iterative_pf_solver_max_num_iter; // TODO(mgovers) also add LogEvent::max_num_iter; this is a bug
+                                                    // in main
     for (auto const& [k, v] : source) {
         if (k == key) {
             destination[k] = std::max(destination[k], v);

power_grid_model_c/power_grid_model/include/power_grid_model/main_model_impl.hpp

@@ -423,14 +423,14 @@ class MainModelImpl<ExtraRetrievableTypes<ExtraRetrievableType...>, ComponentLis
         calculation_info_ = CalculationInfo{};
         // prepare
         auto const& input = [this, prepare_input_ = std::forward<PrepareInputFn>(prepare_input)] {
-            Timer const timer(calculation_info_, 2100, "Prepare");
+            Timer const timer{calculation_info_, LogEvent::prepare};
             prepare_solvers<sym>();
             assert(is_topology_up_to_date_ && is_parameter_up_to_date<sym>());
             return prepare_input_(n_math_solvers_);
         }();
         // calculate
         return [this, &input, solve_ = std::forward<SolveFn>(solve)] {
-            Timer const timer(calculation_info_, 2200, "Math Calculation");
+            Timer const timer{calculation_info_, LogEvent::math_calculation};
             auto& solvers = get_solvers<sym>();
             auto& y_bus_vec = get_y_bus<sym>();
             std::vector<SolverOutputType> solver_output;
@@ -595,7 +595,7 @@ class MainModelImpl<ExtraRetrievableTypes<ExtraRetrievableType...>, ComponentLis
             }
         };
 
-        Timer const t_output(calculation_info_, 3000, "Produce output");
+        Timer const t_output{calculation_info_, LogEvent::produce_output};
         main_core::utils::run_functor_with_all_types_return_void<ComponentType...>(output_func);
     }
 

power_grid_model_c/power_grid_model/include/power_grid_model/math_solver/iterative_linear_se_solver.hpp

@@ -93,22 +93,22 @@ template <symmetry_tag sym_type> class IterativeLinearSESolver {
         output.bus_injection.resize(n_bus_);
         double max_dev = std::numeric_limits<double>::max();
 
-        main_timer = Timer(calculation_info, 2220, "Math solver");
+        main_timer = Timer{calculation_info, LogEvent::math_solver};
 
         // preprocess measured value
-        sub_timer = Timer(calculation_info, 2221, "Pre-process measured value");
+        sub_timer = Timer{calculation_info, LogEvent::preprocess_measured_value};
         MeasuredValues<sym> const measured_values{y_bus.shared_topology(), input};
         auto const observability_result =
             observability_check(measured_values, y_bus.math_topology(), y_bus.y_bus_structure());
 
         // prepare matrix
-        sub_timer = Timer(calculation_info, 2222, "Prepare matrix, including pre-factorization");
+        sub_timer = Timer{calculation_info, LogEvent::prepare_matrix_including_prefactorization};
         prepare_matrix(y_bus, measured_values);
         // prefactorize
         sparse_solver_.prefactorize(data_gain_, perm_, observability_result.use_perturbation());
 
         // initialize voltage with initial angle
-        sub_timer = Timer(calculation_info, 2223, "Initialize voltages");
+        sub_timer = Timer{calculation_info, LogEvent::initialize_voltages}; // TODO(mgovers): make scoped subtimers
         RealValue<sym> const mean_angle_shift = measured_values.mean_angle_shift();
         for (Idx bus = 0; bus != n_bus_; ++bus) {
             output.u[bus] = exp(1.0i * (mean_angle_shift + math_topo_->phase_shift[bus]));
@@ -120,25 +120,25 @@ template <symmetry_tag sym_type> class IterativeLinearSESolver {
             if (num_iter++ == max_iter) {
                 throw IterationDiverge{max_iter, max_dev, err_tol};
             }
-            sub_timer = Timer(calculation_info, 2224, "Calculate rhs");
+            sub_timer = Timer{calculation_info, LogEvent::calculate_rhs};
             prepare_rhs(y_bus, measured_values, output.u);
             // solve with prefactorization
-            sub_timer = Timer(calculation_info, 2225, "Solve sparse linear equation (pre-factorized)");
+            sub_timer = Timer{calculation_info, LogEvent::solve_sparse_linear_equation_prefactorized};
             sparse_solver_.solve_with_prefactorized_matrix(data_gain_, perm_, x_rhs_, x_rhs_);
-            sub_timer = Timer(calculation_info, 2226, "Iterate unknown");
+            sub_timer = Timer{calculation_info, LogEvent::iterate_unknown};
             max_dev = iterate_unknown(output.u, measured_values.has_angle());
         };
 
         // calculate math result
-        sub_timer = Timer(calculation_info, 2227, "Calculate math result");
+        sub_timer = Timer{calculation_info, LogEvent::calculate_math_result};
         detail::calculate_se_result<sym>(y_bus, measured_values, output);
 
         // Manually stop timers to avoid "Max number of iterations" to be included in the timing.
         sub_timer.stop();
         main_timer.stop();
 
-        auto const key = Timer::make_key(2228, "Max number of iterations");
-        calculation_info[key] = std::max(calculation_info[key], static_cast<double>(num_iter));
+        calculation_info[LogEvent::max_num_iter] =
+            std::max(calculation_info[LogEvent::max_num_iter], static_cast<double>(num_iter));
 
         return output;
     }

power_grid_model_c/power_grid_model/include/power_grid_model/math_solver/iterative_pf_solver.hpp

@@ -34,11 +34,11 @@ template <symmetry_tag sym, typename DerivedSolver> class IterativePFSolver {
         output.u.resize(n_bus_);
         double max_dev = std::numeric_limits<double>::infinity();
 
-        Timer main_timer{calculation_info, 2220, "Math solver"};
+        Timer main_timer{calculation_info, LogEvent::math_solver};
 
         // initialize
         {
-            Timer const sub_timer{calculation_info, 2221, "Initialize calculation"};
+            Timer const sub_timer{calculation_info, LogEvent::initialize_calculation};
             // Further initialization specific to the derived solver
             derived_solver.initialize_derived_solver(y_bus, input, output);
         }
@@ -52,31 +52,31 @@ template <symmetry_tag sym, typename DerivedSolver> class IterativePFSolver {
             }
             {
                 // Prepare the matrices of linear equations to be solved
-                Timer const sub_timer{calculation_info, 2222, "Prepare the matrices"};
+                Timer const sub_timer{calculation_info, LogEvent::prepare_matrices};
                 derived_solver.prepare_matrix_and_rhs(y_bus, input, output.u);
             }
             {
                 // Solve the linear equations
-                Timer const sub_timer{calculation_info, 2223, "Solve sparse linear equation"};
+                Timer const sub_timer{calculation_info, LogEvent::solve_sparse_linear_equation};
                 derived_solver.solve_matrix();
             }
             {
                 // Calculate maximum deviation of voltage at any bus
-                Timer const sub_timer{calculation_info, 2224, "Iterate unknown"};
+                Timer const sub_timer{calculation_info, LogEvent::iterate_unknown};
                 max_dev = derived_solver.iterate_unknown(output.u);
             }
         }
 
         // calculate math result
         {
-            Timer const sub_timer{calculation_info, 2225, "Calculate math result"};
+            Timer const sub_timer{calculation_info, LogEvent::calculate_math_result};
             calculate_result(y_bus, input, output);
         }
         // Manually stop timers to avoid "Max number of iterations" to be included in the timing.
         main_timer.stop();
 
-        auto const key = Timer::make_key(2226, "Max number of iterations");
-        calculation_info[key] = std::max(calculation_info[key], static_cast<double>(num_iter));
+        calculation_info[LogEvent::iterative_pf_solver_max_num_iter] =
+            std::max(calculation_info[LogEvent::iterative_pf_solver_max_num_iter], static_cast<double>(num_iter));
 
         return output;
     }

power_grid_model_c/power_grid_model/include/power_grid_model/math_solver/linear_pf_solver.hpp

@@ -64,24 +64,26 @@ template <symmetry_tag sym_type> class LinearPFSolver {
 
     SolverOutput<sym> run_power_flow(YBus<sym> const& y_bus, PowerFlowInput<sym> const& input,
                                      CalculationInfo& calculation_info) {
+        using enum LogEvent;
+
         // output
         SolverOutput<sym> output;
         output.u.resize(n_bus_);
 
-        Timer const main_timer(calculation_info, 2220, "Math solver");
+        Timer const main_timer{calculation_info, math_solver};
 
         // prepare matrix
-        Timer sub_timer(calculation_info, 2221, "Prepare matrix");
+        Timer sub_timer{calculation_info, prepare_matrix};
         detail::copy_y_bus<sym>(y_bus, mat_data_);
         prepare_matrix_and_rhs(y_bus, input, output);
 
         // solve
         // u vector will have I_injection for slack bus for now
-        sub_timer = Timer(calculation_info, 2222, "Solve sparse linear equation");
+        sub_timer = Timer{calculation_info, solve_sparse_linear_equation};
         sparse_solver_.prefactorize_and_solve(mat_data_, perm_, output.u, output.u);
 
         // calculate math result
-        sub_timer = Timer(calculation_info, 2223, "Calculate math result");
+        sub_timer = Timer{calculation_info, calculate_math_result};
         calculate_result(y_bus, input, output);
 
         // output

power_grid_model_c/power_grid_model/include/power_grid_model/math_solver/math_solver.hpp

@@ -85,7 +85,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
 
         // construct model if needed
         if (!iec60909_sc_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             iec60909_sc_solver_.emplace(y_bus, topo_ptr_);
         }
 
@@ -119,7 +119,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
     SolverOutput<sym> run_power_flow_newton_raphson(PowerFlowInput<sym> const& input, double err_tol, Idx max_iter,
                                                     CalculationInfo& calculation_info, YBus<sym> const& y_bus) {
         if (!newton_raphson_pf_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             newton_raphson_pf_solver_.emplace(y_bus, topo_ptr_);
         }
         return newton_raphson_pf_solver_.value().run_power_flow(y_bus, input, err_tol, max_iter, calculation_info);
@@ -128,7 +128,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
     SolverOutput<sym> run_power_flow_linear(PowerFlowInput<sym> const& input, double /* err_tol */, Idx /* max_iter */,
                                             CalculationInfo& calculation_info, YBus<sym> const& y_bus) {
         if (!linear_pf_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             linear_pf_solver_.emplace(y_bus, topo_ptr_);
         }
         return linear_pf_solver_.value().run_power_flow(y_bus, input, calculation_info);
@@ -137,7 +137,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
     SolverOutput<sym> run_power_flow_iterative_current(PowerFlowInput<sym> const& input, double err_tol, Idx max_iter,
                                                        CalculationInfo& calculation_info, YBus<sym> const& y_bus) {
         if (!iterative_current_pf_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             iterative_current_pf_solver_.emplace(y_bus, topo_ptr_);
         }
         return iterative_current_pf_solver_.value().run_power_flow(y_bus, input, err_tol, max_iter, calculation_info);
@@ -155,7 +155,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
                                                             YBus<sym> const& y_bus) {
         // construct model if needed
         if (!iterative_linear_se_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             iterative_linear_se_solver_.emplace(y_bus, topo_ptr_);
         }
 
@@ -169,7 +169,7 @@ template <symmetry_tag sym> class MathSolver : public MathSolverBase<sym> {
                                                           YBus<sym> const& y_bus) {
         // construct model if needed
         if (!newton_raphson_se_solver_.has_value()) {
-            Timer const timer(calculation_info, 2210, "Create math solver");
+            Timer const timer{calculation_info, LogEvent::create_math_solver};
             newton_raphson_se_solver_.emplace(y_bus, topo_ptr_);
         }