Thursday, February 10, 2011

Difficult node

I was solving a fairly large MIP with Cplex. Here is a fragment of the log (note: this is on one single thread):

Elapsed real time = 566.11 sec. (tree size =  2.99 MB, solutions = 10)
    481   264        cutoff         506640.0000   520455.3013   261404    2.73%
    482   265   506826.9584 11312   506640.0000   520455.3013   261459    2.73%
    483   264        cutoff         506640.0000   520455.3013   261614    2.73%
    484   263        cutoff         506640.0000   520455.3013   261651    2.73%
    485   264   520249.4385 15602   506640.0000   520320.2694   261735    2.70%
    486   265   518128.2823 15362   506640.0000   520320.2694   262612    2.70%
    487   266   516143.3611 14872   506640.0000   520320.2694   263324    2.70%
    488   267   523860.6453 19418   506640.0000   520320.2694   300816    2.70%
    489   268   520653.5158 16789   506640.0000   520320.2694   303721    2.70%
    490   269   518087.1120 16662   506640.0000   520320.2694   304842    2.70%
Elapsed real time = 1006.14 sec. (tree size =  3.01 MB, solutions = 10)

So at node 481 we have spent about 500 seconds, so Cplex progresses at about one node per second. Then suddenly we hit node 488, which takes roughly 500 seconds on its own! (I.e. two fairly related LPs can have solution times differ by a factor of 500!) After that Cplex goes on at the original speed. Indeed this was a very difficult LP: Cplex seems to be in serious trouble and is continuously spitting out the message: Reinitializing dual norms . . .

Note: this was with default settings (except for some more logging to find out what was going on) and on one thread.

The complete LP log for this node looks like:

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

    487   266   516143.3611 14872   506640.0000   520320.2694   263324    2.70%
Reinitializing dual norms . . .
Presolve time =    0.03 sec.

Iteration log . . .
Iteration:     1   Dual objective     =      -3841906.151524
Iteration:    99   Dual objective     =      -3841903.731889
Iteration:   241   Dual objective     =      -3841896.325263
Iteration:   497   Dual objective     =      -3833124.702332
Iteration:   983   Dual objective     =      -3797471.390188
Iteration:  1523   Dual objective     =      -3754303.279927
Iteration:  2080   Dual objective     =      -3707798.471109
Iteration:  2710   Dual objective     =      -3656679.526552
Iteration:  2907   Dual objective     =      -3630332.738058
Iteration:  3533   Dual objective     =      -3595507.425059
Iteration:  3735   Dual objective     =      -3576274.079757
Iteration:  4430   Dual objective     =      -3524336.790331
Iteration:  4678   Dual objective     =      -3490669.838329
Iteration:  5354   Dual objective     =      -3448480.284408
Iteration:  5606   Dual objective     =      -3428625.257030
Iteration:  6315   Dual objective     =      -3367003.220315
Iteration:  6468   Dual objective     =      -3349361.379134
Iteration:  7155   Dual objective     =      -3297319.745665
Iteration:  7329   Dual objective     =      -3281513.998036
Iteration:  8037   Dual objective     =      -3209022.397667
Iteration:  8161   Dual objective     =      -3199124.408539
Iteration:  8901   Dual objective     =      -3124981.851110
Iteration:  9079   Dual objective     =      -3108232.351078
Iteration:  9776   Dual objective     =      -3034039.972295
Iteration:  9968   Dual objective     =      -3016600.770835
Iteration: 10673   Dual objective     =      -2952710.711324
Iteration: 10803   Dual objective     =      -2945017.948468
Iteration: 11448   Dual objective     =      -2898918.669928
Iteration: 11618   Dual objective     =      -2887124.836641
Iteration: 12273   Dual objective     =      -2848398.670676
Iteration: 12416   Dual objective     =      -2836891.004217
Iteration: 13067   Dual objective     =      -2785546.502463
Iteration: 13179   Dual objective     =      -2776722.955055
Iteration: 13934   Dual objective     =      -2676147.352767
Iteration: 14095   Dual objective     =      -2666906.348111
Iteration: 14836   Dual objective     =      -2529741.300207
Iteration: 14995   Dual objective     =      -2511660.451169
Iteration: 15481   Dual objective     =      -2471645.239424
Iteration: 16014   Dual objective     =      -2432226.214840
Iteration: 16562   Dual objective     =      -2395094.381369
Iteration: 17059   Dual objective     =      -2357603.822987
Iteration: 17459   Dual objective     =      -2326713.124520
Iteration: 17742   Dual objective     =      -2317912.703615
Iteration: 18112   Dual objective     =      -2286965.681775
Iteration: 18471   Dual objective     =      -2260883.577792
Iteration: 18759   Dual objective     =      -2243191.450463
Iteration: 19115   Dual objective     =      -2219254.325035
Iteration: 19409   Dual objective     =      -2188802.191091
Iteration: 19714   Dual objective     =      -2168006.118507
Iteration: 19995   Dual objective     =      -2144692.352121
Iteration: 20279   Dual objective     =      -2119330.380293
Iteration: 20557   Dual objective     =      -2101269.034905
Iteration: 20798   Dual objective     =      -2077386.394778
Reinitializing dual norms . . .
Computed 1 new norms.

