Merge pull request #2865 from ERGO-Code/fix-2860

jajhall · web-flow · commit b174cc9340f1 · 2026-02-24T14:14:58.000Z
Add logging and time budget for probing in presolve, and increase visibility of presolve rule switch-off
diff --git a/FEATURES.md b/FEATURES.md
@@ -25,5 +25,9 @@ HiPO is now capable of solving convex QP problems. Option
 solver="qpasm" selects the previous active-set QP solver, while
 solver="hipo" or solver="ipm" selects the HiPO solver.
 
+Following PR [#2865](https://github.com/ERGO-Code/HiGHS/pull/2865),
+HiGHS performs logging during probing in MIP presolve and checks for
+time-out
+
 ## Build changes
 
diff --git a/check/TestPresolve.cpp b/check/TestPresolve.cpp
@@ -863,3 +863,40 @@ TEST_CASE("dual-bound-tightening", "[highs_test_presolve]") {
   highs.passModel(lp);
   REQUIRE(highs.presolve() == HighsStatus::kOk);
 }
+
+TEST_CASE("presolve-rule-off", "[highs_test_presolve]") {
+  std::string model = "afiro";
+  std::string model_file =
+      std::string(HIGHS_DIR) + "/check/instances/" + model + ".mps";
+  Highs h;
+  h.setOptionValue("output_flag", dev_run);
+  h.readModel(model_file);
+  h.setOptionValue("log_dev_level", 1);
+  h.setOptionValue("presolve_rule_logging", true);
+  HighsInt full_presolve_num_col, full_presolve_num_row;
+  // Run presolve with and without aggregator
+  for (HighsInt k = 0; k < 2; k++) {
+    h.presolve();
+    if (k == 0) {
+      full_presolve_num_col = h.getPresolvedLp().num_col_;
+      full_presolve_num_row = h.getPresolvedLp().num_row_;
+      if (dev_run)
+        printf("Presolved %s has num_col = %d; num_row = %d\n", model.c_str(),
+               int(full_presolve_num_col), int(full_presolve_num_row));
+      HighsPresolveLog presolve_log = h.getPresolveLog();
+      REQUIRE(presolve_log.rule[kPresolveRuleAggregator].col_removed > 0);
+      HighsInt presolve_rule_off =
+          std::pow(int(2), int(kPresolveRuleAggregator));
+      h.setOptionValue("presolve_rule_off", presolve_rule_off);
+    } else if (k > 0) {
+      HighsInt presolve_num_col = h.getPresolvedLp().num_col_;
+      HighsInt presolve_num_row = h.getPresolvedLp().num_row_;
+      REQUIRE(presolve_num_col > full_presolve_num_col);
+      REQUIRE(presolve_num_row > full_presolve_num_row);
+      if (dev_run)
+        printf("Presolved %s has num_col = %d; num_row = %d\n", model.c_str(),
+               int(presolve_num_col), int(presolve_num_row));
+    }
+  }
+  h.resetGlobalScheduler(true);
+}
diff --git a/highs/io/HighsIO.cpp b/highs/io/HighsIO.cpp
@@ -303,6 +303,19 @@ const std::string highsBoolToString(const bool b, const HighsInt field_width) {
   return b ? " true" : "false";
 }
 
+const std::string highsTimeToString(const double time) {
+  return
+#ifndef NDEBUG
+      std::to_string(time);
+#else
+      std::to_string(static_cast<int>(time));
+#endif
+}
+
+const std::string highsTimeSecondToString(const double time) {
+  return highsTimeToString(time) + "s";
+}
+
 const std::string highsInsertMdEscapes(const std::string& from_string) {
   std::string to_string = "";
   const char* underscore = "_";
diff --git a/highs/io/HighsIO.h b/highs/io/HighsIO.h
@@ -108,5 +108,6 @@ const std::string highsBoolToString(const bool b,
 
 const std::string highsInsertMdEscapes(const std::string& from_string);
 const std::string highsInsertMdId(const std::string& from_string);
-
+const std::string highsTimeToString(const double time);
+const std::string highsTimeSecondToString(const double time);
 #endif
diff --git a/highs/presolve/HPresolve.cpp b/highs/presolve/HPresolve.cpp
@@ -1683,12 +1683,74 @@ HPresolve::Result HPresolve::runProbing(HighsPostsolveStack& postsolve_stack) {
       };
     }
 
+    // Set up logging for probing
+    const bool silent = silentLog();
+    HighsInt iBin = -1;
+    HighsInt iBin_probed = -1;
+    HighsInt num_binary = binaries.size();
+    double tt = this->timer->read();
+    double tt0 = tt;
+    double log_tt = tt0;
+    HighsInt log_iBin_probed = iBin_probed;
+    auto probingLog = [&]() {
+      if (silent || options->timeless_log) return;
+      // Ensure that enough time has elapsed, and at least on binary
+      // has been probed
+      const double log_tt_interval = 5.0;
+      if (tt > log_tt + log_tt_interval && iBin_probed > log_iBin_probed) {
+        // Get the average rate from the start of probing
+        assert(iBin_probed > 0);
+        double rate0 = (tt - tt0) / double(iBin_probed);
+        // Get the average rate since last logging
+        HighsInt dl_iBin_probed = iBin_probed - log_iBin_probed;
+        assert(dl_iBin_probed > 0);
+        double rate1 = (tt - log_tt) / double(dl_iBin_probed);
+        // Assess the time for probing based on the greater rate
+        double rate = std::max(rate0, rate1);
+        std::string rate_str =
+            " (rate " + highsTimeToString(1e3 * rate) + "/ms";
+        double expected_probing_finish_time =
+            tt + rate * (num_binary - iBin_probed);
+        std::string expected_probing_finish_time_str =
+            " => expected probing finish time " +
+            highsTimeSecondToString(expected_probing_finish_time) + ")";
+        std::string time_str = highsTimeSecondToString(tt);
+        highsLogUser(options->log_options, HighsLogType::kInfo,
+                     "   Considered %d / %d binaries; %d probed %s%s %s\n",
+                     int(iBin), int(num_binary), int(iBin_probed),
+                     rate_str.c_str(), expected_probing_finish_time_str.c_str(),
+                     time_str.c_str());
+        log_tt = tt;
+        log_iBin_probed = iBin_probed;
+      }
+    };
+
     for (const auto& binvar : binaries) {
-      HighsInt i = std::get<3>(binvar);
+      // Count the binaries considered
+      iBin++;
 
+      HighsInt i = std::get<3>(binvar);
       if (cliquetable.getSubstitution(i) != nullptr || !domain.isBinary(i))
         continue;
 
+      // Count the binaries probed
+      iBin_probed++;
+
+      // Check for timeout
+      tt = this->timer->read();
+      if (tt > options->time_limit) {
+        highsLogUser(options->log_options, HighsLogType::kInfo,
+                     "Time limit reached in probing: "
+                     "consider not using probing by setting option "
+                     "presolve_rule_off to 2^%-d = %d\n",
+                     int(kPresolveRuleProbing),
+                     int(std::pow(int(2), int(kPresolveRuleProbing))));
+        return Result::kStopped;
+      }
+
+      // Possibly log probing
+      probingLog();
+
       bool tightenLimits = (numProbed - oldNumProbed) >= 2500;
 
       // when a large percentage of columns have been deleted, stop this round
@@ -1761,9 +1823,6 @@ HPresolve::Result HPresolve::runProbing(HighsPostsolveStack& postsolve_stack) {
       if (numLiftOpps >= maxNumLiftOpps)
         implications.storeLiftingOpportunity = nullptr;
 
-      // printf("nprobed: %" HIGHSINT_FORMAT ", numCliques: %" HIGHSINT_FORMAT
-      // "\n", nprobed,
-      //       cliquetable.numCliques());
       if (domain.infeasible()) {
         mipsolver->analysis_.mipTimerStop(kMipClockProbingPresolve);
         return Result::kPrimalInfeasible;
@@ -5468,31 +5527,29 @@ HPresolve::Result HPresolve::presolve(HighsPostsolveStack& postsolve_stack) {
     model->sense_ = ObjSense::kMinimize;
   }
 
+  const bool silent = silentLog();
+  if (options->presolve != kHighsOffString) {
+    if (!silent)
+      highsLogUser(options->log_options, HighsLogType::kInfo,
+                   "Presolving model\n");
+  }
   // Set up the logic to allow presolve rules, and logging for their
   // effectiveness
   analysis_.setup(this->model, this->options, this->numDeletedRows,
-                  this->numDeletedCols);
+                  this->numDeletedCols, silent);
 
   if (options->presolve != kHighsOffString) {
     if (mipsolver) mipsolver->mipdata_->cliquetable.setPresolveFlag(true);
-    if (!mipsolver || mipsolver->mipdata_->numRestarts == 0)
-      highsLogUser(options->log_options, HighsLogType::kInfo,
-                   "Presolving model\n");
 
     auto report = [&]() {
-      if (!mipsolver || mipsolver->mipdata_->numRestarts == 0) {
+      if (!silent) {
         HighsInt numCol = model->num_col_ - numDeletedCols;
         HighsInt numRow = model->num_row_ - numDeletedRows;
         HighsInt numNonz =
             static_cast<HighsInt>(Avalue.size() - freeslots.size());
         // Only read the run time if it's to be printed
         const double run_time = options->output_flag ? this->timer->read() : 0;
-#ifndef NDEBUG
-        std::string time_str = " " + std::to_string(run_time) + "s";
-#else
-        std::string time_str =
-            " " + std::to_string(static_cast<int>(run_time)) + "s";
-#endif
+        std::string time_str = highsTimeSecondToString(run_time);
         if (options->timeless_log) time_str = "";
         highsLogUser(options->log_options, HighsLogType::kInfo,
                      "%" HIGHSINT_FORMAT " rows, %" HIGHSINT_FORMAT
@@ -5972,6 +6029,10 @@ HighsCDouble HPresolve::computeDynamism(
          static_cast<HighsCDouble>(minAbsCoef);
 }
 
+bool HPresolve::silentLog() const {
+  return mipsolver && mipsolver->mipdata_->numRestarts > 0;
+}
+
 HighsModelStatus HPresolve::run(HighsPostsolveStack& postsolve_stack) {
   presolve_status_ = HighsPresolveStatus::kNotSet;
   shrinkProblemEnabled = true;
@@ -6171,28 +6232,31 @@ HPresolve::Result HPresolve::removeDependentEquations(
   const double time_limit =
       std::max(1.0, std::min(0.01 * options->time_limit, 1000.0));
   factor.setTimeLimit(time_limit);
+  const bool silent = silentLog();
   // Determine rank deficiency of the equations
-  highsLogUser(options->log_options, HighsLogType::kInfo,
-               "Dependent equations search running on %d equations with time "
-               "limit of %.2fs\n",
-               static_cast<int>(matrix.num_col_), time_limit);
+  if (!silent)
+    highsLogUser(options->log_options, HighsLogType::kInfo,
+                 "Dependent equations search running on %d equations with time "
+                 "limit of %.2fs\n",
+                 static_cast<int>(matrix.num_col_), time_limit);
   double time_taken = -this->timer->read();
   HighsInt build_return = factor.build();
   time_taken += this->timer->read();
   if (build_return == kBuildKernelReturnTimeout) {
     // HFactor::build has timed out, so just return
-    highsLogUser(options->log_options, HighsLogType::kInfo,
-                 "Dependent equations search terminated after %.3gs due to "
-                 "expected time exceeding limit\n",
-                 time_taken);
+    if (!silent)
+      highsLogUser(options->log_options, HighsLogType::kInfo,
+                   "Dependent equations search terminated after %.3gs due to "
+                   "expected time exceeding limit\n",
+                   time_taken);
     analysis_.logging_on_ = logging_on;
     if (logging_on)
       analysis_.stopPresolveRuleLog(kPresolveRuleDependentFreeCols);
     return Result::kOk;
   } else {
     double pct_off_timeout =
         1e2 * std::fabs(time_taken - time_limit) / time_limit;
-    if (pct_off_timeout < 1.0)
+    if (!silent && pct_off_timeout < 1.0)
       highsLogUser(options->log_options, HighsLogType::kWarning,
                    "Dependent equations search finished within %.2f%% of limit "
                    "of %.2fs: "
@@ -6217,11 +6281,12 @@ HPresolve::Result HPresolve::removeDependentEquations(
       num_fictitious_rows_skipped++;
     }
   }
-  highsLogUser(options->log_options, HighsLogType::kInfo,
-               "Dependent equations search removed %d rows and %d nonzeros "
-               "in %.2fs (limit = %.2fs)\n",
-               static_cast<int>(num_removed_row),
-               static_cast<int>(num_removed_nz), time_taken, time_limit);
+  if (!silent)
+    highsLogUser(options->log_options, HighsLogType::kInfo,
+                 "Dependent equations search removed %d rows and %d nonzeros "
+                 "in %.2fs (limit = %.2fs)\n",
+                 static_cast<int>(num_removed_row),
+                 static_cast<int>(num_removed_nz), time_taken, time_limit);
   if (num_fictitious_rows_skipped)
     highsLogDev(options->log_options, HighsLogType::kInfo,
                 ", avoiding %d fictitious rows",
diff --git a/highs/presolve/HPresolve.h b/highs/presolve/HPresolve.h
@@ -348,6 +348,8 @@ class HPresolve {
   template <typename storageFormat>
   HighsCDouble computeDynamism(const HighsMatrixSlice<storageFormat>& vector);
 
+  bool silentLog() const;
+
  public:
   // for LP presolve
   bool okSetInput(HighsLp& model_, const HighsOptions& options_,
diff --git a/highs/presolve/HPresolveAnalysis.cpp b/highs/presolve/HPresolveAnalysis.cpp
diff --git a/highs/presolve/HPresolveAnalysis.h b/highs/presolve/HPresolveAnalysis.h
