Incumbent callbacks during polishing

I keep hitting this issue where I have to use something like an incumbent callback from CPLEX in order to report progress, use a custom stopping criterion, save intermediate solutions, etc. This works fine in normal CPLEX B&B, but it seems that incumbent callbacks don't get called during polishing. I have at least one system where the best solutions are found by doing almost all search by polishing (e.g. start polishing after the first feasible solution found by B&B, and polish for the rest of the time, typically 2 hours).

In the extract from a log file below you can see the callback gets called once early in the search (the lines beginning like 8898059 [0x7f0aaec0c740] INFO'), and then CPLEX polishes for the remainder of the time limit (2 hours in this case, but I just included the log from the first hour or so) and finds more than 50 improving solutions but we never explore any more nodes of the B&B tree and the incumbent callback never gets called for those solutions

Root relaxation solution time = 469.28 sec. (170358.47 ticks)

Nodes Cuts/
Node Left Objective IInf Best Integer Best Bound ItCnt Gap

* 0+ 0 6392.5239 ---
Found incumbent of value 6392.523939 after 527.81 sec. (180188.26 ticks)
0 0 1681.8948 3775 6392.5239 1681.8948 19 73.69%
8898059 [0x7f0aaec0c740] INFO SpotBooker null - Writing 9238 spots in slotter file ../74251/74251Slot_20181109_0819_0004.csv
8898060 [0x7f0aaec0c740] INFO SpotBooker null - Creating SnpSolutionWriter
8898060 [0x7f0aaec0c740] INFO SpotBooker null - Writing solution in file
8898060 [0x7f0aaec0c740] INFO root null - SnpSolutionWriter::writeSolution(): Writing solution
8899094 [0x7f0aaec0c740] INFO SpotBooker null - Writing CampaignTimeband file ../74251/74251CmpTB_20181109_0819_0004.csv
8900500 [0x7f0aaec0c740] INFO SpotBooker null - Writing Break file ../74251/74251Break_20181109_0819_0004.csv
8901155 [0x7f0aaec0c740] INFO SpotBooker null - Writing Spot file ../74251/74251Spot_20181109_0819_0004.csv
8902914 [0x7f0aaec0c740] INFO SpotBooker null - Writing Campaign file ../74251/74251Cbfs_20181109_0819_0004.csv
8905087 [0x7f0aaec0c740] INFO SpotBooker null - Writing StrikeWeight file ../74251/74251Skw_20181109_0819_0004.csv
8912224 [0x7f0aaec0c740] INFO SpotBooker null - Writing Spotlength file ../74251/74251Spl_20181109_0819_0004.csv
8912569 [0x7f0aaec0c740] INFO SpotBooker null - Writing Stat file ../74251/ilogstat.csv
8912991 [0x7f0aaec0c740] INFO camgen.context null - TimeLimit for batch 0: 7200
8925486 [0x7f0aaec0c740] INFO camgen.context null - TimeLimit for batch 0: 7200
8929996 [0x7f0aaec0c740] INFO SpotBooker null - * New solution [4] (1018.77) Time is : 09/11/2018 10:47:56 198 Objective = 6392.52 TBShortFall = 3233.4 TBSurplus: = 587.731 SWshortfall = 23600.4 SPLshortfall = 271.638 CBshortfall = 2811.05 FSshortfall = 454 SPLSWshortfall = 7.27596e-12 SPLTBshortfall = 0
8929998 [0x7f0aaec0c740] INFO ienginestatus null - SOLUTIONFOUND, 4,../74251/74251Slot_20181109_0819_0004.csv, A new solution has been found.

Starting condition for polishing reached (PolishAfterIntSol).
Starting solution polishing.

0 2 1681.8948 3775 6392.5239 1681.8969 19 73.69%
Elapsed time = 612.76 sec. (188910.34 ticks, tree = 0.01 MB, solutions = 1)
* 1+ 1 2079.1194 1681.8969 19.11%
Found incumbent of value 2079.119398 after 642.78 sec. (199425.64 ticks)
* 1+ 1 2014.3022 1681.8969 16.50%
Found incumbent of value 2014.302214 after 651.17 sec. (200964.16 ticks)
* 1+ 1 1964.9403 1681.8969 14.40%
Found incumbent of value 1964.940271 after 660.00 sec. (202838.90 ticks)
* 1+ 1 1926.1641 1681.8969 12.68%
Found incumbent of value 1926.164087 after 699.20 sec. (214447.52 ticks)
* 1+ 1 1917.1946 1681.8969 12.27%
Found incumbent of value 1917.194559 after 730.07 sec. (223484.64 ticks)
* 1+ 1 1904.9701 1681.8969 11.71%
Found incumbent of value 1904.970112 after 734.03 sec. (224332.54 ticks)
* 1+ 1 1902.5002 1681.8969 11.60%
Found incumbent of value 1902.500223 after 740.16 sec. (225418.66 ticks)
* 1+ 1 1899.6258 1681.8969 11.46%
Found incumbent of value 1899.625844 after 745.94 sec. (226734.62 ticks)
* 1+ 1 1899.1907 1681.8969 11.44%
Found incumbent of value 1899.190748 after 752.44 sec. (228378.14 ticks)
* 1+ 1 1897.2340 1681.8969 11.35%
Found incumbent of value 1897.233952 after 759.34 sec. (230110.65 ticks)
* 1+ 1 1897.2074 1681.8969 11.35%
Found incumbent of value 1897.207421 after 812.86 sec. (245125.79 ticks)
* 1+ 1 1892.3549 1681.8969 11.12%
Found incumbent of value 1892.354947 after 855.48 sec. (256958.66 ticks)
* 1+ 1 1890.6748 1681.8969 11.04%
Found incumbent of value 1890.674812 after 863.39 sec. (258247.40 ticks)
* 1+ 1 1890.0481 1681.8969 11.01%
Found incumbent of value 1890.048120 after 871.42 sec. (259720.46 ticks)
* 1+ 1 1889.8012 1681.8969 11.00%
Found incumbent of value 1889.801216 after 879.79 sec. (261233.73 ticks)
* 1+ 1 1889.4482 1681.8969 10.98%
Found incumbent of value 1889.448231 after 886.03 sec. (262261.40 ticks)
* 1+ 1 1889.2712 1681.8969 10.98%
Found incumbent of value 1889.271214 after 894.17 sec. (263746.18 ticks)
* 1+ 1 1882.1903 1681.8969 10.64%
Found incumbent of value 1882.190299 after 973.27 sec. (290227.66 ticks)
* 1+ 1 1879.4758 1681.8969 10.51%
Found incumbent of value 1879.475841 after 998.97 sec. (297512.41 ticks)
* 1+ 1 1877.7263 1681.8969 10.43%
Found incumbent of value 1877.726256 after 1026.28 sec. (304476.59 ticks)
* 1+ 1 1876.9111 1681.8969 10.39%
Found incumbent of value 1876.911074 after 1051.40 sec. (311305.01 ticks)
* 1+ 1 1874.4944 1681.8969 10.27%
Found incumbent of value 1874.494379 after 1075.35 sec. (317817.35 ticks)
* 1+ 1 1874.2825 1681.8969 10.26%
Found incumbent of value 1874.282520 after 1105.00 sec. (326985.17 ticks)
* 1+ 1 1871.8066 1681.8969 10.15%
Found incumbent of value 1871.806562 after 1509.44 sec. (471920.11 ticks)
* 1+ 1 1867.4764 1681.8969 9.94%
Found incumbent of value 1867.476371 after 1531.07 sec. (477737.52 ticks)
* 1+ 1 1866.0550 1681.8969 9.87%
Found incumbent of value 1866.055013 after 1550.36 sec. (482770.32 ticks)
* 1+ 1 1865.3992 1681.8969 9.84%
Found incumbent of value 1865.399192 after 1567.93 sec. (487298.24 ticks)
* 1+ 1 1862.9764 1681.8969 9.72%
Found incumbent of value 1862.976374 after 1586.15 sec. (491752.99 ticks)
* 1+ 1 1862.5586 1681.8969 9.70%
Found incumbent of value 1862.558599 after 1609.78 sec. (498299.88 ticks)
* 1+ 1 1862.4833 1681.8969 9.70%
Found incumbent of value 1862.483313 after 1631.96 sec. (505004.08 ticks)
* 1+ 1 1862.4054 1681.8969 9.69%
Found incumbent of value 1862.405386 after 1653.75 sec. (511317.31 ticks)
* 1+ 1 1857.3918 1681.8969 9.45%
Found incumbent of value 1857.391837 after 1937.79 sec. (612501.39 ticks)
* 1+ 1 1855.4681 1681.8969 9.35%
Found incumbent of value 1855.468088 after 1956.17 sec. (617319.58 ticks)
* 1+ 1 1853.7645 1681.8969 9.27%
Found incumbent of value 1853.764490 after 1972.54 sec. (621470.95 ticks)
* 1+ 1 1853.0617 1681.8969 9.24%
Found incumbent of value 1853.061680 after 1994.26 sec. (627600.77 ticks)
* 1+ 1 1852.9257 1681.8969 9.23%
Found incumbent of value 1852.925693 after 2019.86 sec. (634843.00 ticks)
* 1+ 1 1852.6118 1681.8969 9.21%
Found incumbent of value 1852.611836 after 2053.03 sec. (644496.95 ticks)
* 1+ 1 1851.6808 1681.8969 9.17%
Found incumbent of value 1851.680769 after 2379.66 sec. (748425.72 ticks)
* 1+ 1 1847.0864 1681.8969 8.94%
Found incumbent of value 1847.086441 after 2395.34 sec. (752666.92 ticks)
* 1+ 1 1846.1921 1681.8969 8.90%
Found incumbent of value 1846.192101 after 2420.30 sec. (759344.96 ticks)
* 1+ 1 1846.0849 1681.8969 8.89%
Found incumbent of value 1846.084883 after 2448.67 sec. (767801.01 ticks)
* 1+ 1 1845.9334 1681.8969 8.89%
Found incumbent of value 1845.933423 after 2466.65 sec. (772787.58 ticks)
* 1+ 1 1844.5498 1681.8969 8.82%
Found incumbent of value 1844.549812 after 2761.02 sec. (871509.92 ticks)
* 1+ 1 1842.7488 1681.8969 8.73%
Found incumbent of value 1842.748787 after 2787.84 sec. (878516.05 ticks)
* 1+ 1 1840.0397 1681.8969 8.59%
Found incumbent of value 1840.039691 after 2818.94 sec. (886814.38 ticks)
* 1+ 1 1839.9790 1681.8969 8.59%
Found incumbent of value 1839.979013 after 2861.71 sec. (899589.51 ticks)
* 1+ 1 1839.6265 1681.8969 8.57%
Found incumbent of value 1839.626534 after 2897.39 sec. (910314.12 ticks)
* 1+ 1 1838.9105 1681.8969 8.54%
Found incumbent of value 1838.910492 after 2931.59 sec. (919793.41 ticks)
* 1+ 1 1837.7080 1681.8969 8.48%
Found incumbent of value 1837.707978 after 3324.43 sec. (1053017.61 ticks)
* 1+ 1 1836.2549 1681.8969 8.41%
Found incumbent of value 1836.254902 after 3340.79 sec. (1057597.31 ticks)
* 1+ 1 1835.8271 1681.8969 8.38%
Found incumbent of value 1835.827122 after 3358.95 sec. (1062445.32 ticks)
* 1+ 1 1834.6973 1681.8969 8.33%
Found incumbent of value 1834.697255 after 3377.83 sec. (1067471.24 ticks)
* 1+ 1 1834.2800 1681.8969 8.31%
Found incumbent of value 1834.279957 after 3404.80 sec. (1074357.22 ticks)
* 1+ 1 1834.2488 1681.8969 8.31%

Post comment

Guest

Reply | Jan 28, 2020

The requested behavior is implemented. What the user reports can only have been a bug with an older version of CPLEX. I am attaching a code and logs that I created with 12.10 and the legacy as well as the generic callback. In all cases you can see that polishing starts at the root and at node 1 we find more than one incumbent. For all these incumbents the callback gets invoked. The model I used here was markshare1.

// Test invocation of incumbent callback even in phase II of polishing.
#include <cmath>
#include <cstring>
#include <limits>
#include <iostream>
#include <ilcplex/ilocplex.h>
#include <ilconcert/ilothread.h>

using std::cout;
using std::endl;

IloFastMutex mtx;
double lastIncumbent = std::numeric_limits<double>::quiet_NaN();

class GenericIncumbent : public IloCplex::Callback::Function {
public:
GenericIncumbent() {}
   void invoke(IloCplex::Callback::Context const &context) {
      // We assume that we are invoked in the Candidate context and
      // query the proposed solution value.
      // If that is different from the last solution seen, then we have
      // found a new incumbent.
      // In that case we could also query the x vector via
      // context.getIncumbent()
      double obj = context.getCandidateObjective();
      mtx.lock();
      if ( isnan(lastIncumbent) ||
           obj < lastIncumbent )
      {
         cout << "#### New incumbent (generic): " << obj << endl;
         lastIncumbent = obj;
      }
      mtx.unlock();
   }
};

// Legacy incumbent callback.
ILOINCUMBENTCALLBACK0(LegacyIncumbent) {
   // We assume that the proposed solution will become the next incumbent
   // (this is however NOT guaranteed!). If the objective is different from
   // the last objective we saw then we conclude that we have a new incumbent
   // and report it.
   // In that case we could also query the x vector via getValue()
   double obj = getObjValue();
   mtx.lock();
   if ( isnan(lastIncumbent) ||
        obj < lastIncumbent )
   {
      cout << "#### New incumbent (legacy): " << obj << endl;
      lastIncumbent = obj;
   }
   mtx.unlock();
}

int
main(int argc, char **argv)
{
   bool useGeneric = true;

   for (int i = 1; i < argc; ++i) {
      if ( ::strcmp(argv[i], "--generic") == 0 )
         useGeneric = true;
      else if ( ::strcmp(argv[i], "--no-generic") == 0 )
         useGeneric = false;
      else {
         IloEnv env;
         IloModel model(env);
         IloCplex cplex(model);
         cplex.importModel(model, argv[i]);
         GenericIncumbent generic;
         if ( useGeneric )
            cplex.use(&generic, IloCplex::Callback::Context::Id::Candidate);
         else {
            cplex.use(LegacyIncumbent(env));
            cplex.setParam(IloCplex::Param::Threads, cplex.getNumCores());
         }

         cplex.setParam(IloCplex::Param::MIP::Limits::Nodes, 100);
         cplex.setParam(IloCplex::Param::MIP::PolishAfter::Nodes, 1);

         cplex.solve();

         env.end();
      }
   }

   return 0;
}

generic.log

legacy.log

Guest

Reply
| Jan 4, 2019

This looks more a bug than a missing feature. I just tried to reproduce this and failed. Both with 12.7 and 12.8 the incumbent callback is invoked for any solution that is found during polishing.

Can you get in contact with the developers by posting on the forum at https://www.ibm.com/developerworks/community/forums/html/forum?id=11111111-0000-0000-0000-000000002059?

0 reply Hide replies

By clicking the "Post Comment" or "Submit Idea" button, you are agreeing to the IBM Ideas Portal Terms of Use.
Do not place IBM confidential, company confidential, or personal information into any field.

Please enter your email address

RELATED IDEAS

Incumbent callbacks during polishing