Iteration log . . .
Iteration:     1   Dual objective     =        523929.554470
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Computed 1 new norms.

Iteration log . . .
Iteration:     1   Dual objective     =        523906.181764
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Presolve time =    0.03 sec.

Iteration log . . .
Iteration:     1   Dual objective     =      -3841905.976331
Iteration:   105   Dual objective     =      -3841903.131273
Iteration:   246   Dual objective     =      -3841896.140704
Iteration:   507   Dual objective     =      -3838713.068222
Iteration:   894   Dual objective     =      -3811626.518779
Iteration:  1354   Dual objective     =      -3764349.808794
Iteration:  1950   Dual objective     =      -3716691.151902
Iteration:  2529   Dual objective     =      -3671720.678326
Iteration:  3126   Dual objective     =      -3630785.254997
Iteration:  3710   Dual objective     =      -3580631.257956
Iteration:  3915   Dual objective     =      -3556381.872188
Iteration:  4542   Dual objective     =      -3516125.176397
Iteration:  4758   Dual objective     =      -3480770.191419
Iteration:  5413   Dual objective     =      -3420932.778138
Iteration:  5630   Dual objective     =      -3398017.816329
Iteration:  6302   Dual objective     =      -3351246.558220
Iteration:  6581   Dual objective     =      -3305563.181271
Iteration:  7184   Dual objective     =      -3257758.571097
Iteration:  7833   Dual objective     =      -3192802.673832
Iteration:  8011   Dual objective     =      -3166992.105016
Iteration:  8636   Dual objective     =      -3116200.958218
Iteration:  8832   Dual objective     =      -3098684.775319
Iteration:  9432   Dual objective     =      -3043570.270174
Iteration: 10080   Dual objective     =      -2985600.061041
Iteration: 10235   Dual objective     =      -2973830.203254
Iteration: 10801   Dual objective     =      -2916211.021159
Iteration: 11360   Dual objective     =      -2867799.539015
Iteration: 11875   Dual objective     =      -2823950.498423
Iteration: 12332   Dual objective     =      -2779467.977983
Iteration: 12825   Dual objective     =      -2727943.967284
Iteration: 13292   Dual objective     =      -2696406.098426
Iteration: 13700   Dual objective     =      -2647176.945812
Iteration: 14200   Dual objective     =      -2600457.134997
Iteration: 14508   Dual objective     =      -2576935.786560
Iteration: 14906   Dual objective     =      -2546799.151262
Iteration: 15300   Dual objective     =      -2521837.128016
Iteration: 15676   Dual objective     =      -2496890.187652
Iteration: 16059   Dual objective     =      -2448672.938679
Iteration: 16389   Dual objective     =      -2420917.892289
Iteration: 16724   Dual objective     =      -2393328.883271
Iteration: 17041   Dual objective     =      -2368571.737103
Iteration: 17394   Dual objective     =      -2343239.451580
Iteration: 17760   Dual objective     =      -2314625.526527
Iteration: 18138   Dual objective     =      -2282459.585867
Iteration: 18459   Dual objective     =      -2257788.748656
Iteration: 18826   Dual objective     =      -2234141.675548
Iteration: 19121   Dual objective     =      -2215471.592131
Iteration: 19458   Dual objective     =      -2169441.476149
Iteration: 19687   Dual objective     =      -2147757.029749
Iteration: 19951   Dual objective     =      -2128010.300581
Iteration: 20217   Dual objective     =      -2109334.737229
Iteration: 20475   Dual objective     =      -2089396.930805
Iteration: 20718   Dual objective     =      -2065209.659076
Reinitializing dual norms . . .
Computed 1 new norms.

