Skip to content

Commit 38bc501

Browse files
jajhalljajhall
authored
Merge pull request #2147 from ERGO-Code/no-time-reporting
Introduced `timeless_log` option so logging is deterministic
2 parents 52af45f + 7c0620a commit 38bc501

File tree

13 files changed

+98
-60
lines changed

13 files changed

+98
-60
lines changed

‎src/ipm/IpxWrapper.cpp‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,6 +85,7 @@ HighsStatus solveLpIpx(const HighsOptions& options, HighsTimer& timer,
8585
parameters.debug = 4;
8686
}
8787
parameters.highs_logging = true;
88+
parameters.timeless_log = options.timeless_log;
8889
parameters.log_options = &options.log_options;
8990
// Just test feasibility and optimality tolerances for now
9091
// ToDo Set more parameters

‎src/ipm/ipx/control.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -91,6 +91,7 @@ class Control {
9191
double centringRatioReduction() const {return parameters_.centring_ratio_reduction; }
9292
double centringAlphaScaling() const{return parameters_.centring_alpha_scaling; }
9393
ipxint badProductsTolerance() const{return parameters_.bad_products_tolerance; }
94+
bool timelessLog() const{return parameters_.timeless_log; }
9495

9596
const Parameters& parameters() const;
9697
void parameters(const Parameters& new_parameters);

‎src/ipm/ipx/ipm.cc‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -825,8 +825,9 @@ void IPM::PrintHeader() {
825825
<< " " << Format("Iter", 4)
826826
<< " " << Format("P.res", 8) << " " << Format("D.res", 8)
827827
<< " " << Format("P.obj", 15) << " " << Format("D.obj", 15)
828-
<< " " << Format("mu", 8)
829-
<< " " << Format("Time", 7);
828+
<< " " << Format("mu", 8);
829+
if (!control_.timelessLog())
830+
h_logging_stream << " " << Format("Time", 7);
830831
control_.hLog(h_logging_stream);
831832
control_.Debug()
832833
<< " " << Format("stepsizes", 9)
@@ -850,8 +851,9 @@ void IPM::PrintOutput() {
850851
<< " " << Scientific(iterate_->dresidual(), 8, 2)
851852
<< " " << Scientific(iterate_->pobjective_after_postproc(), 15, 8)
852853
<< " " << Scientific(iterate_->dobjective_after_postproc(), 15, 8)
853-
<< " " << Scientific(iterate_->mu(), 8, 2)
854-
<< " " << Fixed(control_.Elapsed(), 6, 0) << "s";
854+
<< " " << Scientific(iterate_->mu(), 8, 2);
855+
if (!control_.timelessLog())
856+
h_logging_stream << " " << Fixed(control_.Elapsed(), 6, 0) << "s";
855857
control_.hLog(h_logging_stream);
856858
control_.Debug()
857859
<< " " << Fixed(step_primal_, 4, 2) << " " << Fixed(step_dual_, 4, 2)

‎src/ipm/ipx/ipx_parameters.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,7 @@ struct ipx_parameters {
6464

6565
/* HiGHS logging parameters */
6666
bool highs_logging;
67+
bool timeless_log;
6768
const HighsLogOptions* log_options;
6869

6970
};

‎src/ipm/ipx/lp_solver.cc‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -649,9 +649,10 @@ void LpSolver::RunCrossover() {
649649
void LpSolver::PrintSummary() {
650650
std::stringstream h_logging_stream;
651651
h_logging_stream.str(std::string());
652-
h_logging_stream << "Summary\n"
653-
<< Textline("Runtime:") << fix2(control_.Elapsed()) << "s\n"
654-
<< Textline("Status interior point solve:")
652+
h_logging_stream << "Summary\n";
653+
if (!control_.timelessLog())
654+
h_logging_stream << Textline("Runtime:") << fix2(control_.Elapsed()) << "s\n";
655+
h_logging_stream << Textline("Status interior point solve:")
655656
<< StatusString(info_.status_ipm) << '\n'
656657
<< Textline("Status crossover:")
657658
<< StatusString(info_.status_crossover) << '\n';

‎src/lp_data/Highs.cpp‎

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -3875,10 +3875,13 @@ HighsStatus Highs::callSolveQp() {
38753875
// Define the QP solver iteration logging function
38763876
settings.iteration_log.subscribe([this](Statistics& stats) {
38773877
int rep = stats.iteration.size() - 1;
3878+
std::string time_string =
3879+
options_.timeless_log ? ""
3880+
: highsFormatToString(" %9.2fs", stats.time[rep]);
38783881
highsLogUser(options_.log_options, HighsLogType::kInfo,
3879-
"%11d %15.8g %6d %9.2fs\n",
3880-
int(stats.iteration[rep]), stats.objval[rep],
3881-
int(stats.nullspacedimension[rep]), stats.time[rep]);
3882+
"%11d %15.8g %6d%s\n", int(stats.iteration[rep]),
3883+
stats.objval[rep], int(stats.nullspacedimension[rep]),
3884+
time_string.c_str());
38823885
});
38833886

38843887
// Define the QP nullspace limit logging function
@@ -4613,9 +4616,11 @@ void Highs::reportSolvedLpQpStats() {
46134616
highsLogUser(log_options, HighsLogType::kInfo,
46144617
"Relative P-D gap : %17.10e\n", relative_primal_dual_gap);
46154618
}
4616-
double run_time = timer_.read();
4617-
highsLogUser(log_options, HighsLogType::kInfo,
4618-
"HiGHS run time : %13.2f\n", run_time);
4619+
if (!options_.timeless_log) {
4620+
double run_time = timer_.read();
4621+
highsLogUser(log_options, HighsLogType::kInfo,
4622+
"HiGHS run time : %13.2f\n", run_time);
4623+
}
46194624
}
46204625

46214626
HighsStatus Highs::crossover(const HighsSolution& user_solution) {

‎src/lp_data/HighsOptions.h‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -335,6 +335,7 @@ struct HighsOptionsStruct {
335335
// Control of HiGHS log
336336
bool output_flag;
337337
bool log_to_console;
338+
bool timeless_log;
338339

339340
// Options for IPM solver
340341
HighsInt ipm_iteration_limit;
@@ -485,6 +486,7 @@ struct HighsOptionsStruct {
485486
write_presolved_model_file(""),
486487
output_flag(false),
487488
log_to_console(false),
489+
timeless_log(false),
488490
ipm_iteration_limit(0),
489491
pdlp_native_termination(false),
490492
pdlp_scaling(false),
@@ -847,6 +849,11 @@ class HighsOptions : public HighsOptionsStruct {
847849
advanced, &log_to_console, true);
848850
records.push_back(record_bool);
849851

852+
record_bool = new OptionRecordBool(
853+
"timeless_log", "Suppression of time-based data in logging", true,
854+
&timeless_log, false);
855+
records.push_back(record_bool);
856+
850857
record_string =
851858
new OptionRecordString(kSolutionFileString, "Solution file", advanced,
852859
&solution_file, kHighsFilenameDefault);

‎src/mip/HighsMipSolver.cpp‎

Lines changed: 19 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -773,6 +773,7 @@ void HighsMipSolver::cleanupSolve() {
773773
gapValString.data());
774774
}
775775

776+
bool timeless_log = options_mip_->timeless_log;
776777
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
777778
"\nSolving report\n");
778779
if (this->orig_model_->model_name_.length())
@@ -783,12 +784,15 @@ void HighsMipSolver::cleanupSolve() {
783784
" Status %s\n"
784785
" Primal bound %.12g\n"
785786
" Dual bound %.12g\n"
786-
" Gap %s\n"
787-
" P-D integral %.12g\n"
788-
" Solution status %s\n",
787+
" Gap %s\n",
789788
utilModelStatusToString(modelstatus_).c_str(), primal_bound_,
790-
dual_bound_, gapString.data(),
791-
mipdata_->primal_dual_integral.value, solutionstatus.c_str());
789+
dual_bound_, gapString.data());
790+
if (!timeless_log)
791+
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
792+
" P-D integral %.12g\n",
793+
mipdata_->primal_dual_integral.value);
794+
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
795+
" Solution status %s\n", solutionstatus.c_str());
792796
if (solutionstatus != "-")
793797
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
794798
" %.12g (objective)\n"
@@ -797,21 +801,23 @@ void HighsMipSolver::cleanupSolve() {
797801
" %.12g (row viol.)\n",
798802
solution_objective_, bound_violation_, integrality_violation_,
799803
row_violation_);
804+
if (!timeless_log)
805+
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
806+
" Timing %.2f (total)\n"
807+
" %.2f (presolve)\n"
808+
" %.2f (solve)\n"
809+
" %.2f (postsolve)\n",
810+
timer_.read(), analysis_.mipTimerRead(kMipClockPresolve),
811+
analysis_.mipTimerRead(kMipClockSolve),
812+
analysis_.mipTimerRead(kMipClockPostsolve));
800813
highsLogUser(options_mip_->log_options, HighsLogType::kInfo,
801-
" Timing %.2f (total)\n"
802-
" %.2f (presolve)\n"
803-
" %.2f (solve)\n"
804-
" %.2f (postsolve)\n"
805814
" Max sub-MIP depth %d\n"
806815
" Nodes %llu\n"
807816
" Repair LPs %llu (%llu feasible; %llu iterations)\n"
808817
" LP iterations %llu (total)\n"
809818
" %llu (strong br.)\n"
810819
" %llu (separation)\n"
811820
" %llu (heuristics)\n",
812-
timer_.read(), analysis_.mipTimerRead(kMipClockPresolve),
813-
analysis_.mipTimerRead(kMipClockSolve),
814-
analysis_.mipTimerRead(kMipClockPostsolve),
815821
int(max_submip_level), (long long unsigned)mipdata_->num_nodes,
816822
(long long unsigned)mipdata_->total_repair_lp,
817823
(long long unsigned)mipdata_->total_repair_lp_feasible,
@@ -821,7 +827,7 @@ void HighsMipSolver::cleanupSolve() {
821827
(long long unsigned)mipdata_->sepa_lp_iterations,
822828
(long long unsigned)mipdata_->heuristic_lp_iterations);
823829

824-
analysis_.reportMipTimer();
830+
if (!timeless_log) analysis_.reportMipTimer();
825831

826832
assert(modelstatus_ != HighsModelStatus::kNotset);
827833
}

‎src/mip/HighsMipSolverData.cpp‎

Lines changed: 37 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -372,10 +372,9 @@ void HighsMipSolverData::finishAnalyticCenterComputation(
372372
}
373373
if (nfixed > 0)
374374
highsLogDev(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
375-
"Fixing %" HIGHSINT_FORMAT " columns (%" HIGHSINT_FORMAT
376-
" integers) sitting at bound at "
375+
"Fixing %d columns (%d integers) sitting at bound at "
377376
"analytic center\n",
378-
nfixed, nintfixed);
377+
int(nfixed), int(nintfixed));
379378
mipsolver.mipdata_->domain.propagate();
380379
if (mipsolver.mipdata_->domain.infeasible()) return;
381380
}
@@ -406,34 +405,33 @@ void HighsMipSolverData::finishSymmetryDetection(
406405
taskGroup.sync();
407406

408407
symmetries = std::move(symData->symmetries);
408+
std::string symmetry_time =
409+
mipsolver.options_mip_->timeless_log
410+
? ""
411+
: highsFormatToString(" %.1fs", symData->detectionTime);
409412
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
410-
"\nSymmetry detection completed in %.1fs\n",
411-
symData->detectionTime);
413+
"\nSymmetry detection completed in%s\n", symmetry_time.c_str());
412414

