Merge pull request #2632 from ERGO-Code/better-ipx-logging

jajhall · web-flow · commit bb3b26292dc3 · 2025-11-03T10:17:06.000Z
Better IPX logging
diff --git a/highs/ipm/IpxWrapper.cpp b/highs/ipm/IpxWrapper.cpp
@@ -63,6 +63,10 @@ HighsStatus solveLpIpx(const HighsOptions& options, HighsTimer& timer,
   resetModelStatusAndHighsInfo(model_status, highs_info);
   // Create the LpSolver instance
   ipx::LpSolver lps;
+  // Use the current HiGHS time as an offset for the lps.control_
+  // elapsed time
+  lps.setTimerOffset(timer.read());
+
   // Set IPX parameters
   //
   // Cannot set internal IPX parameters directly since they are
@@ -125,8 +129,9 @@ HighsStatus solveLpIpx(const HighsOptions& options, HighsTimer& timer,
 
   parameters.analyse_basis_data =
       kHighsAnalysisLevelNlaData & options.highs_analysis_level;
-  // Determine the run time allowed for IPX
-  parameters.time_limit = options.time_limit - timer.read();
+  // Now that the lps.control_ elapsed time includes the HiGHS time,
+  // can use the HiGHS time limit
+  parameters.time_limit = options.time_limit;
   parameters.ipm_maxiter =
       options.ipm_iteration_limit - highs_info.ipm_iteration_count;
   // Determine if crossover is to be run or not
@@ -458,6 +463,10 @@ HighsStatus solveLpHipo(const HighsOptions& options, HighsTimer& timer,
 
   // Create solver instance
   hipo::Solver hipo{};
+  // This creates ipx::LpSolver ipx_lps_, in case HiPO has to switch
+  // to IPX, so use the current HiGHS time as an offset for the
+  // ipx_lps.control_ elapsed time
+  hipo.setIpxTimerOffset(timer.read());
 
   hipo::Options hipo_options{};
 
@@ -504,7 +513,7 @@ HighsStatus solveLpHipo(const HighsOptions& options, HighsTimer& timer,
 
   // Potentially control if ipx is used for refinement and if it is displayed
   // hipo_options.refine_with_ipx = true;
-  // hipo_options.display_ipx = true;
+  hipo_options.display_ipx = true;
 
   // if option parallel is on, it can be refined by option hipo_parallel_type
   if (options.parallel == kHighsOnString) {
@@ -1591,4 +1600,4 @@ HighsStatus reportHipoCrossoverStatus(const HighsOptions& options,
   }
   return HighsStatus::kError;
 }
-#endif
+#endif
diff --git a/highs/ipm/hipo/ipm/Solver.cpp b/highs/ipm/hipo/ipm/Solver.cpp
@@ -187,7 +187,7 @@ bool Solver::prepareIpx() {
   ipx_param.ipm_feasibility_tol = options_.feasibility_tol;
   ipx_param.ipm_optimality_tol = options_.optimality_tol;
   ipx_param.start_crossover_tol = options_.crossover_tol;
-  ipx_param.time_limit = options_.time_limit - control_.elapsed();
+  ipx_param.time_limit = options_.time_limit;
   ipx_param.ipm_maxiter = options_.max_iter - iter_;
   ipx_lps_.SetParameters(ipx_param);
 
@@ -1590,4 +1590,4 @@ bool Solver::solved() const { return statusIsSolved(); }
 bool Solver::stopped() const { return statusIsStopped(); }
 bool Solver::failed() const { return statusIsFailed(); }
 
-}  // namespace hipo
+}  // namespace hipo
diff --git a/highs/ipm/hipo/ipm/Solver.h b/highs/ipm/hipo/ipm/Solver.h
@@ -121,6 +121,9 @@ class Solver {
   bool stopped() const;
   bool failed() const;
 
+  // Set the IPX timer offset
+  void setIpxTimerOffset(const double offset) { this->ipx_lps_.setTimerOffset(offset); }
+
  private:
   // Functions to run the various stages of the ipm
   void runIpm();
diff --git a/highs/ipm/ipx/basis.cc b/highs/ipm/ipx/basis.cc
@@ -132,7 +132,7 @@ Int Basis::Factorize() {
     h_logging_stream <<
       "    Start  factorization " << Format(num_factorizations_+1, 3) <<
       ": nonzeros in basis = " << Format(basis_num_nz, 9) <<
-      Format("", 14) << Fixed(control_.Elapsed(), 6, 0) << "s\n";
+      Format("", 14) << time(control_.Elapsed()) << "\n";
     control_.hIntervalLog(h_logging_stream);
 
     Int err = 0;                // return code
@@ -165,7 +165,7 @@ Int Basis::Factorize() {
     h_logging_stream <<
       "    Finish factorization " << Format(num_factorizations_, 3) <<
       ": fill factor = " << Fixed(lu_->fill_factor(), 6, 2) <<
-      Format("", 23) << Fixed(control_.Elapsed(), 6, 0) << "s\n";
+      Format("", 23) << time(control_.Elapsed()) << "\n";
     control_.hIntervalLog(h_logging_stream);
     return err;
 }
@@ -933,7 +933,7 @@ void Basis::PivotFixedVariablesOutOfBasis(const double* colweights, Info* info){
 	h_logging_stream.str(std::string());
 	h_logging_stream << Format(remaining.size(), 9) <<
 	  " fixed variables remaining" << Format("", 38) <<
-	  Fixed(control_.Elapsed(), 6, 0) << "s\n";
+	  time(control_.Elapsed()) << "\n";
 	control_.hIntervalLog(h_logging_stream);
     }
     control_.Debug()
diff --git a/highs/ipm/ipx/control.cc b/highs/ipm/ipx/control.cc
@@ -13,7 +13,7 @@ Control::Control() {
 Int Control::InterruptCheck(const Int ipm_iteration_count) const {
     HighsTaskExecutor::getThisWorkerDeque()->checkInterrupt();
     if (parameters_.time_limit >= 0.0 &&
-        parameters_.time_limit < timer_.Elapsed())
+        parameters_.time_limit < this->Elapsed())
         return IPX_ERROR_time_interrupt;
     // The pointer callback_ should not be null, since that indicates
     // that it's not been set
@@ -38,7 +38,8 @@ void Control::hLog(std::string str) const {
   } else {
     output_ << str;
   }
-
+  // Reset interval-based logging since something has been logged
+  interval_.Reset();
 }
 
 void Control::hLog(std::stringstream& logging) const {
@@ -50,9 +51,12 @@ void Control::hLog(std::stringstream& logging) const {
     output_ << logging.str();
   }
   logging.str(std::string());
+  // Reset interval-based logging since something has been logged
+  interval_.Reset();
 }
 
 void Control::hIntervalLog(std::stringstream& logging) const {
+  double interval_elapsed = interval_.Elapsed();
   if (parameters_.print_interval >= 0.0 &&
       interval_.Elapsed() >= parameters_.print_interval) {
     interval_.Reset();
@@ -79,7 +83,7 @@ void Control::ResetPrintInterval() const {
 }
 
 double Control::Elapsed() const {
-    return timer_.Elapsed();
+    return timer_.offset_ + timer_.Elapsed();
 }
 
 const Parameters& Control::parameters() const {
diff --git a/highs/ipm/ipx/control.h b/highs/ipm/ipx/control.h
@@ -92,6 +92,8 @@ class Control {
     double centringAlphaScaling() const{return parameters_.centring_alpha_scaling; }
     ipxint badProductsTolerance() const{return parameters_.bad_products_tolerance; }
     bool timelessLog() const{return parameters_.timeless_log; }
+    void setTimerOffset(const double offset) { this->timer_.offset_ = offset; }
+
 
     const Parameters& parameters() const;
     void parameters(const Parameters& new_parameters);
@@ -137,6 +139,7 @@ inline std::string sci2(double d) { return Scientific(d,0,2); }
 inline std::string sci8(double d) { return Scientific(d,0,8); }
 inline std::string fix2(double d) { return Fixed(d,0,2); }
 inline std::string fix8(double d) { return Fixed(d,0,8); }
+inline std::string time(double d) { return Fixed(d,8,1); }
 
 // Formats @text into a line of fixed width and indentation.
 // This is used to print messages like
diff --git a/highs/ipm/ipx/ipm.cc b/highs/ipm/ipx/ipm.cc
@@ -828,9 +828,8 @@ void IPM::PrintHeader() {
     << "  " << Format("pinf", 9)
     << "  " << Format("dinf", 9)
     << "  " << Format("gap", 8);
-    //  h_logging_stream << "  " << Format("mu", 8);
   if (!control_.timelessLog())
-    h_logging_stream << "  " << Format("time", 7);
+    h_logging_stream << "   " << Format("time", 7);
   control_.hLog(h_logging_stream);
   control_.Debug()
     << "  " << Format("stepsizes", 9)
@@ -868,7 +867,7 @@ void IPM::PrintOutput() {
       << "  " << Scientific(logging_gap, 8, 2);
     //    h_logging_stream << "  " << Scientific(iterate_->mu(), 8, 2);
     if (!control_.timelessLog())
-      h_logging_stream << "  " << Fixed(control_.Elapsed(), 6, 0) << "s";
+      h_logging_stream << "  " << time(control_.Elapsed());
     control_.hLog(h_logging_stream);
     control_.Debug()
       << "  " << Fixed(step_primal_, 4, 2) << " " << Fixed(step_dual_, 4, 2)
diff --git a/highs/ipm/ipx/ipm.h b/highs/ipm/ipx/ipm.h
@@ -37,6 +37,7 @@ class IPM {
 
     Int maxiter() const { return maxiter_; }
     void maxiter(Int i) { maxiter_ = i; }
+    void PrintHeader();
 
 private:
     struct Step;
@@ -67,7 +68,6 @@ class IPM {
     void SolveNewtonSystem(const double* rb, const double* rc,
                            const double* rl, const double* ru,
                            const double* sl, const double* su, Step& lhs);
-    void PrintHeader();
     void PrintOutput();
 
     const Control& control_;
diff --git a/highs/ipm/ipx/ipx_internal.h b/highs/ipm/ipx/ipx_internal.h
@@ -21,7 +21,7 @@ struct Parameters : public ipx_parameters {
   Parameters() {
     display = 1;
     logfile = nullptr;
-    print_interval = 5.0;
+    print_interval = 60.0;
     analyse_basis_data = false;
     time_limit = -1.0;
     dualize = -1;
diff --git a/highs/ipm/ipx/lp_solver.cc b/highs/ipm/ipx/lp_solver.cc
@@ -394,7 +394,7 @@ void LpSolver::RunIPM() {
     info_.centring_success = false;
 
     if (x_start_.size() != 0) {
-      control_.hLog(" Using starting point provided by user. Skipping initial iterations.\n");
+        control_.hLog(" Using starting point provided by user. Skipping initial iterations.\n");
         iterate_->Initialize(x_start_, xl_start_, xu_start_,
                              y_start_, zl_start_, zu_start_);
     }
@@ -558,6 +558,7 @@ void LpSolver::BuildStartingBasis() {
 void LpSolver::RunMainIPM(IPM& ipm) {
     KKTSolverBasis kkt(control_, *basis_);
     Timer timer;
+    ipm.PrintHeader();
     ipm.maxiter(control_.ipm_maxiter());
     ipm.Driver(&kkt, iterate_.get(), &info_);
     info_.time_ipm2 = timer.Elapsed();
diff --git a/highs/ipm/ipx/lp_solver.h b/highs/ipm/ipx/lp_solver.h
@@ -164,6 +164,8 @@ class LpSolver {
     // Returns -1 if no basis was available and 0 otherwise.
     Int SymbolicInvert(Int* rowcounts, Int* colcounts);
 
+  void setTimerOffset(const double offset) {this->control_.setTimerOffset(offset); }
+
 private:
     void ClearSolution();
     void InteriorPointSolve();
diff --git a/highs/ipm/ipx/timer.cc b/highs/ipm/ipx/timer.cc
@@ -1,27 +1,16 @@
 #include "ipm/ipx/timer.h"
-
+#include <cstdio>
 namespace ipx {
 
-Timer::Timer() {
-    Reset();
-}
-
-double Timer::Elapsed() const {
-    return toc(t0_);
-}
-
-void Timer::Reset() {
-    t0_ = tic();
-}
-
-Timer::TimePoint Timer::tic() {
-    return std::chrono::high_resolution_clock::now();
+Timer::Timer(const double offset)
+    : offset_(offset) {
+    Reset(true);
 }
 
-double Timer::toc(TimePoint start) {
-    TimePoint end = tic();
-    std::chrono::duration<double> diff = end-start;
-    return diff.count();
+void Timer::Reset(const bool first) {
+  if (!first) offset_ -= t0_;
+  t0_ = read();
+  if (!first) offset_ += t0_;
 }
 
 }  // namespace ipx
diff --git a/highs/ipm/ipx/timer.h b/highs/ipm/ipx/timer.h
@@ -4,19 +4,20 @@
 #include <chrono>
 
 namespace ipx {
+    using namespace std::chrono;
 
 class Timer {
 public:
-    Timer();
-    double Elapsed() const;
-    void Reset();
+    Timer(const double offset=0);
+    double Elapsed() const { return toc(t0_); }
+    void Reset(const bool first = false);
 
 private:
-    typedef std::chrono::time_point<std::chrono::high_resolution_clock>
-        TimePoint;
-    static TimePoint tic();
-    static double toc(TimePoint start);
-    TimePoint t0_;
+    static double toc(double start) { return read() - start; }
+    static double read() { return duration_cast<duration<double>>(high_resolution_clock::now().time_since_epoch()).count(); }
+    double t0_;
+public:
+    double offset_;
 };
 
 }  // namespace ipx
diff --git a/highs/simplex/HighsSimplexAnalysis.cpp b/highs/simplex/HighsSimplexAnalysis.cpp
@@ -1480,7 +1480,7 @@ void HighsSimplexAnalysis::reportRunTime(const bool header,
 #ifndef NDEBUG
   *analysis_log << highsFormatToString(" %15.8gs", run_time);
 #else
-  *analysis_log << highsFormatToString(" %ds", int(run_time + 0.49));
+  *analysis_log << highsFormatToString(" %.1fs", run_time);
 #endif
 }
 

Original file line number	Diff line number	Diff line change
`@@ -13,7 +13,7 @@ Control::Control() {`
`13`	`13`	`Int Control::InterruptCheck(const Int ipm_iteration_count) const {`
`14`	`14`	`HighsTaskExecutor::getThisWorkerDeque()->checkInterrupt();`
`15`	`15`	`if (parameters_.time_limit >= 0.0 &&`
`16`		`- parameters_.time_limit < timer_.Elapsed())`
	`16`	`+ parameters_.time_limit < this->Elapsed())`
`17`	`17`	`return IPX_ERROR_time_interrupt;`
`18`	`18`	`// The pointer callback_ should not be null, since that indicates`
`19`	`19`	`// that it's not been set`
`@@ -38,7 +38,8 @@ void Control::hLog(std::string str) const {`
`38`	`38`	`} else {`
`39`	`39`	`output_ << str;`
`40`	`40`	`}`
`41`		`-`
	`41`	`+ // Reset interval-based logging since something has been logged`
	`42`	`+ interval_.Reset();`
`42`	`43`	`}`
`43`	`44`
`44`	`45`	`void Control::hLog(std::stringstream& logging) const {`
`@@ -50,9 +51,12 @@ void Control::hLog(std::stringstream& logging) const {`
`50`	`51`	`output_ << logging.str();`
`51`	`52`	`}`
`52`	`53`	`logging.str(std::string());`
	`54`	`+ // Reset interval-based logging since something has been logged`
	`55`	`+ interval_.Reset();`
`53`	`56`	`}`
`54`	`57`
`55`	`58`	`void Control::hIntervalLog(std::stringstream& logging) const {`
	`59`	`+ double interval_elapsed = interval_.Elapsed();`
`56`	`60`	`if (parameters_.print_interval >= 0.0 &&`
`57`	`61`	`interval_.Elapsed() >= parameters_.print_interval) {`
`58`	`62`	`interval_.Reset();`
`@@ -79,7 +83,7 @@ void Control::ResetPrintInterval() const {`
`79`	`83`	`}`
`80`	`84`
`81`	`85`	`double Control::Elapsed() const {`
`82`		`- return timer_.Elapsed();`
	`86`	`+ return timer_.offset_ + timer_.Elapsed();`
`83`	`87`	`}`
`84`	`88`
`85`	`89`	`const Parameters& Control::parameters() const {`