MIP log cleanup

cpp/include/cuopt/linear_programming/mip/solver_stats.hpp

@@ -9,7 +9,6 @@
 #include <atomic>
 #include <limits>
 namespace cuopt::linear_programming {
-
 template <typename i_t, typename f_t>
 struct solver_stats_t {
   // Direction-neutral placeholder; solver_context initializes based on maximize/minimize.

cpp/src/branch_and_bound/branch_and_bound.cpp

@@ -197,22 +197,12 @@ f_t user_relative_gap(const lp_problem_t<i_t, f_t>& lp, f_t obj_value, f_t lower
   return user_mip_gap;
 }
 
-template <typename i_t, typename f_t>
-std::string user_mip_gap(const lp_problem_t<i_t, f_t>& lp, f_t obj_value, f_t lower_bound)
+template <typename f_t>
+std::string to_percentage(f_t value)
 {
-  const f_t user_mip_gap = user_relative_gap(lp, obj_value, lower_bound);
-  if (user_mip_gap == std::numeric_limits<f_t>::infinity()) {
-    return "   -  ";
-  } else {
-    constexpr int BUFFER_LEN = 32;
-    char buffer[BUFFER_LEN];
-    if (user_mip_gap > 1e-3) {
-      snprintf(buffer, BUFFER_LEN - 1, "%5.1f%%", user_mip_gap * 100);
-    } else {
-      snprintf(buffer, BUFFER_LEN - 1, "%5.2f%%", user_mip_gap * 100);
-    }
-    return std::string(buffer);
-  }
+  if (value == std::numeric_limits<f_t>::infinity()) return "---";
+  if (value > 1e-3) { return std::format("{:5.1f}%", value * 100); }
+  return std::format("{:5.2f}%", value * 100);
 }
 
 }  // namespace
@@ -302,29 +292,57 @@ void branch_and_bound_t<i_t, f_t>::set_initial_upper_bound(f_t bound)
   upper_bound_ = bound;
 }
 
