From d6c619585ecae8718956a65814f49e1dfcaf2ace Mon Sep 17 00:00:00 2001 From: JAJHall Date: Fri, 24 Jan 2025 14:53:19 +0000 Subject: [PATCH] Introduced timeless_log option so logging is deterministic --- src/ipm/IpxWrapper.cpp | 1 + src/ipm/ipx/control.h | 1 + src/ipm/ipx/ipm.cc | 10 ++++---- src/ipm/ipx/ipx_parameters.h | 1 + src/ipm/ipx/lp_solver.cc | 7 +++--- src/lp_data/Highs.cpp | 17 +++++++++----- src/lp_data/HighsOptions.h | 7 ++++++ src/mip/HighsMipSolver.cpp | 32 ++++++++++++++----------- src/mip/HighsMipSolverData.cpp | 35 +++++++++++++++++----------- src/mip/HighsMipSolverData.h | 2 ++ src/presolve/HPresolve.cpp | 1 + src/simplex/HighsSimplexAnalysis.cpp | 6 +++-- src/simplex/HighsSimplexAnalysis.h | 4 ++++ 13 files changed, 82 insertions(+), 42 deletions(-) diff --git a/src/ipm/IpxWrapper.cpp b/src/ipm/IpxWrapper.cpp index 37792e5152..51f84dec04 100644 --- a/src/ipm/IpxWrapper.cpp +++ b/src/ipm/IpxWrapper.cpp @@ -85,6 +85,7 @@ HighsStatus solveLpIpx(const HighsOptions& options, HighsTimer& timer, parameters.debug = 4; } parameters.highs_logging = true; + parameters.timeless_log = options.timeless_log; parameters.log_options = &options.log_options; // Just test feasibility and optimality tolerances for now // ToDo Set more parameters diff --git a/src/ipm/ipx/control.h b/src/ipm/ipx/control.h index d322b0d383..f234cec1ce 100644 --- a/src/ipm/ipx/control.h +++ b/src/ipm/ipx/control.h @@ -91,6 +91,7 @@ class Control { double centringRatioReduction() const {return parameters_.centring_ratio_reduction; } double centringAlphaScaling() const{return parameters_.centring_alpha_scaling; } ipxint badProductsTolerance() const{return parameters_.bad_products_tolerance; } + bool timelessLog() const{return parameters_.timeless_log; } const Parameters& parameters() const; void parameters(const Parameters& new_parameters); diff --git a/src/ipm/ipx/ipm.cc b/src/ipm/ipx/ipm.cc index 4a21364951..e1a9f2ec82 100644 --- a/src/ipm/ipx/ipm.cc +++ b/src/ipm/ipx/ipm.cc @@ -825,8 +825,9 @@ void IPM::PrintHeader() { << " " << Format("Iter", 4) << " " << Format("P.res", 8) << " " << Format("D.res", 8) << " " << Format("P.obj", 15) << " " << Format("D.obj", 15) - << " " << Format("mu", 8) - << " " << Format("Time", 7); + << " " << Format("mu", 8); + if (!control_.timelessLog()) + h_logging_stream << " " << Format("Time", 7); control_.hLog(h_logging_stream); control_.Debug() << " " << Format("stepsizes", 9) @@ -850,8 +851,9 @@ void IPM::PrintOutput() { << " " << Scientific(iterate_->dresidual(), 8, 2) << " " << Scientific(iterate_->pobjective_after_postproc(), 15, 8) << " " << Scientific(iterate_->dobjective_after_postproc(), 15, 8) - << " " << Scientific(iterate_->mu(), 8, 2) - << " " << Fixed(control_.Elapsed(), 6, 0) << "s"; + << " " << Scientific(iterate_->mu(), 8, 2); + if (!control_.timelessLog()) + h_logging_stream << " " << Fixed(control_.Elapsed(), 6, 0) << "s"; control_.hLog(h_logging_stream); control_.Debug() << " " << Fixed(step_primal_, 4, 2) << " " << Fixed(step_dual_, 4, 2) diff --git a/src/ipm/ipx/ipx_parameters.h b/src/ipm/ipx/ipx_parameters.h index 2f9db89186..7bffbc992b 100644 --- a/src/ipm/ipx/ipx_parameters.h +++ b/src/ipm/ipx/ipx_parameters.h @@ -64,6 +64,7 @@ struct ipx_parameters { /* HiGHS logging parameters */ bool highs_logging; + bool timeless_log; const HighsLogOptions* log_options; }; diff --git a/src/ipm/ipx/lp_solver.cc b/src/ipm/ipx/lp_solver.cc index 2276ec4e62..52b643a57a 100644 --- a/src/ipm/ipx/lp_solver.cc +++ b/src/ipm/ipx/lp_solver.cc @@ -649,9 +649,10 @@ void LpSolver::RunCrossover() { void LpSolver::PrintSummary() { std::stringstream h_logging_stream; h_logging_stream.str(std::string()); - h_logging_stream << "Summary\n" - << Textline("Runtime:") << fix2(control_.Elapsed()) << "s\n" - << Textline("Status interior point solve:") + h_logging_stream << "Summary\n"; + if (!control_.timelessLog()) + h_logging_stream << Textline("Runtime:") << fix2(control_.Elapsed()) << "s\n"; + h_logging_stream << Textline("Status interior point solve:") << StatusString(info_.status_ipm) << '\n' << Textline("Status crossover:") << StatusString(info_.status_crossover) << '\n'; diff --git a/src/lp_data/Highs.cpp b/src/lp_data/Highs.cpp index 94ed199839..54b1773c1e 100644 --- a/src/lp_data/Highs.cpp +++ b/src/lp_data/Highs.cpp @@ -3874,10 +3874,13 @@ HighsStatus Highs::callSolveQp() { // Define the QP solver iteration logging function settings.iteration_log.subscribe([this](Statistics& stats) { int rep = stats.iteration.size() - 1; + std::string time_string = + options_.timeless_log ? "" + : highsFormatToString(" %9.2fs", stats.time[rep]); highsLogUser(options_.log_options, HighsLogType::kInfo, - "%11d %15.8g %6d %9.2fs\n", - int(stats.iteration[rep]), stats.objval[rep], - int(stats.nullspacedimension[rep]), stats.time[rep]); + "%11d %15.8g %6d%s\n", int(stats.iteration[rep]), + stats.objval[rep], int(stats.nullspacedimension[rep]), + time_string.c_str()); }); // Define the QP nullspace limit logging function @@ -4611,9 +4614,11 @@ void Highs::reportSolvedLpQpStats() { highsLogUser(log_options, HighsLogType::kInfo, "Relative P-D gap : %17.10e\n", relative_primal_dual_gap); } - double run_time = timer_.read(); - highsLogUser(log_options, HighsLogType::kInfo, - "HiGHS run time : %13.2f\n", run_time); + if (!options_.timeless_log) { + double run_time = timer_.read(); + highsLogUser(log_options, HighsLogType::kInfo, + "HiGHS run time : %13.2f\n", run_time); + } } HighsStatus Highs::crossover(const HighsSolution& user_solution) { diff --git a/src/lp_data/HighsOptions.h b/src/lp_data/HighsOptions.h index ceeabbb1cc..645a74194f 100644 --- a/src/lp_data/HighsOptions.h +++ b/src/lp_data/HighsOptions.h @@ -335,6 +335,7 @@ struct HighsOptionsStruct { // Control of HiGHS log bool output_flag; bool log_to_console; + bool timeless_log; // Options for IPM solver HighsInt ipm_iteration_limit; @@ -485,6 +486,7 @@ struct HighsOptionsStruct { write_presolved_model_file(""), output_flag(false), log_to_console(false), + timeless_log(false), ipm_iteration_limit(0), pdlp_native_termination(false), pdlp_scaling(false), @@ -847,6 +849,11 @@ class HighsOptions : public HighsOptionsStruct { advanced, &log_to_console, true); records.push_back(record_bool); + record_bool = new OptionRecordBool( + "timeless_log", "Suppression of time-based data in logging", true, + &timeless_log, false);// true); // + records.push_back(record_bool); + record_string = new OptionRecordString(kSolutionFileString, "Solution file", advanced, &solution_file, kHighsFilenameDefault); diff --git a/src/mip/HighsMipSolver.cpp b/src/mip/HighsMipSolver.cpp index f432173423..c9d1d32ba5 100644 --- a/src/mip/HighsMipSolver.cpp +++ b/src/mip/HighsMipSolver.cpp @@ -773,6 +773,7 @@ void HighsMipSolver::cleanupSolve() { gapValString.data()); } + bool timeless_log = options_mip_->timeless_log; highsLogUser(options_mip_->log_options, HighsLogType::kInfo, "\nSolving report\n"); if (this->orig_model_->model_name_.length()) @@ -783,12 +784,15 @@ void HighsMipSolver::cleanupSolve() { " Status %s\n" " Primal bound %.12g\n" " Dual bound %.12g\n" - " Gap %s\n" - " P-D integral %.12g\n" - " Solution status %s\n", + " Gap %s\n", utilModelStatusToString(modelstatus_).c_str(), primal_bound_, - dual_bound_, gapString.data(), - mipdata_->primal_dual_integral.value, solutionstatus.c_str()); + dual_bound_, gapString.data()); + if (!timeless_log) + highsLogUser(options_mip_->log_options, HighsLogType::kInfo, + " P-D integral %.12g\n", + mipdata_->primal_dual_integral.value); + highsLogUser(options_mip_->log_options, HighsLogType::kInfo, + " Solution status %s\n", solutionstatus.c_str()); if (solutionstatus != "-") highsLogUser(options_mip_->log_options, HighsLogType::kInfo, " %.12g (objective)\n" @@ -797,11 +801,16 @@ void HighsMipSolver::cleanupSolve() { " %.12g (row viol.)\n", solution_objective_, bound_violation_, integrality_violation_, row_violation_); + if (!timeless_log) + highsLogUser(options_mip_->log_options, HighsLogType::kInfo, + " Timing %.2f (total)\n" + " %.2f (presolve)\n" + " %.2f (solve)\n" + " %.2f (postsolve)\n", + timer_.read(), analysis_.mipTimerRead(kMipClockPresolve), + analysis_.mipTimerRead(kMipClockSolve), + analysis_.mipTimerRead(kMipClockPostsolve)); highsLogUser(options_mip_->log_options, HighsLogType::kInfo, - " Timing %.2f (total)\n" - " %.2f (presolve)\n" - " %.2f (solve)\n" - " %.2f (postsolve)\n" " Max sub-MIP depth %d\n" " Nodes %llu\n" " Repair LPs %llu (%llu feasible; %llu iterations)\n" @@ -809,9 +818,6 @@ void HighsMipSolver::cleanupSolve() { " %llu (strong br.)\n" " %llu (separation)\n" " %llu (heuristics)\n", - timer_.read(), analysis_.mipTimerRead(kMipClockPresolve), - analysis_.mipTimerRead(kMipClockSolve), - analysis_.mipTimerRead(kMipClockPostsolve), int(max_submip_level), (long long unsigned)mipdata_->num_nodes, (long long unsigned)mipdata_->total_repair_lp, (long long unsigned)mipdata_->total_repair_lp_feasible, @@ -821,7 +827,7 @@ void HighsMipSolver::cleanupSolve() { (long long unsigned)mipdata_->sepa_lp_iterations, (long long unsigned)mipdata_->heuristic_lp_iterations); - analysis_.reportMipTimer(); + if (!timeless_log) analysis_.reportMipTimer(); assert(modelstatus_ != HighsModelStatus::kNotset); } diff --git a/src/mip/HighsMipSolverData.cpp b/src/mip/HighsMipSolverData.cpp index 4c411f8ffc..459139d211 100644 --- a/src/mip/HighsMipSolverData.cpp +++ b/src/mip/HighsMipSolverData.cpp @@ -678,6 +678,7 @@ void HighsMipSolverData::runSetup() { const HighsLp& model = *mipsolver.model_; last_disptime = -kHighsInf; + disptime = 0; // Transform the reference of the objective limit and lower/upper // bounds from the original model to the current model, undoing the @@ -1598,21 +1599,26 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) { bool output_flag = *mipsolver.options_mip_->log_options.output_flag; if (!output_flag) return; - double time = mipsolver.timer_.read(); + bool timeless_log = mipsolver.options_mip_->timeless_log; + disptime = timeless_log ? disptime + 1 : mipsolver.timer_.read(); if (solution_source == kSolutionSourceNone && - time - last_disptime < mipsolver.options_mip_->mip_min_logging_interval) + disptime - last_disptime < + mipsolver.options_mip_->mip_min_logging_interval) return; - last_disptime = time; + last_disptime = disptime; + std::string time_string = + timeless_log ? "" : highsFormatToString(" %7.1fs", disptime); if (num_disp_lines % 20 == 0) { if (num_disp_lines == 0) printSolutionSourceKey(); - highsLogUser( - mipsolver.options_mip_->log_options, HighsLogType::kInfo, - // clang-format off - "\n Nodes | B&B Tree | Objective Bounds | Dynamic Constraints | Work \n" - "Src Proc. InQueue | Leaves Expl. | BestBound BestSol Gap | Cuts InLp Confl. | LpIters Time\n\n" - // clang-format on - ); + std::string work_string0 = timeless_log ? " Work" : " Work "; + std::string work_string1 = timeless_log ? "LpIters" : "LpIters Time"; + highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo, + // clang-format off + "\n Nodes | B&B Tree | Objective Bounds | Dynamic Constraints | %s\n" + "Src Proc. InQueue | Leaves Expl. | BestBound BestSol Gap | Cuts InLp Confl. | %s\n\n", + // clang-format on + work_string0.c_str(), work_string1.c_str()); //" %7s | %10s | %10s | %10s | %10s | %-15s | %-15s | %7s | %7s " //"| %8s | %8s\n", @@ -1656,13 +1662,13 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) { highsLogUser( mipsolver.options_mip_->log_options, HighsLogType::kInfo, // clang-format off - " %s %7s %7s %7s %6.2f%% %-15s %-15s %8s %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s %7.1fs\n", + " %s %7s %7s %7s %6.2f%% %-15s %-15s %8s %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s%s\n", // clang-format on solutionSourceToString(solution_source).c_str(), print_nodes.data(), queue_nodes.data(), print_leaves.data(), explored, lb_string.data(), ub_string.data(), gap_string.data(), cutpool.getNumCuts(), lp.numRows() - lp.getNumModelRows(), conflictPool.getNumConflicts(), - print_lp_iters.data(), time); + print_lp_iters.data(), time_string.c_str()); } else { std::array ub_string; if (mipsolver.options_mip_->objective_bound < ub) { @@ -1677,13 +1683,13 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) { highsLogUser( mipsolver.options_mip_->log_options, HighsLogType::kInfo, // clang-format off - " %s %7s %7s %7s %6.2f%% %-15s %-15s %8.2f %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s %7.1fs\n", + " %s %7s %7s %7s %6.2f%% %-15s %-15s %8.2f %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s%s\n", // clang-format on solutionSourceToString(solution_source).c_str(), print_nodes.data(), queue_nodes.data(), print_leaves.data(), explored, lb_string.data(), ub_string.data(), gap, cutpool.getNumCuts(), lp.numRows() - lp.getNumModelRows(), conflictPool.getNumConflicts(), - print_lp_iters.data(), time); + print_lp_iters.data(), time_string.c_str()); } // Check that limitsToBounds yields the same values for the // dual_bound, primal_bound (modulo optimization sense) and @@ -1960,6 +1966,7 @@ void HighsMipSolverData::evaluateRootNode() { // make sure first line after solving root LP is printed last_disptime = -kHighsInf; + disptime = 0; mipsolver.analysis_.mipTimerStart(kMipClockRandomizedRounding1); heuristics.randomizedRounding(firstlpsol); diff --git a/src/mip/HighsMipSolverData.h b/src/mip/HighsMipSolverData.h index 080016b9a9..8678751e45 100644 --- a/src/mip/HighsMipSolverData.h +++ b/src/mip/HighsMipSolverData.h @@ -118,6 +118,7 @@ struct HighsMipSolverData { HighsCDouble pruned_treeweight; double avgrootlpiters; + double disptime; double last_disptime; int64_t firstrootlpiters; int64_t num_nodes; @@ -183,6 +184,7 @@ struct HighsMipSolverData { maxTreeSizeLog2(0), pruned_treeweight(0), avgrootlpiters(0.0), + disptime(0.0), last_disptime(0.0), firstrootlpiters(0), num_nodes(0), diff --git a/src/presolve/HPresolve.cpp b/src/presolve/HPresolve.cpp index 6c72a06046..e4d35935db 100644 --- a/src/presolve/HPresolve.cpp +++ b/src/presolve/HPresolve.cpp @@ -4098,6 +4098,7 @@ HPresolve::Result HPresolve::presolve(HighsPostsolveStack& postsolve_stack) { #else std::string time_str = " " + std::to_string(int(run_time)) + "s"; #endif + if (options->timeless_log) time_str = ""; highsLogUser(options->log_options, HighsLogType::kInfo, "%" HIGHSINT_FORMAT " rows, %" HIGHSINT_FORMAT " cols, %" HIGHSINT_FORMAT " nonzeros %s\n", diff --git a/src/simplex/HighsSimplexAnalysis.cpp b/src/simplex/HighsSimplexAnalysis.cpp index 9b4a474ac0..e876194396 100644 --- a/src/simplex/HighsSimplexAnalysis.cpp +++ b/src/simplex/HighsSimplexAnalysis.cpp @@ -36,6 +36,7 @@ void HighsSimplexAnalysis::setup(const std::string lp_name, const HighsLp& lp, kHighsAnalysisLevelNlaData & options.highs_analysis_level; analyse_simplex_data = analyse_simplex_summary_data || analyse_simplex_runtime_data; + highs_run_time = 0; last_user_log_time = -kHighsInf; delta_user_log_time = 5e0; @@ -54,6 +55,7 @@ void HighsSimplexAnalysis::setup(const std::string lp_name, const HighsLp& lp, // AnIterNumCostlyDseIt = 0; // Copy messaging parameter from options messaging(options.log_options); + timeless_log = options.timeless_log; // Initialise the densities col_aq_density = 0; row_ep_density = 0; @@ -380,13 +382,13 @@ void HighsSimplexAnalysis::userInvertReport(const bool force) { void HighsSimplexAnalysis::userInvertReport(const bool header, const bool force) { - const double highs_run_time = timer_->read(); + highs_run_time = timeless_log ? highs_run_time + 1 : timer_->read(); if (!force && highs_run_time < last_user_log_time + delta_user_log_time) return; analysis_log = std::unique_ptr(new std::stringstream()); reportIterationObjective(header); reportInfeasibility(header); - reportRunTime(header, highs_run_time); + if (!timeless_log) reportRunTime(header, highs_run_time); highsLogUser(log_options, HighsLogType::kInfo, "%s\n", analysis_log->str().c_str()); if (!header) last_user_log_time = highs_run_time; diff --git a/src/simplex/HighsSimplexAnalysis.h b/src/simplex/HighsSimplexAnalysis.h index 34802614f3..94a0292a67 100644 --- a/src/simplex/HighsSimplexAnalysis.h +++ b/src/simplex/HighsSimplexAnalysis.h @@ -152,8 +152,10 @@ class HighsSimplexAnalysis { max_sum_average_log_extreme_dual_steepest_edge_weight_error(0.0), num_invert_report_since_last_header(-1), num_iteration_report_since_last_header(-1), + highs_run_time(0.0), last_user_log_time(-kHighsInf), delta_user_log_time(1e0), + timeless_log(false), average_concurrency(0.0), average_fraction_of_possible_minor_iterations_performed(0.0), sum_multi_chosen(0), @@ -428,8 +430,10 @@ class HighsSimplexAnalysis { HighsInt num_invert_report_since_last_header; HighsInt num_iteration_report_since_last_header; + double highs_run_time; double last_user_log_time; double delta_user_log_time; + bool timeless_log; double average_concurrency; double average_fraction_of_possible_minor_iterations_performed;