Iteration log . . .
Iteration:     1   Dual objective     =        523888.142422
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Presolve time =    0.03 sec.

Iteration log . . .
Iteration:     1   Dual objective     =      -3841905.859545
Iteration:    99   Dual objective     =      -3841903.011398
Iteration:   252   Dual objective     =      -3841894.692271
Iteration:   507   Dual objective     =      -3840844.436812
Iteration:   905   Dual objective     =      -3809177.025401
Iteration:  1316   Dual objective     =      -3775269.438552
Iteration:  1847   Dual objective     =      -3733280.272145
Iteration:  2455   Dual objective     =      -3686179.494274
Iteration:  3027   Dual objective     =      -3635995.451702
Iteration:  3613   Dual objective     =      -3575891.460385
Iteration:  4217   Dual objective     =      -3496438.081595
Iteration:  4409   Dual objective     =      -3477268.125179
Iteration:  5032   Dual objective     =      -3425225.190150
Iteration:  5232   Dual objective     =      -3396735.913136
Iteration:  5812   Dual objective     =      -3344119.616512
Iteration:  5994   Dual objective     =      -3321794.756722
Iteration:  6634   Dual objective     =      -3274723.634367
Iteration:  6821   Dual objective     =      -3259306.213635
Iteration:  7416   Dual objective     =      -3213995.241698
Iteration:  8062   Dual objective     =      -3166963.054004
Iteration:  8219   Dual objective     =      -3141047.190671
Iteration:  8770   Dual objective     =      -3088144.368722
Iteration:  9383   Dual objective     =      -3043848.339080
Iteration:  9495   Dual objective     =      -3027140.462055
Iteration: 10036   Dual objective     =      -2974233.962473
Iteration: 10659   Dual objective     =      -2927848.584815
Iteration: 10797   Dual objective     =      -2912746.475612
Iteration: 11289   Dual objective     =      -2875567.761266
Iteration: 11798   Dual objective     =      -2840664.791129
Iteration: 12342   Dual objective     =      -2797566.877039
Iteration: 12727   Dual objective     =      -2770685.813501
Iteration: 13099   Dual objective     =      -2745235.944352
Iteration: 13515   Dual objective     =      -2694449.998233
Iteration: 13832   Dual objective     =      -2660934.552350
Iteration: 14179   Dual objective     =      -2628050.031466
Iteration: 14533   Dual objective     =      -2594714.859274
Iteration: 14825   Dual objective     =      -2569509.967392
Iteration: 15223   Dual objective     =      -2537750.563217
Iteration: 15567   Dual objective     =      -2506461.651899
Iteration: 15922   Dual objective     =      -2478535.086325
Iteration: 16294   Dual objective     =      -2446453.392772
Iteration: 16712   Dual objective     =      -2417198.307122
Iteration: 17103   Dual objective     =      -2389918.152437
Iteration: 17446   Dual objective     =      -2361544.098618
Iteration: 17805   Dual objective     =      -2323321.344454
Iteration: 18130   Dual objective     =      -2295890.457439
Iteration: 18429   Dual objective     =      -2267865.598547
Iteration: 18764   Dual objective     =      -2241635.477994
Iteration: 19102   Dual objective     =      -2219171.747238
Iteration: 19393   Dual objective     =      -2201003.266337
Iteration: 19703   Dual objective     =      -2168361.607889
Iteration: 19966   Dual objective     =      -2146698.281697
Iteration: 20201   Dual objective     =      -2129147.245370
Iteration: 20473   Dual objective     =      -2112044.456781
Iteration: 20708   Dual objective     =      -2091320.760407
Iteration: 20948   Dual objective     =      -2068652.616732
Elapsed time =   10.25 sec. (21000 iterations).
Removing shift (3).
Reinitializing dual norms . . .
Computed 1 new norms.

