A little Python Log Parser/Plotter

[Thell]

Hi. I just wanted to share this little plotter.

https://gist.github.com/Thell/acff85705ed790b4362579b42803e0f6

Here's a sample. These are images from some modelling iterations of a problem I've been working on. Notice how as the model improved so did the shape and the solution. Thanks for the worthy data in the output logs!👍

Early on, it gives the right answers given enough time but its obvious the solver needs some help.

Some of the model is fixed but there's still quite a bit of redundant logic in the vars/constraints hindering the solver's progress.

Latest rewrites look great. Remove anything else from the model that can be removed while still being valid results in regression of the time and the shape of the problem. Pareto efficiency my friends. 😄

The problem is a Multicommodity Assignment and Flow Problem with budget, grouping and group size penalties on a small node undirected weighted graph (~2200 edges) with 24 groups of dynamic sizes and 274 commodities with each having a different value within each group. It has been a fun problem to model and having an image plotter seems to show the progress.

Anyhow, thanks again for the great solver!

[jajhall]

Very neat! I'm looking to add profiling to the MIP solver to aid development, but this is also a valuable tool for visualising what it's doing.

[Thell]

Thanks. I wish I had thought of it when first starting the project. I suppose someone with a more concrete understanding of how the internals of the solver worked would be able to grok more from the images but even to a layman the images can definitely show when the model "just doesn't look right".

[jajhall]

To compare the pictures with the logging, it would be better if the horizontal axis were in seconds

Finally - until I start looking at it in detail! - it would be good to have a marker on the horizontal axis - or even a fine vertical line - to indicate when an improving primal solution has been found. My guess is that this is the reason for the later vertical drops in the red "In queue" line. Earlier (when the line drops to zero) they are due to restarting the search with fixed values for the integer variables whose values are known.

I'm puzzled by the bets bound/solution lines, since I assume that you're minimizing. In this case, I'd expect the best solutions to drop from higher values, and the best bound to rise from lower values.

[Thell]

To compare the pictures with the logging, it would be better if the horizontal axis were in seconds
Indeed, I've had it both ways and found seconds was better for comparing to the logs but minutes translated better in my mind for time spent.

I'm puzzled by the bets bound/solution lines, since I assume that you're minimizing.
I should have mentioned that it is doing maximize.

Having an improvement marker is a great idea. I was simply zooming and panning, lol. There's quite a few things that could (should) be done to make it a more useful script. It'd be real neat to feed the output data into one of those purpose built time series visualization tools using a machine readable output option. That seemed like quite a bit of overkill for me to see the progression though.

And good call! I see quite a few restarts.

BTW - I should mention having the ability to write the pre-solve model was helpful so thanks for doing that.

Before fixing up the model I was getting quite a few restarts from inactive columns along with those HighsSearch::selectBranchingCandidate Error fracval errors. From the log of the first graph...

Running HiGHS 1.7.2 (git hash: 5ce7a2753): Copyright (c) 2024 HiGHS under MIT licence terms
Number of BV entries in BOUNDS section is 18393
MIP  MaximizeEmpireValue-pulp has 34791 rows; 33419 cols; 95705 nonzeros; 33417 integer variables
Coefficient ranges:
  Matrix [1e+00, 9e+06]
  Cost   [1e+00, 1e+00]
  Bound  [1e+00, 5e+02]
  RHS    [1e+00, 5e+02]
Presolving model
21161 rows, 20289 cols, 66962 nonzeros  0s
13367 rows, 15151 cols, 63566 nonzeros  0s
10615 rows, 12854 cols, 58977 nonzeros  0s
8822 rows, 12833 cols, 52994 nonzeros  0s

Solving MIP model with:
   8822 rows
   12833 cols (3411 binary, 9421 integer, 1 implied int., 0 continuous)
   52994 nonzeros

        Nodes      |    B&B Tree     |            Objective Bounds              |  Dynamic Constraints |       Work      
     Proc. InQueue |  Leaves   Expl. | BestBound       BestSol              Gap |   Cuts   InLp Confl. | LpIters     Time

         0       0         0   0.00%   9354143398.563  -inf                 inf        0      0      0         0     0.6s
 R       0       0         0   0.00%   9354143398.563  -0                 Large        0      0      0         0     0.8s
         0       0         0   0.00%   9354143398.563  -0                 Large     7536   1629    460     14332     6.2s
         0       0         0   0.00%   9354143398.563  -0                 Large     7735    886    546    109103    36.8s

0.1% inactive integer columns, restarting
Model after restart has 8821 rows, 12822 cols (3401 bin., 9420 int., 1 impl., 0 cont.), and 52678 nonzeros

         0       0         0   0.00%   9342536393.43   -0                 Large      883      0      0    109103    36.9s
         0       0         0   0.00%   9342536393.43   -0                 Large      883    704     10    118583    38.0s
         0       0         0   0.00%   432751535.1159  -0                 Large     4122   1442     10    125696    43.2s

