diff --git a/cpp/src/branch_and_bound/branch_and_bound.cpp b/cpp/src/branch_and_bound/branch_and_bound.cpp index 806f2850ce..a17bc6716c 100644 --- a/cpp/src/branch_and_bound/branch_and_bound.cpp +++ b/cpp/src/branch_and_bound/branch_and_bound.cpp @@ -213,34 +213,22 @@ f_t compute_user_abs_gap(const lp_problem_t& lp, f_t obj_value, f_t lo return gap; } -template -f_t user_relative_gap(const lp_problem_t& lp, f_t obj_value, f_t lower_bound) +template +f_t user_relative_gap(f_t user_obj, f_t user_lower_bound) { - f_t user_obj = compute_user_objective(lp, obj_value); - f_t user_lower_bound = compute_user_objective(lp, lower_bound); - f_t user_mip_gap = user_obj == 0.0 - ? (user_lower_bound == 0.0 ? 0.0 : std::numeric_limits::infinity()) - : compute_user_abs_gap(lp, obj_value, lower_bound) / std::abs(user_obj); + f_t user_mip_gap = user_obj == 0.0 + ? (user_lower_bound == 0.0 ? 0.0 : std::numeric_limits::infinity()) + : std::abs(user_obj - user_lower_bound) / std::abs(user_obj); if (std::isnan(user_mip_gap)) { return std::numeric_limits::infinity(); } return user_mip_gap; } -template -std::string user_mip_gap(const lp_problem_t& lp, f_t obj_value, f_t lower_bound) +template +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::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::infinity()) return "-"; + if (value > 1e-3) { return std::format("{:5.1f}%", value * 100); } + return std::format("{:5.2f}%", value * 100); } } // namespace @@ -331,29 +319,58 @@ void branch_and_bound_t::set_initial_upper_bound(f_t bound) upper_bound_ = bound; } +template +void branch_and_bound_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 void branch_and_bound_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(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(user_obj, user_lower); + 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(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_obj = compute_user_objective(original_lp_, obj); + f_t user_lower = compute_user_objective(original_lp_, root_lp_current_lower_bound_.load()); + f_t user_gap = user_relative_gap(user_obj, user_lower); + 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", @@ -374,34 +391,23 @@ void branch_and_bound_t::report( const f_t user_lower = compute_user_objective(original_lp_, lower_bound); const f_t iters = static_cast(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(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(user_obj, user_lower); + 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 @@ -736,36 +742,33 @@ void branch_and_bound_t::set_final_solution(mip_solution_t& settings_.heuristic_preemption_callback(); } - f_t obj = compute_user_objective(original_lp_, upper_bound_.load()); + f_t user_obj = compute_user_objective(original_lp_, upper_bound_.load()); f_t user_bound = compute_user_objective(original_lp_, lower_bound); - f_t gap = std::abs(obj - user_bound); - f_t gap_rel = user_relative_gap(original_lp_, upper_bound_.load(), lower_bound); + f_t gap = std::abs(user_obj - user_bound); + f_t gap_rel = user_relative_gap(user_obj, user_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; @@ -791,7 +794,6 @@ void branch_and_bound_t::set_final_solution(mip_solution_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(); @@ -1532,7 +1534,7 @@ dual_status_t branch_and_bound_t::solve_node_lp( worker->leaf_edge_norms); if (lp_status == dual_status_t::NUMERICAL) { - log.debug("Numerical issue node %d. Resolving from scratch.\n", node_ptr->node_id); + log.debug_format("Numerical issue node {}. Resolving from scratch.\n", node_ptr->node_id); lp_status_t second_status = solve_linear_program_with_advanced_basis(worker->leaf_problem, lp_start_time, @@ -1577,7 +1579,9 @@ void branch_and_bound_t::plunge_with(bfs_worker_t* worker, f_t lower_bound = get_lower_bound(); f_t upper_bound = upper_bound_; - f_t rel_gap = user_relative_gap(original_lp_, upper_bound, lower_bound); + f_t user_obj = compute_user_objective(original_lp_, upper_bound); + f_t user_lower = compute_user_objective(original_lp_, lower_bound); + f_t rel_gap = user_relative_gap(user_obj, user_lower); f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound, lower_bound); while (stack.size() > 0 && (solver_status_ == mip_status_t::UNSET && is_running_) && @@ -1709,7 +1713,9 @@ void branch_and_bound_t::plunge_with(bfs_worker_t* worker, lower_bound = get_lower_bound(); upper_bound = upper_bound_; - rel_gap = user_relative_gap(original_lp_, upper_bound, lower_bound); + user_obj = compute_user_objective(original_lp_, upper_bound); + user_lower = compute_user_objective(original_lp_, lower_bound); + rel_gap = user_relative_gap(user_obj, user_lower); abs_gap = compute_user_abs_gap(original_lp_, upper_bound, lower_bound); } @@ -1778,8 +1784,10 @@ template void branch_and_bound_t::best_first_search_with(bfs_worker_t* worker) { f_t lower_bound = get_lower_bound(); + f_t user_obj = compute_user_objective(original_lp_, upper_bound_.load()); + f_t user_lower = compute_user_objective(original_lp_, lower_bound); f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound_.load(), lower_bound); - f_t rel_gap = user_relative_gap(original_lp_, upper_bound_.load(), lower_bound); + f_t rel_gap = user_relative_gap(user_obj, user_lower); f_t steal_chance = settings_.bnb_steal_chance >= 0 ? settings_.bnb_steal_chance : MIP_DEFAULT_STEAL_CHANCE; node_queue_t& node_queue = worker->node_queue; @@ -1840,8 +1848,10 @@ void branch_and_bound_t::best_first_search_with(bfs_worker_t plunge_with(worker, start_node); lower_bound = get_lower_bound(); + user_obj = compute_user_objective(original_lp_, upper_bound_.load()); + user_lower = compute_user_objective(original_lp_, lower_bound); abs_gap = compute_user_abs_gap(original_lp_, upper_bound_.load(), lower_bound); - rel_gap = user_relative_gap(original_lp_, upper_bound_.load(), lower_bound); + rel_gap = user_relative_gap(user_obj, user_lower); if (abs_gap <= settings_.absolute_mip_gap_tol || rel_gap <= settings_.relative_mip_gap_tol) { node_concurrent_halt_ = 1; @@ -1894,7 +1904,9 @@ void branch_and_bound_t::dive_with(diving_worker_t* worker) f_t lower_bound = get_lower_bound(); f_t upper_bound = upper_bound_; - f_t rel_gap = user_relative_gap(original_lp_, upper_bound, lower_bound); + f_t user_obj = compute_user_objective(original_lp_, upper_bound); + f_t user_lower = compute_user_objective(original_lp_, lower_bound); + f_t rel_gap = user_relative_gap(user_obj, user_lower); f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound, lower_bound); while (stack.size() > 0 && (solver_status_ == mip_status_t::UNSET && is_running_) && @@ -1950,7 +1962,9 @@ void branch_and_bound_t::dive_with(diving_worker_t* worker) lower_bound = get_lower_bound(); upper_bound = upper_bound_; - rel_gap = user_relative_gap(original_lp_, upper_bound, lower_bound); + user_obj = compute_user_objective(original_lp_, upper_bound); + user_lower = compute_user_objective(original_lp_, lower_bound); + rel_gap = user_relative_gap(user_obj, user_lower); abs_gap = compute_user_abs_gap(original_lp_, upper_bound, lower_bound); } @@ -2029,11 +2043,6 @@ lp_status_t branch_and_bound_t::solve_root_relaxation( std::vector& nonbasic_list, std::vector& edge_norms) { - f_t start_time = tic(); - f_t user_objective = 0; - i_t iter = 0; - std::string solver_name = ""; - lp_status_t root_status; // Launch a task for solving the root LP relaxation via dual simplex. @@ -2140,40 +2149,18 @@ lp_status_t branch_and_bound_t::solve_root_relaxation( // Set the edge norms to a default value edge_norms.resize(original_lp_.num_cols, -1.0); set_uninitialized_steepest_edge_norms(original_lp_, basic_list, edge_norms); - user_objective = root_crossover_soln_.user_objective; - iter = root_crossover_soln_.iterations; - solver_name = method_to_string(root_relax_solved_by); } else { // Wait for the dual simplex to finish (after telling PDLP/Barrier to stop) #pragma omp taskwait depend(in : root_status) - user_objective = root_relax_soln_.user_objective; - iter = root_relax_soln_.iterations; root_relax_solved_by = DualSimplex; - solver_name = "Dual Simplex"; } } else { // Wait for the dual simplex to finish (crossover do not produced a solution) #pragma omp taskwait depend(in : root_status) - user_objective = root_relax_soln_.user_objective; - iter = root_relax_soln_.iterations; root_relax_solved_by = DualSimplex; - solver_name = "Dual Simplex"; } - settings_.log.printf("\n"); - if (root_status == lp_status_t::OPTIMAL) { - settings_.log.printf("Root relaxation solution found in %d iterations and %.2fs by %s\n", - iter, - toc(start_time), - solver_name.c_str()); - settings_.log.printf("Root relaxation objective %+.8e\n", user_objective); - } else { - settings_.log.printf("Root relaxation returned: %s\n", - simplex::lp_status_to_string(root_status).c_str()); - } - - settings_.log.printf("\n"); is_root_solution_set = true; return root_status; @@ -2438,8 +2425,10 @@ auto branch_and_bound_t::do_cut_pass( f_t obj = upper_bound_.load(); report(' ', obj, root_objective_, 0, num_fractional); - f_t rel_gap = user_relative_gap(original_lp_, upper_bound_.load(), root_objective_); - f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound_.load(), root_objective_); + f_t user_obj = compute_user_objective(original_lp_, upper_bound_.load()); + f_t user_lower = compute_user_objective(original_lp_, root_objective_); + f_t rel_gap = user_relative_gap(user_obj, user_lower); + f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound_.load(), root_objective_); if (rel_gap < settings_.relative_mip_gap_tol || abs_gap < settings_.absolute_mip_gap_tol) { if (num_fractional == 0) { set_solution_at_root(solution, cut_info); } set_final_solution(solution, root_objective_); @@ -2476,8 +2465,8 @@ mip_status_t branch_and_bound_t::solve(mip_solution_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 variable_bounds( original_lp_, settings_, var_types_, Arow_, new_slacks_); @@ -2539,6 +2528,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut lp_status_t root_status; solving_root_relaxation_ = true; + f_t root_relax_start_time = tic(); if (!enable_concurrent_lp_root_solve()) { // RINS/SUBMIP path settings_.log.printf("\nSolving LP root relaxation with dual simplex\n"); @@ -2551,6 +2541,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut nonbasic_list, root_vstatus_, edge_norms_); + } else { settings_.log.printf("\nSolving LP root relaxation in concurrent mode\n"); root_status = solve_root_relaxation(lp_settings, @@ -2563,16 +2554,20 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut } solving_root_relaxation_ = false; exploration_stats_.total_lp_iters = root_relax_soln_.iterations; - exploration_stats_.total_lp_solve_time = toc(exploration_stats_.start_time); + f_t root_relax_elapsed_time = toc(root_relax_start_time); + exploration_stats_.total_lp_solve_time = root_relax_elapsed_time; if (root_status == lp_status_t::INFEASIBLE) { - settings_.log.printf("MIP Infeasible\n"); + settings_.log.printf("\nThe root LP relaxation is infeasible\n", + lp_status_to_string(root_status).c_str()); signal_extend_cliques_.store(true, std::memory_order_release); #pragma omp taskwait depend(in : *clique_signal) return mip_status_t::INFEASIBLE; } + if (root_status == lp_status_t::UNBOUNDED) { - settings_.log.printf("MIP Unbounded\n"); + settings_.log.printf("\nThe root relaxation is unbounded\n", + lp_status_to_string(root_status).c_str()); if (settings_.heuristic_preemption_callback != nullptr) { settings_.heuristic_preemption_callback(); } @@ -2580,7 +2575,9 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut #pragma omp taskwait depend(in : *clique_signal) return mip_status_t::UNBOUNDED; } + if (root_status == lp_status_t::TIME_LIMIT) { + settings_.log.printf("\n"); solver_status_ = mip_status_t::TIME_LIMIT; set_final_solution(solution, -inf); signal_extend_cliques_.store(true, std::memory_order_release); @@ -2589,6 +2586,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut } if (root_status == lp_status_t::WORK_LIMIT) { + settings_.log.printf("\n"); solver_status_ = mip_status_t::WORK_LIMIT; set_final_solution(solution, -inf); signal_extend_cliques_.store(true, std::memory_order_release); @@ -2597,6 +2595,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut } if (root_status == lp_status_t::NUMERICAL_ISSUES) { + settings_.log.printf("\n"); solver_status_ = mip_status_t::NUMERICAL; set_final_solution(solution, -inf); signal_extend_cliques_.store(true, std::memory_order_release); @@ -2604,6 +2603,14 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut return solver_status_; } + assert(root_status == lp_status_t::OPTIMAL); + settings_.log.print_format( + "\nRoot relaxation solution found in {} iterations and {:.2f}s by {}\n", + root_relax_soln_.iterations, + root_relax_elapsed_time, + method_to_string(root_relax_solved_by)); + settings_.log.printf("Root relaxation objective %+.8e\n\n", root_relax_soln_.user_objective); + assert(root_vstatus_.size() == original_lp_.num_cols); set_uninitialized_steepest_edge_norms(original_lp_, basic_list, edge_norms_); @@ -2644,11 +2651,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_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 cut_pool(original_lp_.num_cols, settings_); cut_generation_t cut_generation(cut_pool, @@ -2802,6 +2805,8 @@ mip_status_t branch_and_bound_t::solve(mip_solution_t& solut original_lp_.num_rows, original_lp_.num_cols, original_lp_.A.col_start[original_lp_.A.n]); + } else { + settings_.log.printf("\n"); } if (enable_root_cut_cpufj && cut_info.has_cuts()) { @@ -2943,16 +2948,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_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 { @@ -2985,6 +2981,7 @@ mip_status_t branch_and_bound_t::solve(mip_solution_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; @@ -3423,8 +3420,10 @@ void branch_and_bound_t::deterministic_sync_callback() f_t lower_bound = deterministic_compute_lower_bound(); f_t upper_bound = upper_bound_.load(); + f_t user_obj = compute_user_objective(original_lp_, upper_bound); + f_t user_lower = compute_user_objective(original_lp_, lower_bound); f_t abs_gap = compute_user_abs_gap(original_lp_, upper_bound, lower_bound); - f_t rel_gap = user_relative_gap(original_lp_, upper_bound, lower_bound); + f_t rel_gap = user_relative_gap(user_obj, user_lower); // Apply limit-based statuses first so a definitive answer (gap closure or tree exhaustion) // detected in the same callback can override them. Otherwise a long producer wait that @@ -3464,9 +3463,8 @@ void branch_and_bound_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(original_lp_, upper_bound, lower_bound); + f_t user_gap = user_relative_gap(user_obj, user_lower); + std::string user_gap_text = to_percentage(user_gap); std::string idle_workers; i_t idle_count = 0; @@ -3480,9 +3478,9 @@ void branch_and_bound_t::deterministic_sync_callback() deterministic_current_horizon_, exploration_stats_.nodes_explored, exploration_stats_.nodes_unexplored, - obj, + user_obj, user_lower, - gap_user.c_str(), + user_gap_text.c_str(), toc(exploration_stats_.start_time), state_hash, idle_workers.empty() ? "" : " ", @@ -3568,7 +3566,8 @@ node_status_t branch_and_bound_t::solve_node_deterministic( &worker.work_context); if (lp_status == dual_status_t::NUMERICAL) { - settings_.log.printf("Numerical issue node %d. Resolving from scratch.\n", node_ptr->node_id); + settings_.log.print_format("Numerical issue node {}. Resolving from scratch.\n", + node_ptr->node_id); lp_status_t second_status = solve_linear_program_with_advanced_basis(worker.leaf_problem, lp_start_time, lp_settings, diff --git a/cpp/src/branch_and_bound/branch_and_bound.hpp b/cpp/src/branch_and_bound/branch_and_bound.hpp index 2d503fa4ad..18eb38de66 100644 --- a/cpp/src/branch_and_bound/branch_and_bound.hpp +++ b/cpp/src/branch_and_bound/branch_and_bound.hpp @@ -261,6 +261,7 @@ class branch_and_bound_t { omp_atomic_t lower_bound_numerical_; std::function user_bound_callback_; + void print_table_header(); void report_heuristic(f_t obj); void report(char symbol, f_t obj, diff --git a/cpp/src/branch_and_bound/symmetry.hpp b/cpp/src/branch_and_bound/symmetry.hpp index 45426a9fa8..1848b3dad8 100644 --- a/cpp/src/branch_and_bound/symmetry.hpp +++ b/cpp/src/branch_and_bound/symmetry.hpp @@ -684,6 +684,8 @@ std::unique_ptr> detect_symmetry( const simplex::simplex_solver_settings_t& settings, bool& has_symmetry) { + settings.log.printf("\nRunning symmetry detection...\n"); + has_symmetry = false; f_t start_time = simplex::tic(); diff --git a/cpp/src/cuts/cuts.cpp b/cpp/src/cuts/cuts.cpp index 2cc041d81a..40efbe6185 100644 --- a/cpp/src/cuts/cuts.cpp +++ b/cpp/src/cuts/cuts.cpp @@ -3610,6 +3610,8 @@ variable_bounds_t::variable_bounds_t(const lp_problem_t& lp, } f_t start_time = tic(); + settings.log.printf("Computing variable bounds..."); + std::vector num_integer_in_row(lp.num_rows, 0); // Construct the slack map @@ -3780,8 +3782,9 @@ variable_bounds_t::variable_bounds_t(const lp_problem_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.print_format("{} variable upper bounds in {:.2f}s\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; @@ -3871,8 +3874,9 @@ variable_bounds_t::variable_bounds_t(const lp_problem_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.print_format("{} variable lower bounds in {:.2f}s\n", lower_edges, toc(start_time)); } template diff --git a/cpp/src/dual_simplex/logger.hpp b/cpp/src/dual_simplex/logger.hpp index c35712fc26..d1688da2a0 100644 --- a/cpp/src/dual_simplex/logger.hpp +++ b/cpp/src/dual_simplex/logger.hpp @@ -16,6 +16,8 @@ #include #include #include +#include +#include namespace cuopt::mathematical_optimization::simplex { @@ -84,6 +86,29 @@ class logger_t { } } + template + void print_format(std::format_string fmt, Args&&... args) + { + if (log) { + std::string msg = std::format(fmt, std::forward(args)...); + if (log_to_console) { +#ifdef CUOPT_LOG_ACTIVE_LEVEL + std::string msg_no_newline = msg; + if (msg_no_newline.size() > 0 && msg.ends_with("\n")) { msg_no_newline.pop_back(); } + + CUOPT_LOG_INFO("%s%s", log_prefix.c_str(), msg_no_newline.c_str()); +#else + std::printf("%s", msg.c_str()); + fflush(stdout); +#endif + } + if (log_to_file && log_file != nullptr) { + std::fprintf(log_file, "%s", msg.c_str()); + fflush(log_file); + } + } + } + void debug([[maybe_unused]] const char* fmt, ...) { if (log) { @@ -118,6 +143,28 @@ class logger_t { } } + template + void debug_format(std::format_string fmt, Args&&... args) + { + if (log) { + std::string msg = std::format(fmt, std::forward(args)...); + if (log_to_console) { +#ifdef CUOPT_LOG_DEBUG + std::string msg_no_newline = msg; + if (msg_no_newline.size() > 0 && msg.ends_with("\n")) { msg_no_newline.pop_back(); } + CUOPT_LOG_TRACE("%s%s", log_prefix.c_str(), msg_no_newline.c_str()); +#else + std::printf("%s", msg.c_str()); + fflush(stdout); +#endif + } + if (log_to_file && log_file != nullptr) { + std::fprintf(log_file, "%s", msg.c_str()); + fflush(log_file); + } + } + } + bool log; bool log_to_console; std::string log_prefix; diff --git a/cpp/src/mip_heuristics/diversity/diversity_manager.cu b/cpp/src/mip_heuristics/diversity/diversity_manager.cu index e90c96d8e4..50b8ccab02 100644 --- a/cpp/src/mip_heuristics/diversity/diversity_manager.cu +++ b/cpp/src/mip_heuristics/diversity/diversity_manager.cu @@ -223,7 +223,7 @@ template bool diversity_manager_t::run_presolve(f_t time_limit, timer_t global_timer) { raft::common::nvtx::range fun_scope("run_presolve"); - CUOPT_LOG_INFO("Starting cuOpt presolve"); + CUOPT_LOG_INFO("\nRunning cuOpt presolve"); timer_t presolve_timer(time_limit); auto term_crit = ls.constraint_prop.bounds_update.solve(*problem_ptr); diff --git a/cpp/src/mip_heuristics/presolve/third_party_presolve.cpp b/cpp/src/mip_heuristics/presolve/third_party_presolve.cpp index d842d2c9ef..08bd7779a0 100644 --- a/cpp/src/mip_heuristics/presolve/third_party_presolve.cpp +++ b/cpp/src/mip_heuristics/presolve/third_party_presolve.cpp @@ -683,12 +683,12 @@ third_party_presolve_result_t third_party_presolve_t::apply( papilo::Problem papilo_problem = build_papilo_problem(op_problem, category, maximize_); - CUOPT_LOG_INFO("Original problem: %d constraints, %d variables, %d nonzeros", - papilo_problem.getNRows(), - papilo_problem.getNCols(), - papilo_problem.getConstraintMatrix().getNnz()); + CUOPT_LOG_DEBUG("Original problem: %d constraints, %d variables, %d nonzeros", + papilo_problem.getNRows(), + papilo_problem.getNCols(), + papilo_problem.getConstraintMatrix().getNnz()); - CUOPT_LOG_INFO("Calling Papilo presolver (git hash %s)", PAPILO_GITHASH); + CUOPT_LOG_INFO("\nRunning Papilo presolve (git hash %s)", PAPILO_GITHASH); if (category == problem_category_t::MIP) { dual_postsolve = false; } papilo::Presolve papilo_presolver; set_presolve_methods(papilo_presolver, category, dual_postsolve); @@ -735,7 +735,7 @@ third_party_presolve_result_t third_party_presolve_t::apply( // Check if presolve found the optimal solution (problem fully reduced) if (papilo_problem.getNRows() == 0 && papilo_problem.getNCols() == 0) { - CUOPT_LOG_INFO("Optimal solution found during presolve"); + status = third_party_presolve_status_t::OPTIMAL; } auto opt_problem = build_optimization_problem( diff --git a/cpp/src/mip_heuristics/solve.cu b/cpp/src/mip_heuristics/solve.cu index 891c7c3a8b..a7cb4884e4 100644 --- a/cpp/src/mip_heuristics/solve.cu +++ b/cpp/src/mip_heuristics/solve.cu @@ -149,7 +149,6 @@ mip_solution_t run_mip_solver( auto stats = solver_stats_t{}; stats.set_solution_bound(solution.get_user_objective()); // log the objective for scripts which need it - CUOPT_LOG_INFO("Best feasible: %f", solution.get_user_objective()); for (auto callback : settings.get_mip_callbacks()) { if (callback->get_type() == internals::base_solution_callback_type::GET_SOLUTION) { auto temp_sol(solution); @@ -593,6 +592,10 @@ mip_solution_t solve_mip_helper(optimization_problem_t& op_p CUOPT_LOG_INFO("%d implied integers", presolve_result_opt->implied_integer_indices.size()); } CUOPT_LOG_INFO("Papilo presolve time: %.2f", presolve_time); + + if (result.status == mip::third_party_presolve_status_t::OPTIMAL) { + CUOPT_LOG_INFO("Optimal solution found during presolve."); + } } // Stop early GPU FJ now that Papilo presolve is complete @@ -747,10 +750,7 @@ mip_solution_t solve_mip_helper(optimization_problem_t& op_p } } - if (sol.get_termination_status() == mip_termination_status_t::FeasibleFound || - sol.get_termination_status() == mip_termination_status_t::Optimal) { - sol.log_detailed_summary(); - } + sol.log_detailed_summary(); if (settings.sol_file != "") { CUOPT_LOG_INFO("Writing solution to file %s", settings.sol_file.c_str()); diff --git a/cpp/src/mip_heuristics/solver.cu b/cpp/src/mip_heuristics/solver.cu index 0ede00964a..bac04cb053 100644 --- a/cpp/src/mip_heuristics/solver.cu +++ b/cpp/src/mip_heuristics/solver.cu @@ -183,7 +183,7 @@ void extract_probing_implied_bounds(const problem_t& op_problem, } } - CUOPT_LOG_INFO("Probing implied bounds: %d zero entries, %d one entries", zero_nnz, one_nnz); + CUOPT_LOG_INFO("\nProbing implied bounds: %d zero entries, %d one entries", zero_nnz, one_nnz); } template diff --git a/cpp/src/mip_heuristics/solver_solution.cu b/cpp/src/mip_heuristics/solver_solution.cu index 7782260dd5..5b59e9a0fa 100644 --- a/cpp/src/mip_heuristics/solver_solution.cu +++ b/cpp/src/mip_heuristics/solver_solution.cu @@ -238,21 +238,39 @@ void mip_solution_t::log_summary() const template void mip_solution_t::log_detailed_summary() const { - CUOPT_LOG_INFO( - "Solution objective: %f , relative_mip_gap %f solution_bound %f presolve_time %f " - "total_solve_time %f " - "max constraint violation %f max int violation %f max var bounds violation %f " - "nodes %d simplex_iterations %d", - objective_, - mip_gap_, - stats_.get_solution_bound(), - stats_.presolve_time, - stats_.total_solve_time, - max_constraint_violation_, - max_int_violation_, - max_variable_bound_violation_, - stats_.num_nodes, - stats_.num_simplex_iterations); + switch (termination_status_) { + case mip_termination_status_t::Optimal: + case mip_termination_status_t::FeasibleFound: + CUOPT_LOG_INFO("%s\n", + std::format("Best objective {:.6e}, best bound {:.6e}, gap {:.2f}%.", + objective_, + stats_.get_solution_bound(), + mip_gap_ * 100) + .c_str()); + break; + + case mip_termination_status_t::Infeasible: + CUOPT_LOG_INFO("Problem has no integer feasible solution.\n"); + break; + + case mip_termination_status_t::TimeLimit: + CUOPT_LOG_INFO("No feasible solution was found within the time limit.\n"); + break; + + case mip_termination_status_t::WorkLimit: + CUOPT_LOG_INFO("No feasible solution was found within the work limit.\n"); + break; + + case mip_termination_status_t::Unbounded: CUOPT_LOG_INFO("The problem is unbounded.\n"); break; + + case mip_termination_status_t::UnboundedOrInfeasible: + CUOPT_LOG_INFO("The problem is unbounded or infeasible.\n"); + break; + + case mip_termination_status_t::NoTermination: + CUOPT_LOG_INFO("Warning: The solver did not terminate successfully.\n"); + break; + } } #if MIP_INSTANTIATE_FLOAT || PDLP_INSTANTIATE_FLOAT diff --git a/python/cuopt/cuopt/tests/linear_programming/test_cpu_only_execution.py b/python/cuopt/cuopt/tests/linear_programming/test_cpu_only_execution.py index 4453d38bcc..07ae224ef9 100644 --- a/python/cuopt/cuopt/tests/linear_programming/test_cpu_only_execution.py +++ b/python/cuopt/cuopt/tests/linear_programming/test_cpu_only_execution.py @@ -120,9 +120,9 @@ def _parse_cli_output(output): result["status"] = "Optimal" continue - # MIP solution: "Solution objective: 2.000000 , ..." + # MIP solution: "Best objective 2.000000 , ..." m = re.match( - r"Solution objective:\s*([+-]?\d+\.?\d*(?:[eE][+-]?\d+)?)", + r"Best objective \s*([+-]?\d+\.?\d*(?:[eE][+-]?\d+)?)", stripped, ) if m: diff --git a/python/libcuopt/libcuopt/tests/test_cli.sh b/python/libcuopt/libcuopt/tests/test_cli.sh index 85f73fa58f..51c0397e74 100644 --- a/python/libcuopt/libcuopt/tests/test_cli.sh +++ b/python/libcuopt/libcuopt/tests/test_cli.sh @@ -30,4 +30,4 @@ cuopt_cli "${RAPIDS_DATASET_ROOT_DIR}"/linear_programming/good-mps-1.lp.bz2 | gr # Add a for mixed integer programming test with options -cuopt_cli "${RAPIDS_DATASET_ROOT_DIR}"/mip/sample.mps --mip-absolute-gap 0.01 --time-limit 10 | grep -q "Solution objective" || (echo "Expected solution objective not found" && exit 1) +cuopt_cli "${RAPIDS_DATASET_ROOT_DIR}"/mip/sample.mps --mip-absolute-gap 0.01 --time-limit 10 | grep -q "Best objective" || (echo "Expected solution objective not found" && exit 1)