Iteration log . . .
Iteration:     1   Dual objective     =        523877.088929
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Presolve time =    0.03 sec.

Iteration log . . .
Iteration:     1   Dual objective     =      -3840905.859289
Iteration:   111   Dual objective     =      -3840901.781364
Iteration:   255   Dual objective     =      -3840894.955055
Iteration:   530   Dual objective     =      -3838423.971391
Iteration:   934   Dual objective     =      -3811190.826782
Iteration:  1412   Dual objective     =      -3770968.413699
Iteration:  1966   Dual objective     =      -3724619.229468
Iteration:  2508   Dual objective     =      -3681003.182495
Iteration:  3134   Dual objective     =      -3619745.869940
Iteration:  3359   Dual objective     =      -3597761.093610
Iteration:  3972   Dual objective     =      -3547987.766113
Iteration:  4104   Dual objective     =      -3527687.383389
Iteration:  4729   Dual objective     =      -3484211.813874
Iteration:  4849   Dual objective     =      -3471174.793623
Iteration:  5508   Dual objective     =      -3395794.140659
Iteration:  5720   Dual objective     =      -3364920.618928
Iteration:  6366   Dual objective     =      -3311864.221638
Iteration:  6526   Dual objective     =      -3290496.894007
Iteration:  7151   Dual objective     =      -3238996.954757
Iteration:  7355   Dual objective     =      -3216734.052015
Iteration:  7966   Dual objective     =      -3172060.564789
Iteration:  8130   Dual objective     =      -3141962.604523
Iteration:  8478   Dual objective     =      -3125913.484428
Iteration:  9073   Dual objective     =      -3084804.105078
Iteration:  9241   Dual objective     =      -3065996.829086
Iteration:  9861   Dual objective     =      -3022778.754723
Iteration: 10036   Dual objective     =      -3001305.436291
Iteration: 10618   Dual objective     =      -2956861.405358
Iteration: 11226   Dual objective     =      -2904836.050621
Iteration: 11364   Dual objective     =      -2879737.142725
Iteration: 11978   Dual objective     =      -2827528.141727
Iteration: 12522   Dual objective     =      -2778344.958494
Iteration: 13123   Dual objective     =      -2735431.400412
Iteration: 13254   Dual objective     =      -2722723.228038
Iteration: 13708   Dual objective     =      -2688725.520148
Iteration: 14206   Dual objective     =      -2644193.874635
Iteration: 14612   Dual objective     =      -2608451.406095
Iteration: 15006   Dual objective     =      -2574086.254795
Iteration: 15370   Dual objective     =      -2536744.234629
Iteration: 15661   Dual objective     =      -2508429.430368
Iteration: 16002   Dual objective     =      -2461115.509406
Iteration: 16298   Dual objective     =      -2435990.094437
Iteration: 16573   Dual objective     =      -2420977.915271
Iteration: 16864   Dual objective     =      -2397827.290436
Iteration: 17165   Dual objective     =      -2372269.058156
Iteration: 17473   Dual objective     =      -2345540.989320
Iteration: 17827   Dual objective     =      -2315238.411661
Iteration: 18147   Dual objective     =      -2289384.407639
Iteration: 18456   Dual objective     =      -2263582.408460
Iteration: 18766   Dual objective     =      -2236149.254510
Iteration: 19071   Dual objective     =      -2212305.396149
Iteration: 19349   Dual objective     =      -2190088.392541
Iteration: 19649   Dual objective     =      -2163044.832584
Iteration: 19929   Dual objective     =      -2140726.127525
Iteration: 20207   Dual objective     =      -2114310.292130
Iteration: 20496   Dual objective     =      -2090483.500058
Iteration: 20755   Dual objective     =      -2069427.314509
Reinitializing dual norms . . .
Computed 1 new norms.