Symmetry detection completed in 0.0s
Found 2 generator(s)

       108     107         1   0.00%   432751535.1159  -0                 Large     4122    904     14    282582   130.1s
       262     259         2   0.00%   432751535.1159  -0                 Large     5819   1511     17    365931   176.1s
       294     258         3   0.00%   432751535.1159  -0                 Large     6747   1802     36    413255   199.8s
       426     398        14   0.00%   432751535.1159  -0                 Large     6747   1802     87    427532   207.0s
 L     426     397        14   0.00%   432751535.1159  346898468.9372    24.75%     6878   1844     90    427948   218.8s
       469     389        23   0.00%   432751535.1159  346898468.9372    24.75%     7096   1982    116    482412   235.1s
       494     428        31   0.00%   432751535.1159  346898468.9372    24.75%     7105   1982    237    489424   240.5s
       532     419        40   0.00%   432751535.1159  346898468.9372    24.75%     7238   2078    309    546262   269.0s
       564     421        55   0.00%   432751535.1159  346898468.9372    24.75%     7252   2078   1064    551999   274.4s
       591     423        66   0.00%   432751535.1159  346898468.9372    24.75%     7264   2078   1269    557282   279.8s
 L     612     447        79   0.00%   432751535.1159  356222887.0378    21.48%     7333   2139   1500    561317   295.5s
       652     447        80   0.00%   432751535.1159  356222887.0378    21.48%     7334   2139   1527    605350   311.2s
       689     453        92   0.00%   432751535.1159  356222887.0378    21.48%     7346   2139   1609    611201   316.3s

On the later models I get mostly Symmetry detection and restarting the search from the root node...

Running HiGHS 1.7.2 (git hash: 47a31db3d): Copyright (c) 2024 HiGHS under MIT licence terms
Number of BV entries in BOUNDS section is 3458
MIP  MaximizeEmpireValue-pulp has 5761 rows; 9907 cols; 27863 nonzeros; 9907 integer variables
Coefficient ranges:
  Matrix [1e+00, 3e+02]
  Cost   [1e+05, 9e+06]
  Bound  [1e+00, 5e+02]
  RHS    [1e+00, 1e+00]
Presolving model
3671 rows, 7765 cols, 22347 nonzeros  0s
2696 rows, 6847 cols, 20097 nonzeros  0s
2532 rows, 5857 cols, 17975 nonzeros  0s
MIP-Timing: After 0.0497s - completed mipdata_->runPresolve
MIP-Timing: After 0.0497s - reached   mipdata_->runSetup()

Solving MIP model with:
   2532 rows
   5857 cols (1842 binary, 4015 integer, 0 implied int., 0 continuous)
   17975 nonzeros
MIP-Timing: After 0.0541s - completed mipdata_->runSetup()
MIP-Timing: After 0.0542s - reached   mipdata_->evaluateRootNode()

        Nodes      |    B&B Tree     |            Objective Bounds              |  Dynamic Constraints |       Work      
     Proc. InQueue |  Leaves   Expl. | BestBound       BestSol              Gap |   Cuts   InLp Confl. | LpIters     Time

         0       0         0   0.00%   542155966.93    -inf                 inf        0      0      0         0     0.1s
         0       0         0   0.00%   482276831.3613  -inf                 inf        0      0      6      3680     0.2s
         0       0         0   0.00%   420888441.9541  -inf                 inf     7099    519    997     39852    10.3s

Symmetry detection completed in 0.0s
Found 2 generator(s)

MIP-Timing: After 10.2689s - completed mipdata_->evaluateRootNode()
        13       0         1   0.02%   420888441.9541  -inf                 inf     6764    519   1005     97508    29.2s
        56       0         2   0.02%   420888441.9541  -inf                 inf     6764    519   1033    131258    38.0s
       152      94         5   0.02%   420170571.5966  -inf                 inf     4590    694   1153    171685    48.9s
       262     214        11   0.02%   420170571.5966  -inf                 inf     4435    657   1200    209666    57.8s
       387     315        18   0.02%   420170571.5966  -inf                 inf     4420    675   1249    250958    67.7s
       634     511        40   0.02%   420170571.5966  -inf                 inf     4173    603   1367    262312    72.8s
       752     590        48   0.02%   420170571.5966  -inf                 inf     4119    624   1425    286299    78.9s
       983     758        69   0.02%   420170571.5966  -inf                 inf     4260    598   1576    300548    84.1s

Restarting search from the root node
Model after restart has 2472 rows, 5788 cols (1838 bin., 3950 int., 0 impl., 0 cont.), and 17892 nonzeros

MIP-Timing: After 86.5779s - reached   mipdata_->evaluateRootNode()
      1093       0         0   0.00%   420170571.5966  -inf                 inf      605      0      0    306221    86.6s
      1093       0         0   0.00%   420170571.5966  -inf                 inf      605    424      1    308339    86.8s
 F    1093       0         0   0.00%   420011649.4829  -0                 Large     1168    529    510    322416    93.2s

Symmetry detection completed in 0.0s
Found 2 generator(s) and 2 full orbitope(s) acting on 4 columns

