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%