413415
if (symmetries.numGenerators == 0) {
414416
detectSymmetries = false;
415417
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
416418
"No symmetry present\n\n");
417419
} else if (symmetries.orbitopes.size() == 0) {
418420
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
419-
"Found %" HIGHSINT_FORMAT " generator(s)\n\n",
420-
symmetries.numGenerators);
421+
"Found %d generator(s)\n\n", int(symmetries.numGenerators));
421422

422423
} else {
423424
if (symmetries.numPerms != 0) {
424-
highsLogUser(
425-
mipsolver.options_mip_->log_options, HighsLogType::kInfo,
426-
"Found %" HIGHSINT_FORMAT " generator(s) and %" HIGHSINT_FORMAT
427-
" full orbitope(s) acting on %" HIGHSINT_FORMAT " columns\n\n",
428-
symmetries.numPerms, (HighsInt)symmetries.orbitopes.size(),
429-
(HighsInt)symmetries.columnToOrbitope.size());
425+
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
426+
"Found %d generator(s) and %d full orbitope(s) acting on %d "
427+
"columns\n\n",
428+
int(symmetries.numPerms), int(symmetries.orbitopes.size()),
429+
int(symmetries.columnToOrbitope.size()));
430430
} else {
431431
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
432-
"Found %" HIGHSINT_FORMAT
433-
" full orbitope(s) acting on %" HIGHSINT_FORMAT
434-
" columns\n\n",
435-
(HighsInt)symmetries.orbitopes.size(),
436-
(HighsInt)symmetries.columnToOrbitope.size());
432+
"Found %d full orbitope(s) acting on %d columns\n\n",
433+
int(symmetries.orbitopes.size()),
434+
int(symmetries.columnToOrbitope.size()));
437435
}
438436
}
439437
symData.reset();
@@ -678,6 +676,7 @@ void HighsMipSolverData::runSetup() {
678676
const HighsLp& model = *mipsolver.model_;
679677

680678
last_disptime = -kHighsInf;
679+
disptime = 0;
681680

682681
// Transform the reference of the objective limit and lower/upper
683682
// bounds from the original model to the current model, undoing the
@@ -1598,21 +1597,26 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) {
15981597
bool output_flag = *mipsolver.options_mip_->log_options.output_flag;
15991598
if (!output_flag) return;
16001599

1601-
double time = mipsolver.timer_.read();
1600+
bool timeless_log = mipsolver.options_mip_->timeless_log;
1601+
disptime = timeless_log ? disptime + 1 : mipsolver.timer_.read();
16021602
if (solution_source == kSolutionSourceNone &&
1603-
time - last_disptime < mipsolver.options_mip_->mip_min_logging_interval)
1603+
disptime - last_disptime <
1604+
mipsolver.options_mip_->mip_min_logging_interval)
16041605
return;
1605-
last_disptime = time;
1606+
last_disptime = disptime;
1607+
std::string time_string =
1608+
timeless_log ? "" : highsFormatToString(" %7.1fs", disptime);
16061609