MIP-Timing: After 93.2507s - completed mipdata_->evaluateRootNode()
 L    1093       0         0   0.00%   420011649.4829  391939786.02       7.16%     1168    455    510    322788    96.2s
      1295      81        46   0.11%   420011649.4829  391939786.02       7.16%     1479    529   1619    343219   101.6s
      1449     151        94   0.11%   420011649.4829  391939786.02       7.16%     1646    556   2713    356114   106.8s
      1600     191       140   0.11%   420011649.4829  391939786.02       7.16%     1797    567   3937    367200   111.8s
      1856     364       168   0.11%   420011649.4829  391939786.02       7.16%     1943    557   4781    380635   117.9s
      2013     489       196   0.11%   420011649.4829  391939786.02       7.16%     2249    601   5825    395447   123.4s

        Nodes      |    B&B Tree     |            Objective Bounds              |  Dynamic Constraints |       Work      
     Proc. InQueue |  Leaves   Expl. | BestBound       BestSol              Gap |   Cuts   InLp Confl. | LpIters     Time

      2195     578       242   0.11%   420011649.4829  391939786.02       7.16%     2383    543   7582    406040   128.9s
      2259     609       254   0.11%   420011649.4829  391939786.02       7.16%     2483    583   8126    421988   134.5s
      2453     710       295   0.11%   420011649.4829  391939786.02       7.16%     2588    607   9911    434039   140.4s
      2571     769       329   0.16%   420011649.4829  391939786.02       7.16%     3172    747   9682    452138   147.0s
 L    2625     653       346   0.16%   420011649.4829  393141109.99       6.83%     3184    770   9246    456984   152.7s
      2777     699       389   0.16%   420011649.4829  393141109.99       6.83%     3135    567   9946    481394   158.6s
      2919     744       431   0.16%   420011649.4829  393141109.99       6.83%     3248    627   9406    493426   163.7s
      3012     770       462   0.16%   420011649.4829  393141109.99       6.83%     3280    635   9630    511965   171.3s

Restarting search from the root node
Model after restart has 2461 rows, 5770 cols (1833 bin., 3937 int., 0 impl., 0 cont.), and 17871 nonzeros

MIP-Timing: After 174.6365s - reached   mipdata_->evaluateRootNode()
      3138       0         0   0.00%   420011649.4829  393141109.99       6.83%      593      0      0    518114   174.6s
      3138       0         0   0.00%   420011649.4829  393141109.99       6.83%      593    386      2    520316   174.9s

Symmetry detection completed in 0.0s
Found 2 generator(s) and 2 full orbitope(s) acting on 4 columns

MIP-Timing: After 178.7442s - completed mipdata_->evaluateRootNode()
      3160       0         1   0.00%   419009981.2343  393141109.99       6.58%     1711    440    188    554459   185.8s

[Thell]

Well, that sure makes a difference! Thanks for the suggestions.

• x-axis in seconds
• added vertical BestSol indicators.
• handle initial non-valid bounds dominating vertical space.

[jajhall]

Here's the chart for my first meaningful test

Clearly this example produces so many improving solutions that the values of the (relative) MIP gap are unreadable. At the expense of having another vertical axis, I'd have thought that they are represented more clearly by plotting.

I also realise that since there's no MIP logging line when exiting the MIP solver, your plot misses off the final status - in particular the final gap. I'll add that to the MIP solver

When you referred to "sharing" this code, I assume that you're happy for me to add it to the HiGHS repo as

plot_highs_log.py

Note that it's not there yet, as I am working in another branch

[Thell]

When you referred to "sharing" this code, I assume that you're happy for me to add it to the HiGHS repo as

Very cool!

Re gap%: I couldn't think of a 'clean' way to represent them other than on an interval.

[jajhall]

In #1894 I'm plotting the gap, and prefer the output. The gap y-axis appears properly on the full-screen image

To add the corresponding y-axis, I had to remove the axis labelling due to lack of space on the RHS.

If I used "120" as the axis offset, it didn't appear. Is the "elbow-room" around the plot area fixed? No matter, I think that the colour-coding of the axis values makes it clear enough what plot they represent.

[Thell]

@jajhall What do you think of this?

By setting the fig size the subplots can be adjusted. I shifted left to allow room for the right axis and moved those labels to the top with zero rotation. Since the legend was just a block taking up space on the left I moved it to the top and flattened it. Seems quite a bit roomier. I'm not sure I'm the biggest fan of our color scheme though, lol. 😄

Gist updated.

[Thell]

Hrmmm... after playing with that a bit it seems it might just be better to leave the labels off of those right side axis. They seem to position themselves relative to the plot size which messes up on some resizing. Like you mentioned the legend suffices and with the legend set horizontal like it is the relationships are pretty darned clear.

[jajhall]

Thanks, for all this.

I much prefer the new legend, but like it at the bottom. The full-weight gap plot can mask bounds, in places where the gap is not really meaningful, so made it linestyle="--", linewidth=0.5.

I'll call this done, and move on - unless I find that after seeing it "in action" on more examples it needs further tweaking

[jajhall]

I've just edited plot_highs_log.py - because "new incumbent solution lines were being plotted when the original objective value was infinite (translated to NaN, but NaN-NaN isn't zero).

If you do feel inspired to modify the plotter further, please checkout plot_highs_log.py and submit a PR so we keep in sync