Understanding the solver output
tischi opened this issue · 1 comments
Hi @JoOkuma,
Would you mind to explain a bit which of those numbers are important to look at?
Barrier statistics:
AA' NZ : 8.056e+05
Factor NZ : 8.428e+06 (roughly 160 MB of memory)
Factor Ops : 3.795e+09 (roughly 1 second per iteration)
Threads : 30
Objective Residual
Iter Primal Dual Primal Dual Compl Time
0 1.79159620e+07 3.53172007e+07 9.68e+02 1.00e+02 7.94e+02 14s
1 1.07420302e+07 2.86756527e+07 6.39e+02 6.65e+01 4.73e+02 15s
2 3.48241623e+06 1.71425783e+07 2.42e+02 2.10e+00 1.66e+02 17s
3 4.11374585e+05 4.65887147e+06 5.00e+01 3.84e-13 3.04e+01 19s
4 -1.35143182e+05 1.22068316e+06 5.74e+00 4.26e-13 5.34e+00 21s
5 -9.84915252e+04 5.23864832e+05 2.23e+00 2.95e-13 2.16e+00 22s
6 -6.55844403e+04 2.66574610e+05 1.19e+00 1.56e-13 1.10e+00 24s
7 -4.18161461e+04 1.47897319e+05 6.77e-01 1.99e-13 6.12e-01 25s
8 -2.54223345e+04 7.09476999e+04 3.73e-01 1.14e-13 3.09e-01 27s
9 -1.76591665e+04 5.02962393e+04 2.42e-01 1.56e-13 2.14e-01 28s
10 -1.09750497e+04 2.92587500e+04 1.23e-01 8.53e-14 1.23e-01 30s
11 -7.76190987e+03 1.94017995e+04 7.29e-02 8.53e-14 8.20e-02 31s
12 -5.03996197e+03 1.12744820e+04 3.96e-02 8.53e-14 4.87e-02 33s
13 -3.24034156e+03 7.11642346e+03 2.22e-02 7.11e-14 3.06e-02 35s
14 -1.29100165e+03 5.08539315e+03 7.55e-03 5.68e-14 1.82e-02 36s
15 -7.36872832e+02 4.02158116e+03 4.49e-03 4.26e-14 1.35e-02 38s
16 -3.57488616e+02 2.00404175e+03 2.66e-03 5.68e-14 6.73e-03 39s
17 -1.48011563e+02 1.50551290e+03 1.78e-03 5.68e-14 4.71e-03 41s
18 -6.77626577e+01 1.24859456e+03 1.47e-03 5.68e-14 3.75e-03 42s
19 -4.02976181e+01 1.11683799e+03 1.36e-03 5.68e-14 3.30e-03 44s
20 7.98028415e+00 1.01034058e+03 1.17e-03 7.11e-14 2.86e-03 45s
21 1.97844107e+01 9.68200160e+02 1.13e-03 7.11e-14 2.71e-03 47s
22 1.03372565e+02 6.77357366e+02 6.07e-04 5.68e-14 1.63e-03 49s
23 1.29756333e+02 4.86652034e+02 4.35e-04 5.68e-14 1.02e-03 51s
24 1.51503148e+02 4.05397685e+02 2.94e-04 4.26e-14 7.23e-04 54s
25 1.65283881e+02 3.84721970e+02 2.15e-04 5.68e-14 6.21e-04 57s
26 1.67742581e+02 3.54350728e+02 2.02e-04 5.68e-14 5.30e-04 58s
27 1.80044852e+02 3.39649537e+02 1.43e-04 5.68e-14 4.51e-04 60s
28 1.83720498e+02 3.24213820e+02 1.31e-04 5.68e-14 3.97e-04 62s
29 1.86461956e+02 3.07695057e+02 1.22e-04 5.68e-14 3.44e-04 65s
30 1.90345336e+02 3.02150142e+02 1.11e-04 5.68e-14 3.17e-04 67s
31 1.94283304e+02 2.97667513e+02 1.00e-04 5.68e-14 2.93e-04 69s
32 1.99400084e+02 2.85032219e+02 8.71e-05 5.68e-14 2.43e-04 71s
33 2.00573589e+02 2.80175192e+02 8.40e-05 7.11e-14 2.26e-04 73s
34 2.06316974e+02 2.77418958e+02 7.05e-05 7.11e-14 2.01e-04 75s
35 2.09222331e+02 2.67166528e+02 6.33e-05 5.68e-14 1.65e-04 77s
36 2.17670033e+02 2.60780787e+02 4.39e-05 5.68e-14 1.22e-04 79s
37 2.21337610e+02 2.58298056e+02 3.58e-05 4.26e-14 1.05e-04 81s
38 2.26228220e+02 2.53367391e+02 2.53e-05 5.68e-14 7.67e-05 83s
39 2.26933554e+02 2.52302799e+02 2.38e-05 5.68e-14 7.17e-05 85s
40 2.29818025e+02 2.48437240e+02 1.78e-05 4.26e-14 5.27e-05 88s
41 2.32138062e+02 2.46483419e+02 1.32e-05 5.68e-14 4.05e-05 90s
42 2.33930647e+02 2.44525205e+02 9.74e-06 5.68e-14 2.99e-05 92s
43 2.35595873e+02 2.42830494e+02 6.59e-06 5.68e-14 2.04e-05 95s
44 2.36450658e+02 2.41437248e+02 5.03e-06 5.68e-14 1.41e-05 97s
45 2.37581776e+02 2.40568802e+02 3.01e-06 4.26e-14 8.46e-06 99s
46 2.38374056e+02 2.40167001e+02 1.63e-06 4.26e-14 5.06e-06 102s
47 2.38670690e+02 2.39909395e+02 1.11e-06 5.68e-14 3.50e-06 103s
48 2.38856095e+02 2.39807555e+02 8.02e-07 5.68e-14 2.68e-06 105s
49 2.38896176e+02 2.39757963e+02 7.38e-07 5.68e-14 2.43e-06 106s
50 2.39021049e+02 2.39655411e+02 5.29e-07 4.26e-14 1.79e-06 107s
51 2.39118032e+02 2.39597899e+02 3.70e-07 4.26e-14 1.35e-06 109s
52 2.39154473e+02 2.39499757e+02 3.13e-07 4.26e-14 9.75e-07 110s
53 2.39224810e+02 2.39441947e+02 2.04e-07 4.26e-14 6.14e-07 112s
54 2.39285188e+02 2.39408009e+02 1.09e-07 4.26e-14 3.47e-07 113s
55 2.39347891e+02 2.39379281e+02 1.36e-08 4.26e-14 8.73e-08 115s
56 2.39355639e+02 2.39363595e+02 3.47e-09 1.14e-13 2.21e-08 116s
57 2.39357669e+02 2.39360758e+02 8.52e-10 8.53e-14 8.55e-09 118s
Barrier performed 57 iterations in 117.71 seconds (7.46 work units)
Barrier solve interrupted - model solved by another algorithm
Solved with primal simplex
Root simplex log...
Iteration Objective Primal Inf. Dual Inf. Time
150031 2.3935844e+02 0.000000e+00 0.000000e+00 119s
Root relaxation: objective 2.393584e+02, 150031 iterations, 116.72 seconds (5.18 work units)
Total elapsed time = 120.43s (DegenMoves)
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 239.35844 0 3341 -399.99616 239.35844 160% - 121s
H 0 0 74.6577562 239.35844 221% - 121s
H 0 0 79.2766681 239.35844 202% - 122s
0 0 233.02530 0 2885 79.27667 233.02530 194% - 124s
H 0 0 93.7168490 233.02530 149% - 124s
H 0 0 110.1277578 233.02530 112% - 131s
0 0 233.01949 0 2796 110.12776 233.01949 112% - 131s
0 0 233.01934 0 2800 110.12776 233.01934 112% - 131s
0 0 231.27108 0 2859 110.12776 231.27108 110% - 134s
H 0 0 111.6377074 231.27108 107% - 135s
0 0 231.16158 0 2744 111.63771 231.16158 107% - 136s
0 0 231.16143 0 2738 111.63771 231.16143 107% - 136s
0 0 230.50350 0 3200 111.63771 230.50350 106% - 138s
0 0 230.46552 0 3288 111.63771 230.46552 106% - 140s
0 0 230.46234 0 3033 111.63771 230.46234 106% - 140s
0 0 230.46229 0 3099 111.63771 230.46229 106% - 140s
0 0 230.03966 0 3245 111.63771 230.03966 106% - 142s
H 0 0 112.8548594 230.03966 104% - 144s
0 0 230.02468 0 3274 112.85486 230.02468 104% - 144s
0 0 230.02361 0 3302 112.85486 230.02361 104% - 144s
0 0 229.66019 0 2908 112.85486 229.66019 104% - 146s
0 0 229.61690 0 3096 112.85486 229.61690 103% - 148s
0 0 229.59641 0 3274 112.85486 229.59641 103% - 148s
0 0 229.59623 0 3265 112.85486 229.59623 103% - 149s
0 0 229.38573 0 3150 112.85486 229.38573 103% - 150s
H 0 0 114.3770741 229.38573 101% - 161s
0 0 229.37472 0 3121 114.37707 229.37472 101% - 162s
0 0 229.37394 0 3046 114.37707 229.37394 101% - 162s
0 0 229.18632 0 3377 114.37707 229.18632 100% - 164s
0 0 229.17448 0 3389 114.37707 229.17448 100% - 166s
0 0 229.17356 0 3440 114.37707 229.17356 100% - 166s
0 0 229.06050 0 3548 114.37707 229.06050 100% - 168s
0 0 229.05052 0 3482 114.37707 229.05052 100% - 170s
0 0 229.05008 0 3397 114.37707 229.05008 100% - 170s
0 0 228.98755 0 3560 114.37707 228.98755 100% - 172s
0 0 228.97963 0 3686 114.37707 228.97963 100% - 174s
0 0 228.97933 0 3689 114.37707 228.97933 100% - 174s
0 0 228.90644 0 3648 114.37707 228.90644 100% - 176s
0 0 228.90338 0 3601 114.37707 228.90338 100% - 178s
0 0 228.90223 0 3715 114.37707 228.90223 100% - 178s
0 0 228.82061 0 3580 114.37707 228.82061 100% - 180s
H 0 0 119.0407406 228.82061 92.2% - 212s
0 0 228.81713 0 3578 119.04074 228.81713 92.2% - 212s
0 0 228.81618 0 3609 119.04074 228.81618 92.2% - 212s
0 0 228.76781 0 3942 119.04074 228.76781 92.2% - 215s
0 0 228.75693 0 3949 119.04074 228.75693 92.2% - 217s
0 0 228.75681 0 3972 119.04074 228.75681 92.2% - 218s
0 0 228.71237 0 3898 119.04074 228.71237 92.1% - 219s
0 0 228.71059 0 3943 119.04074 228.71059 92.1% - 221s
0 0 228.71055 0 3869 119.04074 228.71055 92.1% - 222s
0 0 228.67762 0 4019 119.04074 228.67762 92.1% - 224s
0 0 228.67421 0 4188 119.04074 228.67421 92.1% - 226s
0 0 228.67392 0 4192 119.04074 228.67392 92.1% - 227s
0 0 228.63754 0 3965 119.04074 228.63754 92.1% - 228s
0 0 228.63450 0 4051 119.04074 228.63450 92.1% - 232s
0 0 228.63436 0 4035 119.04074 228.63436 92.1% - 232s
0 0 228.61049 0 4152 119.04074 228.61049 92.0% - 234s
0 0 228.60206 0 4080 119.04074 228.60206 92.0% - 235s
0 0 228.60091 0 4129 119.04074 228.60091 92.0% - 236s
0 0 228.58098 0 4150 119.04074 228.58098 92.0% - 237s
0 0 228.57859 0 4221 119.04074 228.57859 92.0% - 239s
0 0 228.57848 0 4280 119.04074 228.57848 92.0% - 239s
0 0 228.56594 0 4254 119.04074 228.56594 92.0% - 241s
0 0 228.56459 0 4250 119.04074 228.56459 92.0% - 242s
0 0 228.55365 0 3988 119.04074 228.55365 92.0% - 244s
0 0 228.55337 0 3983 119.04074 228.55337 92.0% - 245s
0 2 228.55337 0 3983 119.04074 228.55337 92.0% - 255s
3 8 228.54716 2 3903 119.04074 228.55146 92.0% 309 262s
7 16 228.52161 3 3905 119.04074 228.54663 92.0% 384 274s
15 32 228.35188 4 3874 119.04074 228.52144 92.0% 1434 298s
H 31 64 121.1808350 228.47271 88.5% 2211 411s
H 32 64 123.5517956 228.47271 84.9% 2222 411s
H 37 64 127.2156126 228.47271 79.6% 2199 411s
H 46 64 130.0684059 228.47271 75.7% 2096 411s
H 63 96 140.0626387 228.37074 63.0% 2417 575s
H 67 96 140.0728704 228.36921 63.0% 2306 575s
H 70 96 140.1104346 228.36921 63.0% 2229 575s
H 72 96 140.4615251 228.36921 62.6% 2182 575s
H 75 96 141.0275451 228.36921 61.9% 2111 575s
H 76 96 147.8959769 228.36921 54.4% 2094 575s
95 128 228.15368 7 3866 147.89598 228.36921 54.4% 1975 596s
127 160 228.14565 8 3807 147.89598 228.36921 54.4% 1691 618s
159 192 227.91566 9 3738 147.89598 228.36921 54.4% 1630 648s
191 222 227.92509 9 3418 147.89598 228.36921 54.4% 1578 712s
225 277 227.88757 10 3431 147.89598 228.36921 54.4% 1682 755s
280 333 227.80605 12 3390 147.89598 228.36921 54.4% 1695 780s
338 392 227.68453 12 3547 147.89598 228.36921 54.4% 1521 818s
H 397 424 152.6858969 228.36921 49.6% 1485 1537s
H 429 456 153.1805798 228.36921 49.1% 1449 1656s
H 429 456 166.8669532 228.36921 36.9% 1449 1656s
H 445 456 168.9910695 228.36921 35.1% 1416 1656s
461 521 227.73658 14 3404 168.99107 228.36921 35.1% 1441 1692s
H 537 603 169.7752020 228.36921 34.5% 1382 1743s
H 556 603 169.9578934 228.36921 34.4% 1345 1743s
H 580 603 202.1428122 228.36921 13.0% 1328 1743s
621 685 227.59256 19 3460 202.14281 228.36921 13.0% 1314 1833s
H 724 774 202.2996744 228.36921 12.9% 1441 1892s
H 728 774 204.2018443 228.36921 11.8% 1440 1892s
820 887 227.32439 22 3407 204.20184 228.36921 11.8% 1375 1941s
Hi @tischi , I usually keep track of the second part where the relaxed model is solved.
The first, presolving, is usually quite fast.
Second part:
...
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 239.35844 0 3341 -399.99616 239.35844 160% - 121s
H 0 0 74.6577562 239.35844 221% - 121s
H 0 0 79.2766681 239.35844 202% - 122s
0 0 233.02530 0 2885 79.27667 233.02530 194% - 124s
H 0 0 93.7168490 233.02530 149% - 124s
H 0 0 110.1277578 233.02530 112% - 131s
...
H 724 774 202.2996744 228.36921 12.9% 1441 1892s
H 728 774 204.2018443 228.36921 11.8% 1440 1892s
820 887 227.32439 22 3407 204.20184 228.36921 11.8% 1375 1941s
The right-most column is the processing time in seconds for this step, which can be limited using tracking_config.time_limit
.
The Objective Bounds
show how close you are to the optimum; they have an upper bound (BestBd
) for our maximization problem, which is the objective at a solution with a relaxed version of the problem, that is, with fewer constraints.
The Incumbent
shows the objective of the current solution -- with all constraints, and the Gap
is the normalized gap between this objective and the bound; more information is provided, here.
It can take forever for large datasets to reach 0 gap, so setting a tolerance is preferred; this is the tracking_config.solution_gap
parameter. We use a gap of 0.1%
by default.
Once the solution gap or the time limit is reached, the optimization/search ends.