Not presolving the AC LP; cleaned up dev printing and added printf_flag to HighsTimer so that MIP timing log can be suppressed

Author: jajhall

check/TestMipSolver.cpp

@@ -1044,7 +1044,7 @@ TEST_CASE("mip-lp-solver", "[highs_test_mip_solver]") {
   std::string model_file =
       std::string(HIGHS_DIR) + "/check/instances/flugpl.mps";
   Highs h;
-  // h.setOptionValue("output_flag", dev_run);
+  h.setOptionValue("output_flag", dev_run);
   const bool just_hipo_test = false;
   if (!just_hipo_test) {
     REQUIRE(h.readModel(model_file) == HighsStatus::kOk);
@@ -1071,7 +1071,7 @@ TEST_CASE("mip-sub-solver-time", "[highs_test_mip_solver]") {
   std::string model_file =
     std::string(HIGHS_DIR) + "/check/instances/" + model + ".mps";
   Highs h;
-  //  h.setOptionValue("output_flag", dev_run);
+  h.setOptionValue("output_flag", dev_run);
   h.setOptionValue("highs_analysis_level", kHighsAnalysisLevelMipTime);
   REQUIRE(h.readModel(model_file) == HighsStatus::kOk);
 

highs/lp_data/HighsInterface.cpp

@@ -3062,6 +3062,8 @@ void Highs::restoreInfCost(HighsStatus& return_status) {
 // Modify status and info if user bound or cost scaling, or
 // primal/dual feasibility tolerances have changed
 HighsStatus Highs::optionChangeAction() {
+  this->timer_.setPrintfFlag(options_.output_flag,
+			     options_.log_to_console);
   HighsModel& model = this->model_;
   HighsLp& lp = model.lp_;
   HighsInfo& info = this->info_;

highs/lp_data/HighsOptions.cpp

@@ -437,8 +437,6 @@ OptionStatus setLocalOptionValue(const HighsLogOptions& report_log_options,
                                  std::vector<OptionRecord*>& option_records,
                                  const bool value) {
   HighsInt index;
-  //  printf("setLocalOptionValue: \"%s\" with bool %" HIGHSINT_FORMAT "\n",
-  //  name.c_str(), value);
   OptionStatus status =
       getOptionIndex(report_log_options, name, option_records, index);
   if (status != OptionStatus::kOk) return status;
@@ -459,8 +457,6 @@ OptionStatus setLocalOptionValue(const HighsLogOptions& report_log_options,
                                  std::vector<OptionRecord*>& option_records,
                                  const HighsInt value) {
   HighsInt index;
-  //  printf("setLocalOptionValue: \"%s\" with HighsInt %" HIGHSINT_FORMAT "\n",
-  //  name.c_str(), value);
   OptionStatus status =
       getOptionIndex(report_log_options, name, option_records, index);
   if (status != OptionStatus::kOk) return status;
@@ -488,8 +484,6 @@ OptionStatus setLocalOptionValue(const HighsLogOptions& report_log_options,
                                  std::vector<OptionRecord*>& option_records,
                                  const double value) {
   HighsInt index;
-  //  printf("setLocalOptionValue: \"%s\" with double %g\n", name.c_str(),
-  //  value);
   OptionStatus status =
       getOptionIndex(report_log_options, name, option_records, index);
   if (status != OptionStatus::kOk) return status;

highs/mip/HighsLpRelaxation.cpp

@@ -1115,11 +1115,11 @@ HighsLpRelaxation::Status HighsLpRelaxation::run(bool resolve_on_error) {
   bool use_simplex = !use_ipm;
   if (use_ipm) {
     assert(!valid_basis);
-    const bool ipm_logging = true;
+    const bool ipm_logging = false;
     if (ipm_logging) {
       std::string presolve;
       lpsolver.getOptionValue("presolve", presolve);
-      printf("\nHighsLpRelaxation::run Solving the root node with IPM, using presolve = %s\n", presolve.c_str());
+      printf("HighsLpRelaxation::run Solving the root node with IPM, using presolve = %s\n", presolve.c_str());
       bool output_flag;
       lpsolver.getOptionValue("output_flag", output_flag);
       assert(output_flag == false);
@@ -1129,14 +1129,17 @@ HighsLpRelaxation::Status HighsLpRelaxation::run(bool resolve_on_error) {
     const bool dump_ipm_lp = false;
     if (dump_ipm_lp && !mipsolver.submip) {
       const std::string file_name = mipsolver.model_->model_name_ + "_root.mps";
-      printf("HighsMipSolverData::startAnalyticCenterComputation: Calling lpsolver.writeModel(%s)\n", file_name.c_str());
+      printf("HighsMipSolverData::run Calling lpsolver.writeModel(%s)\n", file_name.c_str());
       lpsolver.writeModel(file_name);
       fflush(stdout);
       exit(1);
     }
     callstatus = lpsolver.run();
     if (ipm_logging) lpsolver.setOptionValue("output_flag", false);
     if (callstatus == HighsStatus::kError) {
+      highsLogDev(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
+		  "HighsLpRelaxation::run HiPO has failed : status = %s Try IPX\n",
+		  lpsolver.modelStatusToString(lpsolver.getModelStatus()).c_str());
       lpsolver.setOptionValue("solver", kSimplexString);
       use_simplex = true;
     }
@@ -1323,11 +1326,11 @@ HighsLpRelaxation::Status HighsLpRelaxation::run(bool resolve_on_error) {
         // istanbul-no-cutoff
         ipm.setOptionValue("simplex_iteration_limit",
                            info.simplex_iteration_count);
-	const bool ipm_logging = true;
+	const bool ipm_logging = false;
 	if (ipm_logging) {
 	  std::string presolve;
 	  ipm.getOptionValue("presolve", presolve);
-	  printf("\nHighsLpRelaxation::run After lpsolver reached iteration limit, solving with IPM, using presolve = %s\n", presolve.c_str());
+	  printf("HighsLpRelaxation::run After lpsolver reached iteration limit, solving with IPM, using presolve = %s\n", presolve.c_str());
 	  bool output_flag;
 	  ipm.getOptionValue("output_flag", output_flag);
 	  assert(output_flag == false);
@@ -1337,11 +1340,10 @@ HighsLpRelaxation::Status HighsLpRelaxation::run(bool resolve_on_error) {
         ipm.run();
 	if (ipm_logging) ipm.setOptionValue("output_flag", false);	
         if (use_hipo && !ipm.getBasis().valid) {
-          printf(
-              "In HighsLpRelaxation::run HiPO has failed to get a valid basis: "
-              "status = %s Try IPX\n",
-              ipm.modelStatusToString(ipm.getModelStatus()).c_str());
           // HiPO has failed to get a solution, so try IPX
+          highsLogDev(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
+              "HighsLpRelaxation::run HiPO has failed to get a valid basis: status = %s Try IPX\n",
+              ipm.modelStatusToString(ipm.getModelStatus()).c_str());
           ipm.setOptionValue("solver", kIpxString);
           ipm.run();
         }

highs/mip/HighsMipAnalysis.cpp

@@ -282,13 +282,14 @@ void HighsMipAnalysis::addSubSolverCallTime(const HighsSubSolverCallTime& sub_so
 
 void HighsMipAnalysis::checkSubSolverCallTime(const HighsSubSolverCallTime& sub_solver_call_time) {
   if (!analyse_mip_time) return;
+  const bool printf_flag = mip_clocks.timer_pointer_->printf_flag;
   bool error = false;
   auto check = [&](const HighsInt& sub_solver_clock, const HighsInt& mip_clock) {
     HighsInt sub_solver_num_call = sub_solver_call_time.num_call[sub_solver_clock];
     HighsInt mip_clock_num_call = mip_clocks.timer_pointer_->numCall(mip_clocks.clock_[mip_clock]);
     const bool ok = sub_solver_num_call == mip_clock_num_call;
     if (!ok) {
-      printf("HighsMipAnalysis::checkSubSolverCallTime: Error for %s\n", sub_solver_call_time.name[sub_solver_clock].c_str());
+      if (printf_flag) printf("HighsMipAnalysis::checkSubSolverCallTime: Error for %s\n", sub_solver_call_time.name[sub_solver_clock].c_str());
       error = true;
     }
   };
@@ -299,6 +300,6 @@ void HighsMipAnalysis::checkSubSolverCallTime(const HighsSubSolverCallTime& sub_
   check(kSubSolverHipoAc, kMipClockHipoSolveAnalyticCentreLp);
   check(kSubSolverIpxAc, kMipClockIpxSolveAnalyticCentreLp);
   check(kSubSolverSubMip, kMipClockSubMipSolve);
-  printf("\nHighsMipAnalysis::checkSubSolverCallTime: %s\n", error ? "ERROR!" : "OK");
+  if (printf_flag) printf("\nHighsMipAnalysis::checkSubSolverCallTime: %s\n", error ? "ERROR!" : "OK");
   assert(!error);
 }

highs/mip/HighsMipSolver.cpp

@@ -42,6 +42,8 @@ HighsMipSolver::HighsMipSolver(HighsCallback& callback,
       pscostinit(nullptr),
       clqtableinit(nullptr),
       implicinit(nullptr) {
+  timer_.setPrintfFlag(options_mip_->output_flag,
+		       options_mip_->log_to_console);
   assert(!submip || submip_level > 0);
   max_submip_level = 0;
   if (solution.value_valid) {

highs/mip/HighsMipSolverData.cpp

@@ -346,10 +346,11 @@ void HighsMipSolverData::startAnalyticCenterComputation(
     Highs ipm;
     ipm.setOptionValue("output_flag", false);
     const std::vector<double>& sol = ipm.getSolution().col_value;
-    // Don't use presolve - because the MIP has already been presolved?
-    const bool use_presolve = true;
-    const std::string presolve = use_presolve ? kHighsChooseString : kHighsOffString;
-    ipm.setOptionValue("presolve", presolve);
+    // Don't use presolve - because this can lead to postsolve putting
+    // integer variables onto bounds. This is not just a "less good"
+    // AC. It can have implications leading to erroneous fixing of
+    // variables and a suboptimal solution declared as optimal.
+    ipm.setOptionValue("presolve", kHighsOffString);
     // Determine the solver
     const std::string mip_ipm_solver = mipsolver.options_mip_->mip_ipm_solver;
     // Currently use HiPO by default and take action on failure
@@ -383,9 +384,6 @@ void HighsMipSolverData::startAnalyticCenterComputation(
     }
     const bool ipm_logging = false;
     if (ipm_logging) {
-      std::string presolve;
-      ipm.getOptionValue("presolve", presolve);
-      printf("\nHighsMipSolverData::startAnalyticCenterComputation Solving for the AC with IPM, using presolve = %s\n", presolve.c_str());
       bool output_flag;
       ipm.getOptionValue("output_flag", output_flag);
       assert(output_flag == false);
@@ -409,6 +407,7 @@ void HighsMipSolverData::startAnalyticCenterComputation(
       mipsolver.analysis_.addSubSolverCallTime(sub_solver_call_time, analytic_centre);
       // Go through sub_solver_call_time to update any MIP clocks
       const bool valid_basis = false;
+      const bool use_presolve = false;
       mipsolver.analysis_.mipTimerUpdate(sub_solver_call_time, valid_basis, use_presolve, analytic_centre);
     }
     if (HighsInt(sol.size()) != mipsolver.numCol()) return;

highs/mip/MipTimer.h

@@ -290,6 +290,7 @@ class MipTimer {
                           const HighsInt kMipClockIdeal = kMipClockTotal,
                           const double tolerance_percent_report_ = -1) {
     HighsTimer* timer_pointer = mip_timer_clock.timer_pointer_;
+    if (!timer_pointer->printf_flag) return false;
     const std::vector<HighsInt>& clock = mip_timer_clock.clock_;
     HighsInt mip_clock_list_size = mip_clock_list.size();
     std::vector<HighsInt> clockList;
@@ -312,6 +313,7 @@ class MipTimer {
                        const HighsInt kMipClockIdeal, const bool header,
                        const bool end_line) {
     HighsTimer* timer_pointer = mip_timer_clock.timer_pointer_;
+    if (!timer_pointer->printf_flag) return;
     const std::vector<HighsInt>& clock = mip_timer_clock.clock_;
     const double ideal_sum_time =
         timer_pointer->clock_time[clock[kMipClockIdeal]];
@@ -511,9 +513,11 @@ class MipTimer {
     csvMipClockList("csvRootNode", model_name, mip_clock_list, mip_timer_clock,
                     kMipClockEvaluateRootNode, header, end_line);
   };
+
   void reportFjClock(std::string& model,
                      const HighsTimerClock& mip_timer_clock) {
     HighsTimer* timer_pointer = mip_timer_clock.timer_pointer_;
+    if (!timer_pointer->printf_flag) return;
     HighsInt iClock = mip_timer_clock.clock_[kMipClockFeasibilityJump];
     const double fj_time = timer_pointer->read(iClock);
     const double total_time = timer_pointer->read();

highs/util/HighsTimer.h

@@ -41,6 +41,14 @@ class HighsTimer {
     presolve_clock = clock_def("Presolve");
     solve_clock = clock_def("Solve");
     postsolve_clock = clock_def("Postsolve");
+    printf_flag = true;
+  }
+
+  /**
+   * @brief Set the printf flag
+   */
+  void setPrintfFlag(const bool output_flag, const bool log_to_console) {
+    this->printf_flag = output_flag ? log_to_console : false;
   }
 
   /**
@@ -73,6 +81,7 @@ class HighsTimer {
     this->presolve_clock = clock_def("Presolve");
     this->solve_clock = clock_def("Solve");
     this->postsolve_clock = clock_def("Postsolve");
+    this->printf_flag = true;
   }
 
   /**
@@ -92,7 +101,7 @@ class HighsTimer {
   void writeAllClocks() {
     for (HighsInt i = 0; i < num_clock; i++)
       if (clock_num_call[i])
-        printf("Time %7.5f for %9d calls of clock %3d: %s\n", clock_time[i],
+        if (printf_flag) printf("Time %7.5f for %9d calls of clock %3d: %s\n", clock_time[i],
                int(clock_num_call[i]), int(i), clock_names[i].c_str());
   }
 
@@ -113,15 +122,15 @@ class HighsTimer {
       // understand this better, for now don't assert that this clock
       // has stopped
       if (!clock_stopped) {
-        printf("Clock %d - %s - still running\n", int(i_clock),
+        if (printf_flag) printf("Clock %d - %s - still running\n", int(i_clock),
                clock_names[i_clock].c_str());
       }
       assert(clock_stopped);
     }
     // Set the start to be the negation of the WallTick to check that
     // the clock's been started when it's next stopped
     if (i_clock == check_clock) {
-      printf("HighsTimer: starting clock %d: %s\n", int(check_clock),
+      if (printf_flag) printf("HighsTimer: starting clock %d: %s\n", int(check_clock),
              this->clock_names[check_clock].c_str());
     }
     clock_start[i_clock] = -getWallTime();
@@ -138,7 +147,7 @@ class HighsTimer {
     // -getWallTime() <= 0
     const bool clock_stopped = clock_start[i_clock] > 0;
     if (clock_stopped) {
-      printf("Clock %d - %s - not running\n", int(i_clock),
+      if (printf_flag) printf("Clock %d - %s - not running\n", int(i_clock),
              clock_names[i_clock].c_str());
     }
     assert(!clock_stopped);
@@ -149,7 +158,7 @@ class HighsTimer {
     // Set the start to be the WallTick to check that the clock's been
     // stopped when it's next started
     if (i_clock == check_clock) {
-      printf("HighsTimer: stopping clock %d: %s\n", int(check_clock),
+      if (printf_flag) printf("HighsTimer: stopping clock %d: %s\n", int(check_clock),
              this->clock_names[check_clock].c_str());
     }
     clock_start[i_clock] = wall_time;
@@ -164,7 +173,7 @@ class HighsTimer {
     assert(i_clock < num_clock);
     if (i_clock == check_clock) {
       std::string clock_name = this->clock_names[check_clock];
-      printf("HighsTimer: reading clock %d: %s\n", int(check_clock),
+      if (printf_flag) printf("HighsTimer: reading clock %d: %s\n", int(check_clock),
              clock_name.c_str());
     }
     double read_time;
@@ -187,7 +196,7 @@ class HighsTimer {
     assert(i_clock >= 0);
     assert(i_clock < num_clock);
     if (i_clock == check_clock) {
-      printf("HighsTimer: querying clock %d: %s - with start record %g\n",
+      if (printf_flag) printf("HighsTimer: querying clock %d: %s - with start record %g\n",
              int(check_clock), this->clock_names[check_clock].c_str(),
              clock_start[i_clock]);
     }
@@ -243,7 +252,7 @@ class HighsTimer {
     size_t num_clock_list_entries = clock_list.size();
     double current_run_highs_time = read();
     bool non_null_report = false;
-
+    if (!printf_flag) return non_null_report;
     // Check validity of the clock list and check no clocks are still
     // running, determine whether there are any times to report and
     // determine the total clock times
@@ -365,6 +374,7 @@ class HighsTimer {
   HighsInt presolve_clock;
   HighsInt solve_clock;
   HighsInt postsolve_clock;
+  bool printf_flag;
 };
 
 #endif /* UTIL_HIGHSTIMER_H_ */