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 2e6b491ade..3da151d73a 100644 --- a/src/lp_data/Highs.cpp +++ b/src/lp_data/Highs.cpp @@ -3875,10 +3875,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 @@ -4613,9 +4616,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..1a0b927f63 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); + 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 7e54b36c44..e1aa17c63d 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..868737a629 100644 --- a/src/mip/HighsMipSolverData.cpp +++ b/src/mip/HighsMipSolverData.cpp @@ -372,10 +372,9 @@ void HighsMipSolverData::finishAnalyticCenterComputation( } if (nfixed > 0) highsLogDev(mipsolver.options_mip_->log_options, HighsLogType::kInfo, - "Fixing %" HIGHSINT_FORMAT " columns (%" HIGHSINT_FORMAT - " integers) sitting at bound at " + "Fixing %d columns (%d integers) sitting at bound at " "analytic center\n", - nfixed, nintfixed); + int(nfixed), int(nintfixed)); mipsolver.mipdata_->domain.propagate(); if (mipsolver.mipdata_->domain.infeasible()) return; } @@ -406,9 +405,12 @@ void HighsMipSolverData::finishSymmetryDetection( taskGroup.sync(); symmetries = std::move(symData->symmetries); + std::string symmetry_time = + mipsolver.options_mip_->timeless_log + ? "" + : highsFormatToString(" %.1fs", symData->detectionTime); highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo, - "\nSymmetry detection completed in %.1fs\n", - symData->detectionTime); + "\nSymmetry detection completed in%s\n", symmetry_time.c_str()); if (symmetries.numGenerators == 0) { detectSymmetries = false; @@ -416,24 +418,20 @@ void HighsMipSolverData::finishSymmetryDetection( "No symmetry present\n\n"); } else if (symmetries.orbitopes.size() == 0) { highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo, - "Found %" HIGHSINT_FORMAT " generator(s)\n\n", - symmetries.numGenerators); + "Found %d generator(s)\n\n", int(symmetries.numGenerators)); } else { if (symmetries.numPerms != 0) { - highsLogUser( - mipsolver.options_mip_->log_options, HighsLogType::kInfo, - "Found %" HIGHSINT_FORMAT " generator(s) and %" HIGHSINT_FORMAT - " full orbitope(s) acting on %" HIGHSINT_FORMAT " columns\n\n", - symmetries.numPerms, (HighsInt)symmetries.orbitopes.size(), - (HighsInt)symmetries.columnToOrbitope.size()); + highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo, + "Found %d generator(s) and %d full orbitope(s) acting on %d " + "columns\n\n", + int(symmetries.numPerms), int(symmetries.orbitopes.size()), + int(symmetries.columnToOrbitope.size())); } else { highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo, - "Found %" HIGHSINT_FORMAT - " full orbitope(s) acting on %" HIGHSINT_FORMAT - " columns\n\n", - (HighsInt)symmetries.orbitopes.size(), - (HighsInt)symmetries.columnToOrbitope.size()); + "Found %d full orbitope(s) acting on %d columns\n\n", + int(symmetries.orbitopes.size()), + int(symmetries.columnToOrbitope.size())); } } symData.reset(); @@ -678,6 +676,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 +1597,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 +1660,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 +1681,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 +1964,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 99d06d7323..5391fa01c9 100644 --- a/src/presolve/HPresolve.cpp +++ b/src/presolve/HPresolve.cpp @@ -4093,6 +4093,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;