print low level logs

src/cpp/benders/benders_by_batch/BendersByBatch.cpp

@@ -113,7 +113,9 @@ void BendersByBatch::MasterLoop() {
               random_batch_permutation_.size(), rank_0);
     SeparationLoop();
     if (Rank() == rank_0) {
-      _data.elapsed_time = GetBendersTime();
+      _data.iteration_time = -_data.benders_time;
+      _data.benders_time = GetBendersTime();
+      _data.iteration_time += _data.benders_time;
       _data.stop = ShouldBendersStop();
     }
     BroadCast(_data.stop, rank_0);
@@ -310,7 +312,7 @@ double BendersByBatch::Gap() const {
  *
  */
 void BendersByBatch::UpdateStoppingCriterion() {
-  if (_data.elapsed_time > Options().TIME_LIMIT) {
+  if (_data.benders_time > Options().TIME_LIMIT) {
     _data.stopping_criterion = StoppingCriterion::timelimit;
   } else if ((Options().MAX_ITERATIONS != -1) &&
              (_data.it >= Options().MAX_ITERATIONS))

src/cpp/benders/benders_core/BendersBase.cpp

@@ -179,7 +179,7 @@ bool BendersBase::ShouldRelaxationStop() const {
  *
  */
 void BendersBase::UpdateStoppingCriterion() {
-  if (_data.elapsed_time > _options.TIME_LIMIT)
+  if (_data.benders_time > _options.TIME_LIMIT)
     _data.stopping_criterion = StoppingCriterion::timelimit;
   else if ((_options.MAX_ITERATIONS != -1) &&
            (_data.it >= _options.MAX_ITERATIONS))
@@ -650,7 +650,7 @@ LogData BendersBase::bendersDataToLogData(
           optimal_gap,
           optimal_gap / data.best_ub,
           _options.MAX_ITERATIONS,
-          data.elapsed_time,
+          data.benders_time,
           data.timer_master,
           data.subproblems_walltime,
           data.cumulative_number_of_subproblem_solved +
@@ -806,7 +806,7 @@ void BendersBase::UpdateMaxNumberIterationResumeMode(
   }
 }
 
-double BendersBase::execution_time() const { return _data.elapsed_time; }
+double BendersBase::execution_time() const { return _data.benders_time; }
 LogData BendersBase::GetBestIterationData() const {
   return best_iteration_data;
 }
@@ -852,7 +852,7 @@ void BendersBase::ClearCurrentIterationCutTrace() const {
 }
 void BendersBase::EndWritingInOutputFile() const {
   _writer->updateEndTime();
-  _writer->write_duration(_data.elapsed_time);
+  _writer->write_duration(_data.benders_time);
   SaveSolutionInOutputFile();
 }
 double BendersBase::GetBendersTime() const { return benders_timer.elapsed(); }

src/cpp/benders/benders_core/BendersMathLogger.cpp

@@ -22,12 +22,12 @@ HeadersManager::HeadersManager(HEADERSTYPE type, const BENDERSMETHOD& method) {
   if (type == HEADERSTYPE::LONG) {
     headers_list.push_back("CumulNbSubPbSolv");
   }
-  headers_list.push_back("IteTime");
-  headers_list.push_back("MasterTime");
-  headers_list.push_back("SPWallTime");
+  headers_list.push_back("IteTime (s)");
+  headers_list.push_back("MasterTime (s)");
+  headers_list.push_back("SPWallTime (s)");
   if (type == HEADERSTYPE::LONG) {
-    headers_list.push_back("SPCpuTime");
-    headers_list.push_back("NotSolvingWallTime");
+    headers_list.push_back("SPCpuTime (s)");
+    headers_list.push_back("NotSolvingWallTime (s)");
   }
 }
 

src/cpp/benders/benders_core/include/BendersStructsDatas.h

@@ -15,6 +15,7 @@ struct CurrentIterationData {
   double best_ub;
   int deletedcut;
   int it;
+  double iteration_time;
   bool stop;
   double overall_subpb_cost_under_approx;
   std::vector<double> single_subpb_costs_under_approx;
@@ -28,7 +29,7 @@ struct CurrentIterationData {
   Point max_invest;
   int nsubproblem;
   int master_status;
-  double elapsed_time;
+  double benders_time;
   StoppingCriterion stopping_criterion;
   bool is_in_initial_relaxation;
   int number_of_subproblem_solved;

src/cpp/benders/benders_mpi/BendersMPI.cpp

@@ -200,7 +200,9 @@ void BendersMpi::step_4_update_best_solution(int rank) {
     _logger->log_at_iteration_end(bendersDataToLogData(_data));
 
     UpdateTrace();
-    _data.elapsed_time = GetBendersTime();
+    _data.iteration_time = -_data.benders_time;
+    _data.benders_time = GetBendersTime();
+    _data.iteration_time += _data.benders_time;
     _data.stop = ShouldBendersStop();
   }
 }

src/cpp/benders/benders_sequential/BendersSequential.cpp

@@ -117,7 +117,9 @@ void BendersSequential::Run() {
     UpdateTrace();
 
     set_timer_master(timer_master.elapsed());
-    _data.elapsed_time = GetBendersTime();
+    _data.iteration_time = -_data.benders_time;
+    _data.benders_time = GetBendersTime();
+    _data.iteration_time += _data.benders_time;
     _data.stop = ShouldBendersStop();
     SaveCurrentBendersData();
   }

src/cpp/benders/logger/MathLogger.cpp

@@ -3,9 +3,9 @@
 #include <iomanip>
 #include <sstream>
 
-double getDurationNotSolving(double interation, double master,
+double getDurationNotSolving(double iteration, double master,
                              double subproblems) {
-  return interation - master - subproblems;
+  return iteration - master - subproblems;
 }
 
 void MathLoggerBase::setHeadersList() {
@@ -41,15 +41,15 @@ void PrintData(LogDestination& log_destination,
     log_destination << data.cumulative_number_of_subproblem_solved;
   }
 
-  log_destination << std::setprecision(2) << data.elapsed_time;
+  log_destination << std::setprecision(2) << data.benders_time;
   log_destination << std::setprecision(2) << data.timer_master;
   log_destination << std::setprecision(2) << data.subproblems_walltime;
 
   if (type == HEADERSTYPE::LONG) {
     log_destination << std::setprecision(2)
                     << data.subproblems_cumulative_cputime;
     log_destination << std::setprecision(2)
-                    << getDurationNotSolving(data.elapsed_time,
+                    << getDurationNotSolving(data.iteration_time,
                                              data.timer_master,
                                              data.subproblems_walltime);
   }

tests/cpp/logger/logger_test.cpp

@@ -807,11 +807,11 @@ TEST(MathLoggerHeadersManagerTest, LongBenders) {
                                                "MaxSpx",
                                                "NbSubPbSolv",
                                                "CumulNbSubPbSolv",
-                                               "IteTime",
-                                               "MasterTime",
-                                               "SPWallTime",
-                                               "SPCpuTime",
-                                               "NotSolvingWallTime"};
+                                               "IteTime (s)",
+                                               "MasterTime (s)",
+                                               "SPWallTime (s)",
+                                               "SPCpuTime (s)",
+                                               "NotSolvingWallTime (s)"};
   ASSERT_EQ(expected_headers, headers_manager.headers_list);
 }
 
@@ -821,7 +821,7 @@ TEST(MathLoggerHeadersManagerTest, ShortBenders) {
 
   std::vector<std::string> expected_headers = {
       "Ite",    "Lb",     "Ub",      "BestUb",     "AbsGap",    "RelGap",
-      "MinSpx", "MaxSpx", "IteTime", "MasterTime", "SPWallTime"};
+      "MinSpx", "MaxSpx", "IteTime (s)", "MasterTime (s)", "SPWallTime (s)"};
   ASSERT_EQ(expected_headers, headers_manager.headers_list);
 }
 
@@ -835,11 +835,11 @@ TEST(MathLoggerHeadersManagerTest, LongBendersByBatch) {
                                                "MaxSpx",
                                                "NbSubPbSolv",
                                                "CumulNbSubPbSolv",
-                                               "IteTime",
-                                               "MasterTime",
-                                               "SPWallTime",
-                                               "SPCpuTime",
-                                               "NotSolvingWallTime"};
+                                               "IteTime (s)",
+                                               "MasterTime (s)",
+                                               "SPWallTime (s)",
+                                               "SPCpuTime (s)",
+                                               "NotSolvingWallTime (s)"};
   ASSERT_EQ(expected_headers, headers_manager.headers_list);
 }
 
@@ -849,7 +849,7 @@ TEST(MathLoggerHeadersManagerTest, ShortBendersByBatch) {
 
   std::vector<std::string> expected_headers = {
       "Ite",         "Lb",      "MinSpx",     "MaxSpx",
-      "NbSubPbSolv", "IteTime", "MasterTime", "SPWallTime"};
+      "NbSubPbSolv", "IteTime (s)", "MasterTime (s)", "SPWallTime (s)"};
   ASSERT_EQ(expected_headers, headers_manager.headers_list);
 }
 
@@ -903,12 +903,12 @@ TEST(MathLoggerBendersByBatchTest, DataInFileLong) {
   data.max_simplexiter = 30;
   data.number_of_subproblem_solved = 657;
   data.cumulative_number_of_subproblem_solved = 1387;
-  data.elapsed_time = 1000;
+  data.benders_time = 1000;
   data.timer_master = 10;
   data.subproblems_walltime = 16;
   data.subproblems_cumulative_cputime = 160;
   auto time_not_solving =
-      data.elapsed_time - data.timer_master - data.subproblems_walltime;
+      data.benders_time - data.timer_master - data.subproblems_walltime;
 
   std::ostringstream expected_msg;
   expected_msg << std::left << std::setw(width) << data.it;
@@ -922,7 +922,7 @@ TEST(MathLoggerBendersByBatchTest, DataInFileLong) {
   expected_msg << std::left << std::setw(width)
                << data.cumulative_number_of_subproblem_solved;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
-               << data.elapsed_time;
+               << data.benders_time;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
                << data.timer_master;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
@@ -954,12 +954,12 @@ TEST(MathLoggerBendersByBatchTest, DataInStdOutShort) {
   data.max_simplexiter = 30;
   data.number_of_subproblem_solved = 657;
   data.cumulative_number_of_subproblem_solved = 1387;
-  data.elapsed_time = 1000;
+  data.benders_time = 1000;
   data.timer_master = 10;
   data.subproblems_walltime = 16;
   data.subproblems_cumulative_cputime = 160;
   auto time_not_solving =
-      data.elapsed_time - data.timer_master - data.subproblems_walltime;
+      data.benders_time - data.timer_master - data.subproblems_walltime;
 
   std::ostringstream expected_msg;
   expected_msg << std::left << std::setw(width) << data.it;
@@ -971,7 +971,7 @@ TEST(MathLoggerBendersByBatchTest, DataInStdOutShort) {
                << data.number_of_subproblem_solved;
 
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
-               << data.elapsed_time;
+               << data.benders_time;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
                << data.timer_master;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
@@ -1000,12 +1000,12 @@ TEST(MathLoggerBendersBaseTest, DataInFileLong) {
   data.max_simplexiter = 30;
   data.number_of_subproblem_solved = 657;
   data.cumulative_number_of_subproblem_solved = 1387;
-  data.elapsed_time = 1000;
+  data.benders_time = 1000;
   data.timer_master = 10;
   data.subproblems_walltime = 16;
   data.subproblems_cumulative_cputime = 160;
   auto time_not_solving =
-      data.elapsed_time - data.timer_master - data.subproblems_walltime;
+      data.benders_time - data.timer_master - data.subproblems_walltime;
 
   std::ostringstream expected_msg;
   expected_msg << std::left << std::setw(width) << data.it;
@@ -1028,7 +1028,7 @@ TEST(MathLoggerBendersBaseTest, DataInFileLong) {
   expected_msg << std::left << std::setw(width)
                << data.cumulative_number_of_subproblem_solved;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
-               << data.elapsed_time;
+               << data.benders_time;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
                << data.timer_master;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
@@ -1060,12 +1060,12 @@ TEST(MathLoggerBendersBaseTest, DataInStdOutShort) {
   data.max_simplexiter = 30;
   data.number_of_subproblem_solved = 657;
   data.cumulative_number_of_subproblem_solved = 1387;
-  data.elapsed_time = 1000;
+  data.benders_time = 1000;
   data.timer_master = 10;
   data.subproblems_walltime = 16;
   data.subproblems_cumulative_cputime = 160;
   auto time_not_solving =
-      data.elapsed_time - data.timer_master - data.subproblems_walltime;
+      data.benders_time - data.timer_master - data.subproblems_walltime;
 
   std::ostringstream expected_msg;
   expected_msg << std::left << std::setw(width) << data.it;
@@ -1085,7 +1085,7 @@ TEST(MathLoggerBendersBaseTest, DataInStdOutShort) {
   expected_msg << std::left << std::setw(width) << data.max_simplexiter;
 
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
-               << data.elapsed_time;
+               << data.benders_time;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
                << data.timer_master;
   expected_msg << std::left << std::setw(width) << std::setprecision(2)
@@ -1099,4 +1099,4 @@ TEST(MathLoggerBendersBaseTest, DataInStdOutShort) {
   std::cout.rdbuf(initialBufferCout);
 
   ASSERT_EQ(expected_msg.str(), redirectedStdout.str());
-}
+}