16071610
if (num_disp_lines % 20 == 0) {
16081611
if (num_disp_lines == 0) printSolutionSourceKey();
1609-
highsLogUser(
1610-
mipsolver.options_mip_->log_options, HighsLogType::kInfo,
1611-
// clang-format off
1612-
"\n Nodes | B&B Tree | Objective Bounds | Dynamic Constraints | Work \n"
1613-
"Src Proc. InQueue | Leaves Expl. | BestBound BestSol Gap | Cuts InLp Confl. | LpIters Time\n\n"
1614-
// clang-format on
1615-
);
1612+
std::string work_string0 = timeless_log ? " Work" : " Work ";
1613+
std::string work_string1 = timeless_log ? "LpIters" : "LpIters Time";
1614+
highsLogUser(mipsolver.options_mip_->log_options, HighsLogType::kInfo,
1615+
// clang-format off
1616+
"\n Nodes | B&B Tree | Objective Bounds | Dynamic Constraints | %s\n"
1617+
"Src Proc. InQueue | Leaves Expl. | BestBound BestSol Gap | Cuts InLp Confl. | %s\n\n",
1618+
// clang-format on
1619+
work_string0.c_str(), work_string1.c_str());
16161620

16171621
//" %7s | %10s | %10s | %10s | %10s | %-15s | %-15s | %7s | %7s "
16181622
//"| %8s | %8s\n",
@@ -1656,13 +1660,13 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) {
16561660
highsLogUser(
16571661
mipsolver.options_mip_->log_options, HighsLogType::kInfo,
16581662
// clang-format off
1659-
" %s %7s %7s %7s %6.2f%% %-15s %-15s %8s %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s %7.1fs\n",
1663+
" %s %7s %7s %7s %6.2f%% %-15s %-15s %8s %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s%s\n",
16601664
// clang-format on
16611665
solutionSourceToString(solution_source).c_str(), print_nodes.data(),
16621666
queue_nodes.data(), print_leaves.data(), explored, lb_string.data(),
16631667
ub_string.data(), gap_string.data(), cutpool.getNumCuts(),
16641668
lp.numRows() - lp.getNumModelRows(), conflictPool.getNumConflicts(),
1665-
print_lp_iters.data(), time);
1669+
print_lp_iters.data(), time_string.c_str());
16661670
} else {
16671671
std::array<char, 22> ub_string;
16681672
if (mipsolver.options_mip_->objective_bound < ub) {
@@ -1677,13 +1681,13 @@ void HighsMipSolverData::printDisplayLine(const int solution_source) {
16771681
highsLogUser(
16781682
mipsolver.options_mip_->log_options, HighsLogType::kInfo,
16791683
// clang-format off
1680-
" %s %7s %7s %7s %6.2f%% %-15s %-15s %8.2f %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s %7.1fs\n",
1684+
" %s %7s %7s %7s %6.2f%% %-15s %-15s %8.2f %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %6" HIGHSINT_FORMAT " %7s%s\n",
16811685
// clang-format on
16821686
solutionSourceToString(solution_source).c_str(), print_nodes.data(),
16831687
queue_nodes.data(), print_leaves.data(), explored, lb_string.data(),
16841688
ub_string.data(), gap, cutpool.getNumCuts(),
16851689
lp.numRows() - lp.getNumModelRows(), conflictPool.getNumConflicts(),
1686-
print_lp_iters.data(), time);
1690+
print_lp_iters.data(), time_string.c_str());
16871691
}
16881692
// Check that limitsToBounds yields the same values for the
16891693
// dual_bound, primal_bound (modulo optimization sense) and
@@ -1960,6 +1964,7 @@ void HighsMipSolverData::evaluateRootNode() {
19601964

19611965
// make sure first line after solving root LP is printed
19621966
last_disptime = -kHighsInf;
1967+
disptime = 0;
19631968

19641969
mipsolver.analysis_.mipTimerStart(kMipClockRandomizedRounding1);
19651970
heuristics.randomizedRounding(firstlpsol);

‎src/mip/HighsMipSolverData.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -118,6 +118,7 @@ struct HighsMipSolverData {
118118

119119
HighsCDouble pruned_treeweight;
120120
double avgrootlpiters;
121+
double disptime;
121122
double last_disptime;
122123
int64_t firstrootlpiters;
123124
int64_t num_nodes;
@@ -183,6 +184,7 @@ struct HighsMipSolverData {
183184
maxTreeSizeLog2(0),
184185
pruned_treeweight(0),
185186
avgrootlpiters(0.0),
187+
disptime(0.0),
186188
last_disptime(0.0),
187189
firstrootlpiters(0),
188190
num_nodes(0),

0 commit comments

Comments
 (0)