+template <typename i_t, typename f_t>
+void branch_and_bound_t<i_t, f_t>::print_table_header()
+{
+  std::string header = std::format("{:^1}|{:^12}|{:^12}|{:^19}|{:^15}|{:^8}|{:^7}|{:^11}|{:^11}|",
+                                   "",
+                                   "Explored",
+                                   "Unexplored",
+                                   "Objective",
+                                   "Bound",
+                                   "IntInf",
+                                   "Depth",
+                                   "Iter/Node",
+                                   "Gap");
+  if (settings_.deterministic) { header += std::format("{:^8}|", "Work"); }
+  header += std::format("{:^8}|", "Time");
+  settings_.log.printf("%s\n", header.c_str());
+}
+
 template <typename i_t, typename f_t>
 void branch_and_bound_t<i_t, f_t>::report_heuristic(f_t obj)
 {
   if (is_running_) {
-    f_t user_obj         = compute_user_objective(original_lp_, obj);
-    f_t user_lower       = compute_user_objective(original_lp_, get_lower_bound());
-    std::string user_gap = user_mip_gap<i_t, f_t>(original_lp_, obj, get_lower_bound());
-
-    settings_.log.printf(
-      "H                            %+13.6e    %+10.6e                               %s %9.2f\n",
-      user_obj,
-      user_lower,
-      user_gap.c_str(),
-      toc(exploration_stats_.start_time));
+    f_t lower_bound           = get_lower_bound();
+    f_t user_obj              = compute_user_objective(original_lp_, obj);
+    f_t user_lower            = compute_user_objective(original_lp_, lower_bound);
+    f_t user_gap              = user_relative_gap(original_lp_, obj, lower_bound);
+    std::string user_gap_text = to_percentage(user_gap);
+
+    std::string log_line =
+      std::format("H {:>12} {:>12} {:^+19.6e} {:^+15.6e} {:>8} {:>7} {:^11} {:^11}",
+                  "",  // nodes explored
+                  "",  // nodes unexplored
+                  user_obj,
+                  user_lower,
+                  "",  // integer infeasible
+                  "",  // depth
+                  "",  // iter/node
+                  user_gap_text);
+
+    if (settings_.deterministic) { log_line += std::format("{:^8}", ""); }
+    log_line += std::format(" {:>8.2f}", toc(exploration_stats_.start_time));
+    settings_.log.printf("%s\n", log_line.c_str());
   } else {
     if (solving_root_relaxation_.load()) {
       f_t user_obj = compute_user_objective(original_lp_, obj);
-      std::string user_gap =
-        user_mip_gap<i_t, f_t>(original_lp_, obj, root_lp_current_lower_bound_.load());
-      settings_.log.printf(
-        "New solution from primal heuristics. Objective %+.6e. Gap %s. Time %.2f\n",
+      f_t user_gap = user_relative_gap(original_lp_, obj, root_lp_current_lower_bound_.load());
+      std::string user_gap_text = to_percentage(user_gap);
+      settings_.log.print_format(
+        "New solution from primal heuristics. Objective {:+.6e}. Gap {}. Time {:.2f}\n",
         user_obj,
-        user_gap.c_str(),
+        user_gap_text,
         toc(exploration_stats_.start_time));
     } else {
       settings_.log.printf("New solution from primal heuristics. Objective %+.6e. Time %.2f\n",
@@ -345,34 +363,23 @@ void branch_and_bound_t<i_t, f_t>::report(
   const f_t user_lower       = compute_user_objective(original_lp_, lower_bound);
   const f_t iters            = static_cast<f_t>(exploration_stats_.total_lp_iters);
   const f_t iter_node        = nodes_explored > 0 ? iters / nodes_explored : iters;
-  const std::string user_gap = user_mip_gap<i_t, f_t>(original_lp_, obj, lower_bound);
-  if (work_time >= 0) {
-    settings_.log.printf(
-      "%c %10d   %10lu    %+13.6e    %+10.6e   %6d %6d   %7.1e     %s %9.2f %9.2f\n",
-      symbol,
-      nodes_explored,
-      nodes_unexplored,
-      user_obj,
-      user_lower,
-      node_int_infeas,
-      node_depth,
-      iter_node,
-      user_gap.c_str(),
-      work_time,
-      toc(exploration_stats_.start_time));
-  } else {
-    settings_.log.printf("%c %10d   %10lu    %+13.6e    %+10.6e   %6d %6d   %7.1e     %s %9.2f\n",
-                         symbol,
-                         nodes_explored,
-                         nodes_unexplored,
-                         user_obj,
-                         user_lower,
-                         node_int_infeas,
-                         node_depth,
-                         iter_node,
-                         user_gap.c_str(),
-                         toc(exploration_stats_.start_time));
-  }
+  f_t user_gap               = user_relative_gap(original_lp_, obj, lower_bound);
+  std::string user_gap_text  = to_percentage(user_gap);
+
+  std::string log_line =
+    std::format("{:^1} {:>12} {:>12} {:^+19.6e} {:^+15.6e} {:>8} {:>7} {:^11.1e} {:^11}",
+                symbol,
+                nodes_explored,
+                nodes_unexplored,
+                user_obj,
+                user_lower,
+                node_int_infeas,
+                node_depth,
+                iter_node,
+                user_gap_text);
+  if (work_time >= 0) { log_line += std::format(" {:>8.2f}", work_time); }
+  log_line += std::format(" {:>8.2f}", toc(exploration_stats_.start_time));
+  settings_.log.printf("%s\n", log_line.c_str());
 }
 
 template <typename i_t, typename f_t>
@@ -713,30 +720,27 @@ void branch_and_bound_t<i_t, f_t>::set_final_solution(mip_solution_t<i_t, f_t>&
   f_t gap_rel          = user_relative_gap(original_lp_, upper_bound_.load(), lower_bound);
   bool is_maximization = original_lp_.obj_scale < 0.0;
 
-  settings_.log.printf("Explored %d nodes in %.2fs.\n",
-                       exploration_stats_.nodes_explored,
-                       toc(exploration_stats_.start_time));
+  settings_.log.print_format("Explored {} nodes ({} simplex iterations) in {:.2f}s.",
+                             exploration_stats_.nodes_explored.load(),
+                             exploration_stats_.total_lp_iters.load(),
+                             toc(exploration_stats_.start_time));
+
   if (exploration_stats_.orbital_fixing_nodes.load() > 0 ||
       exploration_stats_.orbital_conflict_nodes.load() > 0) {
-    settings_.log.printf(
-      "Orbital fixing applied at %lld nodes, %lld total variable fixings, "
-      "%lld nodes with conflicting orbits\n",
-      (long long)exploration_stats_.orbital_fixing_nodes.load(),
-      (long long)exploration_stats_.orbital_fixings_applied.load(),
-      (long long)exploration_stats_.orbital_conflict_nodes.load());
+    settings_.log.print_format(
+      "Orbital fixing applied at {} nodes, {} total variable fixings, "
+      "{} nodes with conflicting orbits\n",
+      exploration_stats_.orbital_fixing_nodes.load(),
+      exploration_stats_.orbital_fixings_applied.load(),
+      exploration_stats_.orbital_conflict_nodes.load());
   }
   if (exploration_stats_.lexical_reduction_nodes.load() > 0) {
-    settings_.log.printf(
-      "Lexical reduction applied at %lld nodes, %lld total variable fixings, %lld nodes pruned\n",
-      (long long)exploration_stats_.lexical_reduction_nodes.load(),
-      (long long)exploration_stats_.lexical_reduction_fixings_applied.load(),
-      (long long)exploration_stats_.lexical_reduction_pruned_nodes.load());
+    settings_.log.print_format(
+      "Lexical reduction applied at {} nodes, {} total variable fixings, {} nodes pruned\n",
+      exploration_stats_.lexical_reduction_nodes.load(),
+      exploration_stats_.lexical_reduction_fixings_applied.load(),
+      exploration_stats_.lexical_reduction_pruned_nodes.load());
   }
-  settings_.log.printf("Absolute Gap %e Objective %.16e %s Bound %.16e\n",
-                       gap,
-                       obj,
-                       is_maximization ? "Upper" : "Lower",
-                       user_bound);
 
   if (gap <= settings_.absolute_mip_gap_tol || gap_rel <= settings_.relative_mip_gap_tol) {
     solver_status_ = mip_status_t::OPTIMAL;
@@ -762,7 +766,6 @@ void branch_and_bound_t<i_t, f_t>::set_final_solution(mip_solution_t<i_t, f_t>&
   if (solver_status_ == mip_status_t::UNSET) {
     if (exploration_stats_.nodes_explored > 0 && exploration_stats_.nodes_unexplored == 0 &&
         upper_bound_ == inf) {
-      settings_.log.printf("Integer infeasible.\n");
       solver_status_ = mip_status_t::INFEASIBLE;
       if (settings_.heuristic_preemption_callback != nullptr) {
         settings_.heuristic_preemption_callback();
@@ -2115,8 +2118,7 @@ lp_status_t branch_and_bound_t<i_t, f_t>::solve_root_relaxation(
                          solver_name.c_str());
     settings_.log.printf("Root relaxation objective %+.8e\n", user_objective);
   } else {
-    settings_.log.printf("Root relaxation returned: %s\n",
-                         lp_status_to_string(root_status).c_str());
+    settings_.log.debug_format("Root relaxation returned: {}", lp_status_to_string(root_status));
   }
 
   settings_.log.printf("\n");
@@ -2422,8 +2424,8 @@ mip_status_t branch_and_bound_t<i_t, f_t>::solve(mip_solution_t<i_t, f_t>& solut
   exploration_stats_.nodes_explored   = 0;
   original_lp_.A.to_compressed_row(Arow_);
 
-  settings_.log.printf("Reduced cost strengthening enabled: %d\n",
-                       settings_.reduced_cost_strengthening);
+  settings_.log.debug("Reduced cost strengthening enabled: %d\n",
+                      settings_.reduced_cost_strengthening);
 
   variable_bounds_t<i_t, f_t> variable_bounds(
     original_lp_, settings_, var_types_, Arow_, new_slacks_);
@@ -2497,6 +2499,17 @@ mip_status_t branch_and_bound_t<i_t, f_t>::solve(mip_solution_t<i_t, f_t>& solut
                                                            nonbasic_list,
                                                            root_vstatus_,
                                                            edge_norms_);
+    if (root_status == lp_status_t::OPTIMAL) {
+      settings_.log.printf("\n");
+      settings_.log.printf(
+        "Root relaxation solution found in %d iterations and %.2fs by Dual Simplex\n",
+        root_relax_soln_.iterations,
+        toc(exploration_stats_.start_time));
+      settings_.log.printf("Root relaxation objective %+.8e\n",
+                           compute_user_objective(original_lp_, root_relax_soln_.x));
+      settings_.log.printf("\n");
+    }
+
   } else {
     settings_.log.printf("\nSolving LP root relaxation in concurrent mode\n");
     root_status = solve_root_relaxation(lp_settings,
@@ -2590,11 +2603,7 @@ mip_status_t branch_and_bound_t<i_t, f_t>::solve(mip_solution_t<i_t, f_t>& solut
   is_running_            = true;
   lower_bound_numerical_ = inf;
 
-  if (num_fractional != 0 && settings_.max_cut_passes > 0) {
-    settings_.log.printf(
-      " | Explored | Unexplored |    Objective    |     Bound     | IntInf | Depth | Iter/Node | "
-      "Gap    |  Time  |\n");
-  }
+  if (num_fractional != 0 && settings_.max_cut_passes > 0) { print_table_header(); }
 
   cut_pool_t<i_t, f_t> cut_pool(original_lp_.num_cols, settings_);
   cut_generation_t<i_t, f_t> cut_generation(cut_pool,
@@ -2889,16 +2898,7 @@ mip_status_t branch_and_bound_t<i_t, f_t>::solve(mip_solution_t<i_t, f_t>& solut
   if (settings_.diving_settings.coefficient_diving != 0) {
     calculate_variable_locks(original_lp_, var_up_locks_, var_down_locks_);
   }
-
-  if (settings_.deterministic) {
-    settings_.log.printf(
-      " | Explored | Unexplored |    Objective    |     Bound     | IntInf | Depth | Iter/Node "
-      "|   Gap    |  Work |  Time  |\n");
-  } else {
-    settings_.log.printf(
-      " | Explored | Unexplored |    Objective    |     Bound     | IntInf | Depth | Iter/Node "
-      "|   Gap    |  Time  |\n");
-  }
+  print_table_header();
 
 #pragma omp taskgroup
   {
@@ -2931,6 +2931,7 @@ mip_status_t branch_and_bound_t<i_t, f_t>::solve(mip_solution_t<i_t, f_t>& solut
   }  // Implicit barrier for all tasks created within the group (RINS, B&B workers)
 
   is_running_ = false;
+  settings_.log.printf("\n");
 
   // Compute final lower bound
   f_t lower_bound;
@@ -3410,9 +3411,10 @@ void branch_and_bound_t<i_t, f_t>::deterministic_sync_callback()
     exploration_stats_.last_log = tic();
   }
 
-  f_t obj              = compute_user_objective(original_lp_, upper_bound);
-  f_t user_lower       = compute_user_objective(original_lp_, lower_bound);
-  std::string gap_user = user_mip_gap<i_t, f_t>(original_lp_, upper_bound, lower_bound);
+  f_t obj                   = compute_user_objective(original_lp_, upper_bound);
+  f_t user_lower            = compute_user_objective(original_lp_, lower_bound);
+  f_t user_gap              = user_relative_gap(original_lp_, upper_bound, lower_bound);
+  std::string user_gap_text = to_percentage(user_gap);
 
   std::string idle_workers;
   i_t idle_count = 0;
@@ -3428,7 +3430,7 @@ void branch_and_bound_t<i_t, f_t>::deterministic_sync_callback()
                        exploration_stats_.nodes_unexplored,
                        obj,
                        user_lower,
-                       gap_user.c_str(),
+                       user_gap_text.c_str(),
                        toc(exploration_stats_.start_time),
                        state_hash,
                        idle_workers.empty() ? "" : " ",

cpp/src/branch_and_bound/branch_and_bound.hpp

@@ -263,6 +263,7 @@ class branch_and_bound_t {
   omp_atomic_t<f_t> lower_bound_numerical_;
   std::function<void(f_t)> user_bound_callback_;
 
+  void print_table_header();
   void report_heuristic(f_t obj);
   void report(char symbol,
               f_t obj,

cpp/src/branch_and_bound/symmetry.hpp

@@ -684,6 +684,8 @@ std::unique_ptr<mip_symmetry_t<i_t, f_t>> detect_symmetry(
   const simplex_solver_settings_t<i_t, f_t>& settings,
   bool& has_symmetry)
 {
+  settings.log.printf("\nRunning symmetry detection...\n");
+
   has_symmetry = false;
 
   f_t start_time = tic();

cpp/src/cuts/cuts.cpp

@@ -3592,6 +3592,8 @@ variable_bounds_t<i_t, f_t>::variable_bounds_t(const lp_problem_t<i_t, f_t>& lp,
   }
   f_t start_time = tic();
 
+  settings.log.debug("Computing variable bounds...");
+
   std::vector<i_t> num_integer_in_row(lp.num_rows, 0);
 
   // Construct the slack map
@@ -3763,7 +3765,7 @@ variable_bounds_t<i_t, f_t>::variable_bounds_t(const lp_problem_t<i_t, f_t>& lp,
     }
   }
   upper_offsets[lp.num_cols] = upper_edges;
-  settings.log.printf("%d variable upper bounds in %.2f seconds\n", upper_edges, toc(start_time));
+  settings.log.debug("%d variable upper bounds in %.2f seconds\n", upper_edges, toc(start_time));
 
   // Now go through all continuous variables and use the activiites to get lower variable bounds
   i_t lower_edges = 0;
@@ -3854,7 +3856,7 @@ variable_bounds_t<i_t, f_t>::variable_bounds_t(const lp_problem_t<i_t, f_t>& lp,
     }
   }
   lower_offsets[lp.num_cols] = lower_edges;
-  settings.log.printf("%d variable lower bounds in %.2f seconds\n", lower_edges, toc(start_time));
+  settings.log.debug("%d variable lower bounds in %.2f seconds\n", lower_edges, toc(start_time));
 }
 
 template <typename i_t, typename f_t>