Skip to main content

Callback cut count and cut count in the MIP log are not equal

Answered

Comments

3 comments

  • Jaromił Najman
    Gurobi Staff Gurobi Staff

    Hi Jihye,

    The MIP_CUTCNT value depicts the number of all cuts added to the problem so far. Gurobi often purges the cuts added so far (especially deeper in the B&B tree) such that the final number of cuts added (reported at the and of the optimization process) is lower than what is provided by the MIP_CUTCNT.

    The best way to count how often a user cut/lazy constraint has been added is to track the number of cbLazy calls manually by a counter.

    If my guess is correct, among the added cuts, I wonder if the cuts that Gurobi evaluated as not helpful in improving the dual bound can improve the performance of the B&C in any way.

    They can improve it in the sense that they can be used to deduce new cuts as a combination of these unused cuts, or they can provide some implied bound information. Also, they can be useful only at certain point in the optimization process and then be dropped later.

    Best regards,
    Jaromił

    0
  • Jihye Jung
    Gurobi-versary
    First Comment
    First Question

    Dear Jaromił,

    Thanks to your comments, the interpretation of the experimental results has changed completely.
    I thought the results of my experiment were pretty bad, but after reading this answer, it turned out to be a pretty positive result. Happy about that :)

    This may be a slightly different topic, but may I add one more question about callback functions and user cuts?

    As I said, I am adding user cuts to the B&B process using a callback function.
    When I added a cut in all MIPNODEs that got the optimal relaxed solution, the performance was rather degraded. So, I modified the callback code as below to add a user cut only at the root node.

    def callback(model, where):
    if where == GRB.Callback.MIP:
    crt_cutcnt = model.cbGet(GRB.Callback.MIP_CUTCNT)
    if crt_cutcnt - model._cutcnt > 0:
    print('*** %s cut added...' % crt_cutcnt)
    model._cutcnt = crt_cutcnt
    if where == GRB.Callback.MIPNODE:
    model._nodecnt += 1
    if model.cbGet(GRB.Callback.MIPNODE_NODCNT) == 0:
    # Add a set of calculated cuts by model.cbCut(...)

    What I intended was:
    1. where == GRB.Callback.MIP: To print the message "*** XX cut added..." if a user cut is newly added
    (indeed I changed the "Cuts" parameter to 0, and the initial value of model._cutcnt is set to 0)
    2. where == GRB.Callback.MIPNODE: To add a set of user cuts only in the root node
    (I expressed the 'only in the root node' condition by model.cbGet(GRB.Callback.MIPNODE_NODCNT) == 0)

    However, the corresponding log is printed like below:

    Root relaxation: objective 7.000000e+00, 1839 iterations, 0.21 seconds

    Nodes | Current Node | Objective Bounds | Work
    Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time

    0 0 7.00000 0 288 - 7.00000 - - 0s
    *** 14 cut added...
    0 0 7.00000 0 288 - 7.00000 - - 0s
    *** 15 cut added...
    0 2 7.00000 0 288 - 7.00000 - - 0s
    *** 17 cut added...
    *** 19 cut added...
    *** 21 cut added...
    *** 23 cut added...
    *** 24 cut added...
    *** 25 cut added...
    23 32 7.00000 4 170 - 7.00000 - 2928 5s
    194 224 7.00000 13 131 - 7.00000 - 1309 11s
    *** 27 cut added...
    * 236 224 17 27.0000000 7.00000 74.1% 1090 11s
    *** 28 cut added...
    *** 29 cut added...
    *** 30 cut added...
    * 685 290 18 19.0000000 7.00000 63.2% 534 12s
    *** 31 cut added...
    *** 32 cut added...
    *** 33 cut added...
    *** 34 cut added...
    *** 35 cut added...
    * 1196 321 22 15.0000000 7.00000 53.3% 370 13s
    *** 36 cut added...
    *** 37 cut added...
    2279 401 infeasible 17 15.00000 7.00000 53.3% 258 15s
    5616 498 infeasible 11 15.00000 7.00000 53.3% 177 20s
    9479 655 7.00000 19 288 15.00000 7.00000 53.3% 151 25s
    9484 661 7.00000 16 253 15.00000 7.00000 53.3% 151 30s
    9490 671 7.00000 18 240 15.00000 7.00000 53.3% 154 39s
    9498 685 7.00000 19 173 15.00000 7.00000 53.3% 156 42s
    9562 723 7.00000 21 141 15.00000 7.00000 53.3% 169 45s
    9696 758 infeasible 24 15.00000 7.00000 53.3% 180 50s
    10460 590 7.00000 29 144 15.00000 7.00000 53.3% 205 56s
    11163 382 7.00000 36 158 15.00000 7.00000 53.3% 219 61s
    11984 292 7.00000 31 145 15.00000 7.00000 53.3% 230 66s
    13201 240 infeasible 32 15.00000 7.00000 53.3% 237 71s
    14073 249 infeasible 31 15.00000 7.00000 53.3% 244 75s
    15126 277 infeasible 29 15.00000 7.00000 53.3% 255 82s
    15619 270 infeasible 27 15.00000 7.00000 53.3% 266 86s
    16461 245 7.00000 37 123 15.00000 7.00000 53.3% 273 92s
    17087 208 11.00000 40 36 15.00000 7.00000 53.3% 276 95s
    17920 217 7.00000 28 160 15.00000 7.00000 53.3% 282 100s
    18635 235 7.00000 26 139 15.00000 7.00000 53.3% 290 106s
    19498 236 7.00000 32 151 15.00000 7.00000 53.3% 297 111s
    19897 253 11.00000 29 98 15.00000 7.00000 53.3% 301 115s
    21097 272 9.81481 28 177 15.00000 7.00000 53.3% 306 121s
    21779 248 7.00000 30 151 15.00000 7.00000 53.3% 308 125s
    23259 251 7.00000 35 144 15.00000 7.00000 53.3% 311 133s
    23770 263 cutoff 37 15.00000 7.00000 53.3% 314 137s
    24328 283 7.00000 34 147 15.00000 7.00000 53.3% 318 141s
    24901 296 cutoff 35 15.00000 7.00000 53.3% 322 145s
    25649 314 7.00000 35 50 15.00000 7.00000 53.3% 325 150s
    27303 331 7.00000 27 155 15.00000 7.00000 53.3% 329 160s
    28267 297 11.00000 31 55 15.00000 7.00000 53.3% 331 165s
    29230 317 7.00000 30 51 15.00000 7.00000 53.3% 333 170s
    29778 330 infeasible 32 15.00000 7.00000 53.3% 337 175s
    30510 310 7.00000 30 169 15.00000 7.00000 53.3% 339 181s
    31711 326 infeasible 35 15.00000 7.00000 53.3% 341 187s
    32763 318 7.00000 33 159 15.00000 7.00000 53.3% 341 192s
    33545 345 infeasible 33 15.00000 7.00000 53.3% 343 197s
    34563 350 infeasible 35 15.00000 7.00000 53.3% 345 203s
    35605 382 infeasible 34 15.00000 7.00000 53.3% 346 210s
    36812 403 infeasible 27 15.00000 7.00000 53.3% 347 216s
    37890 397 cutoff 32 15.00000 7.00000 53.3% 349 223s
    38967 392 10.60000 39 131 15.00000 7.00000 53.3% 351 231s
    40137 374 7.00000 22 162 15.00000 7.00000 53.3% 354 238s
    41407 369 7.00000 28 120 15.00000 7.00000 53.3% 356 246s
    42962 389 7.00000 36 133 15.00000 7.00000 53.3% 356 254s
    44443 356 7.00000 34 144 15.00000 7.00000 53.3% 357 262s
    45945 311 infeasible 37 15.00000 7.00000 53.3% 358 271s
    47315 273 7.00000 27 169 15.00000 7.00000 53.3% 360 279s
    48817 203 infeasible 37 15.00000 7.00000 53.3% 361 288s
    50491 199 infeasible 32 15.00000 7.00000 53.3% 361 296s
    51640 195 7.00000 35 137 15.00000 7.00000 53.3% 362 305s
    53444 109 7.00000 32 55 15.00000 7.00000 53.3% 362 313s
    54902 116 7.00000 35 109 15.00000 7.00000 53.3% 363 321s
    56177 108 infeasible 36 15.00000 7.00000 53.3% 363 330s
    57757 89 11.00000 40 114 15.00000 7.00000 53.3% 363 337s
    59373 142 11.44444 40 157 15.00000 7.00000 53.3% 363 345s
    60953 66 infeasible 30 15.00000 7.00000 53.3% 362 352s
    62549 23 7.00000 36 104 15.00000 7.00000 53.3% 361 356s
    63053 72 7.00000 28 142 15.00000 7.00000 53.3% 360 361s
    63898 34 infeasible 29 15.00000 7.00000 53.3% 361 367s
    64727 9 7.19162 35 171 15.00000 7.00000 53.3% 360 371s

    Explored 65139 nodes (23449581 simplex iterations) in 373.21 seconds
    Thread count was 16 (of 16 available processors)

    Solution count 3: 15 19 27

    Optimal solution found (tolerance 1.00e-04)
    Best objective 1.500000000000e+01, best bound 1.500000000000e+01, gap 0.0000%

    User-callback calls 167299, time in user-callback 0.79 sec

    As you can see in the log, Gurobi keeps adding some new cuts after some nodes are already explored.
    This is different with what I intended, because I guess if multiple nodes have been explored then the condition

     if model.cbGet(GRB.Callback.MIPNODE_NODCNT) == 0:

    will be immediately violated. The results that I found odd seem to be best expressed in this part of the log.
    (excerpted from the log above)

    *** 25 cut added...
    23 32 7.00000 4 170 - 7.00000 - 2928 5s
    194 224 7.00000 13 131 - 7.00000 - 1309 11s
    *** 27 cut added...
    * 236 224 17 27.0000000 7.00000 74.1% 1090 11s
    *** 28 cut added...

    Please note that below are the two main things I want to look at through this experiment.
    1. Whether user cuts were actually added to the B&B process, rather than how many times it was added
    2. Whether or not performance improvement occurs when user cuts are actually added

    I said that the number of added cuts is not the main concern, but I got the above result while printing the number of cuts to check whether user cuts are added only to the root node.

    Is the callback function programmed the way I intended?
    Why is the message that a cut is added even after multiple discovered nodes occur?
    It's a bit different from the first question, but I'd appreciate some help from the Gurobi expert.

    Thank you in advance.

    Best regards,
    Jihye

    0
  • Jaromił Najman
    Gurobi Staff Gurobi Staff

    This issue has been resolved internally. Here is a brief summary of what is happening.

    You see the number of added cuts MIP_CUTCNT increase because Gurobi does not directly use all user cuts. The cuts generated are initially stored in a so-called cut pool and added or removed from the solved problem.
    If you change your callback code to

    if where == GRB.Callback.MIP:
      crt_cutcnt = model.cbGet(GRB.Callback.MIP_CUTCNT)
      if crt_cutcnt != model._cutcnt: # here is the change
        print('*** %s cut added...' % crt_cutcnt)
        model._cutcnt = crt_cutcnt

    you will see that the cut count may also decrease due to Gurobi also removing some cuts from the problem.

    Eli has also answered a similar question in the post Ignored lazy constraint leads to wrong solution.

    Best regards,
    Jaromił

    0

Please sign in to leave a comment.

Powered by Zendesk