Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduced timeless_log option so logging is deterministic #2147

Merged
merged 6 commits into from
Jan 30, 2025
Merged

Introduced timeless_log option so logging is deterministic #2147

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
d6c6195
Introduced timeless_log option so logging is deterministic
jajhall Jan 24, 2025
51ac785
Formatted
jajhall Jan 24, 2025
50efb41
Omitted time from symmetry announcement when timelss_log is true
jajhall Jan 25, 2025
5b4f9c0
Formatted
jajhall Jan 25, 2025
5eb7867
Set correct default for timelss_log
jajhall Jan 25, 2025
7c0620a
Merge branch 'latest' into no-time-reporting
jajhall Jan 27, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions src/ipm/IpxWrapper.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
1 change: 1 addition & 0 deletions src/ipm/ipx/control.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
10 changes: 6 additions & 4 deletions src/ipm/ipx/ipm.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
Expand Down
1 change: 1 addition & 0 deletions src/ipm/ipx/ipx_parameters.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,6 +64,7 @@ struct ipx_parameters {

/* HiGHS logging parameters */
bool highs_logging;
bool timeless_log;
const HighsLogOptions* log_options;

};
Expand Down
7 changes: 4 additions & 3 deletions src/ipm/ipx/lp_solver.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down
17 changes: 11 additions & 6 deletions src/lp_data/Highs.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand Down
7 changes: 7 additions & 0 deletions src/lp_data/HighsOptions.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -335,6 +335,7 @@
// Control of HiGHS log
bool output_flag;
bool log_to_console;
bool timeless_log;

// Options for IPM solver
HighsInt ipm_iteration_limit;
Expand Down Expand Up @@ -485,6 +486,7 @@
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),
Expand Down Expand Up @@ -847,6 +849,11 @@
advanced, &log_to_console, true);
records.push_back(record_bool);

record_bool = new OptionRecordBool(

Check warning on line 852 in src/lp_data/HighsOptions.h

View check run for this annotation

Codecov / codecov/patch

src/lp_data/HighsOptions.h#L852 

Added line #L852 was not covered by tests
"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);
Expand Down
32 changes: 19 additions & 13 deletions src/mip/HighsMipSolver.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand All @@ -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"
Expand All @@ -797,21 +801,23 @@ 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"
" LP iterations %llu (total)\n"
" %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,
Expand All @@ -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);
}
Expand Down
69 changes: 37 additions & 32 deletions src/mip/HighsMipSolverData.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -372,10 +372,9 @@
}
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;
}
Expand Down Expand Up @@ -406,34 +405,33 @@
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;
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
"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,

Check warning on line 425 in src/mip/HighsMipSolverData.cpp

View check run for this annotation

Codecov / codecov/patch

src/mip/HighsMipSolverData.cpp#L425 

Added line #L425 was not covered by tests
"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()));

Check warning on line 429 in src/mip/HighsMipSolverData.cpp

View check run for this annotation

Codecov / codecov/patch

src/mip/HighsMipSolverData.cpp#L428-L429 

Added lines #L428 - L429 were not covered by tests
} 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()));

Check warning on line 434 in src/mip/HighsMipSolverData.cpp

View check run for this annotation

Codecov / codecov/patch

src/mip/HighsMipSolverData.cpp#L433-L434 

Added lines #L433 - L434 were not covered by tests
}
}
symData.reset();
Expand Down Expand Up @@ -678,6 +676,7 @@
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
Expand Down Expand Up @@ -1598,21 +1597,26 @@
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",
Expand Down Expand Up @@ -1656,13 +1660,13 @@
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<char, 22> ub_string;
if (mipsolver.options_mip_->objective_bound < ub) {
Expand All @@ -1677,13 +1681,13 @@
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
Expand Down Expand Up @@ -1960,6 +1964,7 @@

// make sure first line after solving root LP is printed
last_disptime = -kHighsInf;
disptime = 0;

mipsolver.analysis_.mipTimerStart(kMipClockRandomizedRounding1);
heuristics.randomizedRounding(firstlpsol);
Expand Down
2 changes: 2 additions & 0 deletions src/mip/HighsMipSolverData.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,6 +118,7 @@ struct HighsMipSolverData {

HighsCDouble pruned_treeweight;
double avgrootlpiters;
double disptime;
double last_disptime;
int64_t firstrootlpiters;
int64_t num_nodes;
Expand Down Expand Up @@ -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),
Expand Down
1 change: 1 addition & 0 deletions src/presolve/HPresolve.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
6 changes: 4 additions & 2 deletions src/simplex/HighsSimplexAnalysis.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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;
Expand Down Expand Up @@ -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<std::stringstream>(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;
Expand Down
Loading
Loading