Injecting Heuristic Solution with Callback is Very Slow
OngoingHi,
I have a heuristic for a difficult MIP I am solving. I'm using two processes, similar to How do I inject a solution calculated in a separate process? – Gurobi Support Portal . Although my heuristic is fast, there seem to be two problems that prevent it from making the optimization process fast. First, Gurobi takes a long time before calling the callback with where == MIPNODE (>10 mins after root relaxation finished).
Second, although Gurobi realizes my solution in feasible, and returns the right objective from cbUseSolution(), it doesn't seem to do anything with it.
Here's a snippet from the log:
Gurobi Optimizer version 9.1.1 build v9.1.1rc0 (linux64)
Thread count: 48 physical cores, 96 logical processors, using up to 32 threads
Optimize a model with 648960 rows, 9440257 columns and 28327680 nonzeros
Model fingerprint: 0xa0754ebb
Model has 638976 SOS constraints
[...]
Barrier solved model in 5 iterations and 157.23 seconds
Optimal objective 2.00000000e+01
Root crossover log...
223681 variables added to crossover basis 215s
225769 DPushes remaining with DInf 0.0000000e+00 219s
1217 DPushes remaining with DInf 0.0000000e+00 341s
126 DPushes remaining with DInf 0.0000000e+00 362s
0 DPushes remaining with DInf 0.0000000e+00 369s
8 PPushes remaining with PInf 0.0000000e+00 369s
0 PPushes remaining with PInf 0.0000000e+00 370s
Push phase complete: Pinf 0.0000000e+00, Dinf 1.2060309e09 370s
Root simplex log...
Iteration Objective Primal Inf. Dual Inf. Time
225770 2.0000000e+01 0.000000e+00 0.000000e+00 370s
225770 2.0000000e+01 0.000000e+00 0.000000e+00 374s
Solved with barrier
Root relaxation: objective 2.000000e+01, 225770 iterations, 244.84 seconds
Nodes  Current Node  Objective Bounds  Work
Expl Unexpl  Obj Depth IntInf  Incumbent BestBd Gap  It/Node Time
0 0 20.00000 0 9768  20.00000   378s
H 0 0 30.0000000 20.00000 33.3%  803s
MIPNODE at 1068.8488900661469
Solution objective value: 20.0
It doesn't print anything else for at least the next hour. Since the heuristic solution turns out to be optimal in this case, I would expect Gurobi to terminate almost with the OPTIMAL status code immediately after the cbUseSolution() call.
Here's the version of the callback I'm using to reproduce this issue.
def callback(model, where):
if where == GRB.Callback.MIPNODE:
print("MIPNODE at", model.cbGet(GRB.Callback.RUNTIME))
with open("heuristic.txt", "r") as f:
for line in f:
l2 = line.rstrip('\n')
v = model.getVarByName(l2)
if v:
model.cbSetSolution(v, 0)
else:
print "Could not find", l2
print("Solution objective value:", model.cbUseSolution())

Hi Philip,
It is possible that all available threads are occupied by a heuristic, thus resulting in a long waiting time for information to be processed to the main thread. You could try disabling all heuristics by setting Heuristics=0 and or MIPFocus=3. This will turn off the searches for feasible points and should get to your callback quicker.
Best regards,
Jaromił0 
Hi Jaromił,
Thanks for the response. I tried the two parameter settings you suggested, and it they did not help. The first MIPNODE callback happened 1300s after the root relaxation finished, and >1 hour into the solve, it still has not terminated, in spite of the callback providing an optimal solution.
I am happy to share the model and code to reproduce the issue.
Thanks,
Philip
0 
Setting Cuts=0, it solves in about an hour, but it still does not seem to be using my heuristic solution, in spite of returning the correct objective from cbUseSolution()
Nodes  Current Node  Objective Bounds  Work
Expl Unexpl  Obj Depth IntInf  Incumbent BestBd Gap  It/Node Time
0 0 20.00000 0 9729  20.00000   394s
H 0 0 30.0000000 20.00000 33.3%  793s
MIPNODE at 803.6793129444122
Solution objective value: 20.0
0 0 20.00000 0 9729 30.00000 20.00000 33.3%  836s
MIPNODE at 837.3833448886871
Solution objective value: 20.0
MIPNODE at 2788.5118820667267
Solution objective value: 20.0
H 0 2 20.0000000 20.00000 0.00%  2816s
0 2 20.00000 0 9729 20.00000 20.00000 0.00%  2816s
Explored 1 nodes (226447 simplex iterations) in 2817.82 seconds
Thread count was 32 (of 96 available processors)
Solution count 2: 20 30
Optimal solution found (tolerance 1.00e04)
Best objective 2.000000000000e+01, best bound 2.000000000000e+01, gap 0.0000%Usercallback calls 167689, time in usercallback 75.82 sec
So updating the two problems with this information:
 Gurobi accepts an optimal heuristic solution (as determined by cbUseSolution) but then ignores it (at least for 2000s)
 Gurobi spends a lot of time making fruitless attempts to make cuts on this problem
The second problem may just be something strange with my model, but the first problem seems to be a real issue to me.
0 
I think that you have just hit a small quirk in our callback behavior at the root node. Namely, the solution *is* accepted, but at the time the next log line directly after the callback invocation is printed, this solution is not yet integrated into the global data structures. Hence, you only see your solution at the next log line. Unfortunately, in your case the next log line comes 2000 seconds later.
This is a behavior that we have already fixed in our development code. So, with the next minor/major version of Gurobi this should no longer happen.
Regards,
Tobias
0 
Hi Tobias,
Thanks, that makes sense. I'm looking forward to the fix.
Thanks,
Philip
0 
Dear all,
was this issue resolved? I have found the same or a very similar problem that I cannot solve:
Thank you
Mike
0
Please sign in to leave a comment.
Comments
6 comments