Iteration log . . .
Iteration:     1   Dual objective     =        523867.937469
Reinitializing dual norms . . .
Reinitializing dual norms . . .
Presolve time =    0.03 sec.

Iteration log . . .
Iteration:     1   Dual objective     =      -3841905.684309
Iteration:   102   Dual objective     =      -3841902.368505
Iteration:   242   Dual objective     =      -3841895.458341
Iteration:   446   Dual objective     =      -3841858.381207
Iteration:   908   Dual objective     =      -3808120.328684
Iteration:  1416   Dual objective     =      -3759415.354532
Iteration:  1946   Dual objective     =      -3713342.954175
Iteration:  2525   Dual objective     =      -3671109.120111
Iteration:  3148   Dual objective     =      -3609938.455464
Iteration:  3382   Dual objective     =      -3591930.736391
Iteration:  4076   Dual objective     =      -3536427.782319
Iteration:  4241   Dual objective     =      -3519684.477469
Iteration:  4930   Dual objective     =      -3466183.836278
Iteration:  5105   Dual objective     =      -3453148.164249
Iteration:  5742   Dual objective     =      -3410829.614027
Iteration:  5997   Dual objective     =      -3382621.231157
Iteration:  6673   Dual objective     =      -3322131.625983
Iteration:  6856   Dual objective     =      -3303631.351765
Iteration:  7541   Dual objective     =      -3242563.692165
Iteration:  7677   Dual objective     =      -3229271.706031
Iteration:  8351   Dual objective     =      -3161003.248438
Iteration:  8543   Dual objective     =      -3146631.715661
Iteration:  9230   Dual objective     =      -3068916.507137
Iteration:  9402   Dual objective     =      -3056940.594695
Iteration: 10108   Dual objective     =      -2975325.285378
Iteration: 10245   Dual objective     =      -2967363.473985
Iteration: 10906   Dual objective     =      -2897291.543370
Iteration: 11078   Dual objective     =      -2884264.928677
Iteration: 11717   Dual objective     =      -2830500.429613
Iteration: 11890   Dual objective     =      -2822953.499725
Iteration: 12530   Dual objective     =      -2781511.117474
Iteration: 12653   Dual objective     =      -2770352.078919
Iteration: 13351   Dual objective     =      -2714405.298354
Iteration: 13517   Dual objective     =      -2701607.391427
Iteration: 14236   Dual objective     =      -2571915.256287
Iteration: 14342   Dual objective     =      -2563894.537950
Iteration: 14986   Dual objective     =      -2521491.973658
Iteration: 15118   Dual objective     =      -2507367.609192
Iteration: 15752   Dual objective     =      -2454310.911041
Iteration: 15855   Dual objective     =      -2443780.980640
Iteration: 16342   Dual objective     =      -2404960.527602
Iteration: 16786   Dual objective     =      -2376519.420939
Iteration: 17077   Dual objective     =      -2359029.320287
Iteration: 17414   Dual objective     =      -2331088.015172
Iteration: 17748   Dual objective     =      -2313699.479563
Iteration: 18054   Dual objective     =      -2290905.688281
Iteration: 18429   Dual objective     =      -2270198.643206
Iteration: 18829   Dual objective     =      -2245495.320022
Iteration: 19218   Dual objective     =      -2214040.055476
Iteration: 19564   Dual objective     =      -2188027.403627
Iteration: 19967   Dual objective     =      -2136895.020708
Iteration: 20207   Dual objective     =      -2121770.217450
Iteration: 20434   Dual objective     =      -2102058.769866
Iteration: 20665   Dual objective     =      -2085525.678917
Iteration: 20872   Dual objective     =      -2066060.338356
Reinitializing dual norms . . .

Iteration log . . .
Iteration:     1   Dual objective     =        523859.779283
Iteration:   231   Dual objective     =        519501.559686
Reinitializing dual norms . . .
Reinitializing dual norms . . .

Iteration log . . .
Iteration:     1   Dual objective     =        523859.749337
Reinitializing dual norms . . .

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

    488   267   523860.6453 19418   506640.0000   520320.2694   300816    2.70%

6 comments:

  1. It looks to me it's solving several LP's at this node, so I am quite sure it's doing more than branching. Also I do not think it's the actual solving of the LP's which is expensive.

    The message "Reinitializing dual norms" is just that CPLEX is trying to reuse dual norms between nodes in a cleaver way (my guess), otherwise it has to start with unit norms in many cases. So that's perfectly OK and should give you speed-up in many cases.

    ReplyDelete
  2. I think I disagree with Bo here. I took this to mean that it was solving a single node LP (by dual simplex, I assume) and was struggling with numerical instability, forcing it to reinitialize dual norms (is that similar to refactoring a basis?). I think the repeat presolve parameter must also be on (can't recall if what the default for that is, but I think maybe "let CPLEX use it's own judgment").

    It would be interesting to know whether the numerical emphasis parameter would make a difference, but no guarantee you'd get the same search tree with the new parameter setting.

    ReplyDelete
  3. Glad there is disagreement here: I am no longer ashamed that I am confused about Cplex's behavior here.

    ReplyDelete
  4. I am also just guessing here, since the output is a bit strange. So Paul could be right too. To me I does not look like cplex restart due to numerical issues, if that where the case you would see them raising markowitz tolerance in LU and other stuff. But as said I could be wrong.

    The dual norms can be updated by looking at the difference between the basis of the nodes you are switching from and to. One can do some tricks there, you can also see from :

    Reinitializing dual norms . . .
    Computed 1 new norms.

    That it's not recomputed, which would be very time consuming. Switching nodes might need a refactorization, it depends on how you search the tree.

    Again I stress, I do not know the inside of cplex, so this is just guesses from my side.

    ReplyDelete
  5. Bo could be correct, but it would imply that CPLEX was computing LP bounds for different nodes during the node selection process. I think (and I stress "think" here) it switches to a node before solving the LP, in which case if it gets an LP value it doesn't like (or if the node is infeasible) it will prune the node and generate a line in the log.

    Another curiosity: This appears to be a maximization problem, but both problem node 488 and the subsequent (better behaved?) node 489 are listed with objective values higher than the "Best Node" value. Is a branch incumbent being used? The makeBranch command requires an estimate of the objective value for the new node; I've never looked into what happens if you underestimate the value in a max problem. (The lazy approach, which I always use, is to take the objective value of the parent node as the estimate, which if anything will overestimate in a max problem.) Other than that, my only guess would be that what's in the log is the objective value of the original (unpresolved) problem, whereas what CPLEX uses internally is the objective value of the presolved problem, and we're seeing the effects of massive rounding error or numerical stability problems.

    ReplyDelete
  6. Would be a good question to cplex support forum, but most likely some cplex person will answer here soon, I am sure some of them follow your blog too :-)

    ReplyDelete