UPDATE 1: I just found another instance of the same problem where the Python API actually beats the command line (18 288.19 ticks vs. 76 710.09). I naively assumed that both environments share the same default settings, but perhaps it's not the case. Obviously, I should have made more tests and research before jumping the gun!

UPDATE 2: At the request of @BjarniMax, I have launched the CPLEX interpreter on my original instance in single-thread mode. Result: 87 241.71 ticks (vs. 46 513.04 with the Python API in single-thread mode). So, the discrepancy is not (entirely) due to the threads.

UPDATE 3: At the request of @Tobias Achterberg and @jfpuget, I provide my "LP" file, which actually seems to be a command file.

UPDATE 4: Following the mention by @Tobias Achterberg of a "bug" in the Python API parameters' management, I've carried out some more experiments on various instances. Here is how I "reproduce" the CPLEX command line environment in Python:

problem = cplex.Cplex()
problem.parameters.read.datacheck.set(0)
problem.set_results_stream("cplex_python.log")
problem.read("my_instance.lp")
problem.solve()

This indeed changes something for the Python solver, which then behaves exactly as if I would read the data from an SAV file (as first suggested by @Paul Rubin):

problem = cplex.Cplex()
problem.read("my_instance.sav")
problem.solve()

Unfortunately, the discrepancy still exists, like in this instance, where, on the contrary, the command line solver needs at least 20 more times than the Python one. May be there's still some differences between the two environments? Since I was not able to find the equivalent of "display settings all" in the Python API, I came up with the following equivalent script:

#!arch -i386 python2.7

import cplex

def dumpParameters(prefix,obj):
  if hasattr(obj,"get"):
    result.append(prefix + "\t" + repr(obj.get()))
  else:
    for (name,method) in obj.__dict__.iteritems():
      if not name.startswith("_"):
        dumpParameters(prefix + " " + name,method)

result = []
problem = cplex.Cplex()
dumpParameters("",problem.parameters)
print "\n".join(sorted(result))

The other differences are:

  1. simplex perturbation indicator = 0 (exists in Python only)
  2. read API encoding = UTF8 (exists in Python only)
  3. network display, network iterations, network netfind, network pricing, network tolerances feasibility, network tolerances optimality (exist in CPLEX command line only)

I don't know if the remaining culprits are there. In any case, it's now perfectly clear that using the Python API has no significative intrinsic cost. So, in this sense, my original question is answered. However, it's a little disturbing that I cannot make my results reproducible by the other members of my team (who don't use Python).

Thanks for all your help, and sorry for this long thread!

Original question

When I run CPLEX 12.5.0.0 from the command line:

cplex -f my_instance.lp

an optimal integer solution is found in 19056.99 ticks.

But through the Python API, on the very same instance:

import cplex
problem = cplex.Cplex("my_instance.lp")
problem.solve()

the required time now amounts to 97407.10 ticks (more than 5 times slower).

In both cases, the mode is parallel, deterministic, up to 2 threads. Wondering if this poor performance was due to some Python thread overhead, I tried:

problem = cplex.Cplex("my_instance.lp")
problem.parameters.threads.set(1)
problem.solve()

Required 46513.04 ticks (i.e., using one core was two times faster than using two!).

Being new to CPLEX and LP in general, I find these results quite confusing. Is there a way to improve the Python API performance, or should I switch to some more mature API (i.e., Java or C++)?

Complete log for the 2-threads' resolutions from the command line

Tried aggregator 3 times.
MIP Presolve eliminated 2648 rows and 612 columns.
MIP Presolve modified 62 coefficients.
Aggregator did 13 substitutions.
Reduced MIP has 4229 rows, 1078 columns, and 13150 nonzeros.
Reduced MIP has 1071 binaries, 0 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.05 sec. (18.80 ticks)
Probing fixed 24 vars, tightened 0 bounds.
Probing time = 0.05 sec. (18.12 ticks)
Tried aggregator 1 time.
MIP Presolve eliminated 87 rows and 26 columns.
MIP Presolve modified 153 coefficients.
Reduced MIP has 4142 rows, 1052 columns, and 12916 nonzeros.
Reduced MIP has 1045 binaries, 7 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.03 sec. (11.67 ticks)
Probing time = 0.00 sec. (1.06 ticks)
Clique table members: 4199.
MIP emphasis: balance optimality and feasibility.
MIP search method: dynamic search.
Parallel mode: deterministic, using up to 2 threads.
Root relaxation solution time = 0.19 sec. (91.47 ticks)

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

      0     0        2.0649   248                      2.0649      915         
      0     0        2.1300   292                    Cuts: 11     1117         
      0     0        3.0000   287                    Cuts: 58     1520         
      0     0        3.0000   268                    Cuts: 55     1669         
      0     0        3.0000   272                    Cuts: 53     1849         
      0     0        3.0000   280                    Cuts: 27     2093         
      0     2        3.0000   279                      3.0000     2155         
Elapsed time = 5.54 sec. (2445.18 ticks, tree = 0.01 MB, solutions = 0)
     16    16        4.0000   220                      3.0000     5332         
     25    21        3.0000   421                      3.0000     8584         
     50    40        4.0000   241                      3.0000    11678         
     63    49        3.0000   238                      3.0000    13458         
     78    62        3.0000   239                      3.0000    16544         
     88    68        3.0000   185                      3.0000    19482         
    105    83        3.0000   240                      3.0000    22900         
    113    91        3.1605   358                      3.0000    25822         
    119    97        3.1906   473                      3.0000    29995         
    210   188        5.0000   162                      3.0000    46344         
Elapsed time = 14.65 sec. (6056.73 ticks, tree = 1.67 MB, solutions = 0)
*   232   196      integral     0        6.0000        3.0000    49431   50.00%
    283   233        4.0000   208        6.0000        3.0000    59799   50.00%
    421   357        5.0000   173        6.0000        3.0000    72690   50.00%
*   451+  357                            5.0000        3.0000    74233   40.00%
    546   279        3.0488   324        5.0000        3.0000    84557   40.00%
*   593+  298                            4.0000        3.0000    91681   25.00%
    622    38        3.0000   225        4.0000        3.0000    96092   25.00%
    723    31        cutoff              4.0000        3.0000   109728   25.00%
    827    27        cutoff              4.0000        3.0000   121652   25.00%
    941    17        3.0000   217        4.0000        3.0000   133992   25.00%
   1076    24        cutoff              4.0000        3.0000   148970   25.00%
   1189    15        3.0000   225        4.0000        3.0000   162854   25.00%
Elapsed time = 32.43 sec. (14836.30 ticks, tree = 0.16 MB, solutions = 3)
   1269    13        3.0000   229        4.0000        3.0000   172439   25.00%
   1369    15        cutoff              4.0000        3.0000   186650   25.00%
   1482    19        3.0000   227        4.0000        3.0000   200118   25.00%
   1587     8        3.0000   222        4.0000        3.0000   211275   25.00%

GUB cover cuts applied:  1
Clique cuts applied:  3
Cover cuts applied:  2
Implied bound cuts applied:  38
Zero-half cuts applied:  7
Gomory fractional cuts applied:  2

Root node processing (before b&c):
  Real time             =    5.27 sec. (2345.14 ticks)
Parallel b&c, 2 threads:
  Real time             =   35.15 sec. (16626.69 ticks)
  Sync time (average)   =    0.00 sec.
  Wait time (average)   =    0.00 sec.
                          ------------
Total (root+branch&cut) =   40.41 sec. (18971.82 ticks)

Solution pool: 3 solutions saved.

MIP - Integer optimal solution:  Objective =  4.0000000000e+00
Solution time =   40.65 sec.  Iterations = 214773  Nodes = 1652
Deterministic time = 19056.99 ticks  (468.84 ticks/sec)

Partial log for the 2-threads' resolutions from the Python API

... The beginning is 100% identical up to the node 50, then:

     65    51        4.0000   208                      3.0000    14169         
     79    63        3.0000   219                      3.0000    17500         
    100    78        3.0000   202                      3.0000    21773         
    106    84        3.0000   232                      3.0000    24866         
    123    99        4.0000   225                      3.0000    32635         
    136   106        3.1358   348                      3.0000    36276         
*   173+  141                            6.0000        3.0000    42524   50.00%
    201   166        4.0000   207        6.0000        3.0000    46618   50.00%
Elapsed time = 15.90 sec. (6469.36 ticks, tree = 3.21 MB, solutions = 0)
    308   249        5.0000   253        6.0000        3.0000    59008   50.00%

... 100 lines left. Please tell me if you need them too.

Elapsed time = 228.81 sec. (97141.89 ticks, tree = 160.66 MB, solutions = 4)
Nodefile size = 30.63 MB (28.33 MB after compression)

Clique cuts applied:  33
Cover cuts applied:  1
Implied bound cuts applied:  4
Zero-half cuts applied:  10
Gomory fractional cuts applied:  4

Root node processing (before b&c):
  Real time             =    6.42 sec. (2345.36 ticks)
Parallel b&c, 2 threads:
  Real time             =  222.28 sec. (95061.73 ticks)
  Sync time (average)   =    0.01 sec.
  Wait time (average)   =    0.00 sec.
                          ------------
Total (root+branch&cut) =  228.70 sec. (97407.10 ticks)

The log ends here, and I haven't found yet how to display the number of branch & bound nodes.

asked 09 Mar '13, 03:52

aristide's gravatar image

aristide
6125
accept rate: 0%

edited 23 Mar '13, 14:06

2

Since the number of cuts is so different between the two runs, maybe the whole behavior (e.g. tree search) was changed. I could imagine this being the result of different random seeds. Could you also show the number of branch & bound nodes?

(09 Mar '13, 04:04) rschwarz

@aristide: After your updated runs, with the Threads parameter set to 1, was the solution path, between CPLEX standalone and CPLEX Python API, still the same during Presolve, Probing, and the root node (applying cuts)?

(09 Mar '13, 11:42) BjarniMax

@BjarniMax Yes. The first difference occurs 4 "lines" after a first "Best Integer" has been found (node 339).

(09 Mar '13, 11:51) aristide

I am very certain the overhead in the Python API is relative small. Normally these optimizer API's is a thin wrapper eventually calling the C API. In the case of Python I assume they use C types extensions to call the C API. In any case the overhead is only present in the model building phase and not the model solving phase. In your case you just call a LP file hence there should be no overhead.

If you look at the two log output's you will see they generate different cuts, in articular the fast run generate more implied bound cuts and the slow run generate more clique cuts. I bet that's what makes the difference.

So why the difference ?

It turns out MIP's solvers are highly dependent on different things happening in different orders, so the algorithm might take a different path if the random seed is changed, column/row/nz order of the matrix is changed etc.

Try to experiment with the random seed settings in CPLEX and see if you can make it variate in performance, then you know it's the root cause.

link

answered 09 Mar '13, 04:11

Bo%20Jensen's gravatar image

Bo Jensen ♦
5.0k2919
accept rate: 14%

I see @rschwarz beat me to it, sorry for the echo, didn't see his comment.

(09 Mar '13, 04:13) Bo Jensen ♦

@Bo Jensen and @rschwarz, thanks for your suggestions. Turns out that both command-line Cplex and its Python API have the same random seed value of 201207272. I should be able to try other instances of my problem a bit later today.

(09 Mar '13, 05:08) aristide
1

@aristide OK, then try to exclude the different cut generators one by one i.e switch of Clique cuts,Implied cuts etc. You need to find the setting which can explain the difference, when that is found, confirm it works on similar models you have. If you end up using special settings for a class of models, be really sure to remember to switch it off for other models, since default setting is generally what you want.

(09 Mar '13, 05:20) Bo Jensen ♦
1

@aristide Even it has the same random seed, try different settings for it, since you can gain more information on the variability issue causing it.

(09 Mar '13, 05:23) Bo Jensen ♦
1

@aristide Also contacting CPLEX support to get an explanation to the recommended settings in your case, would not be a bad idea.

(09 Mar '13, 05:25) Bo Jensen ♦
2

Bo's point about the order of rows and columns is important. Does the same discrepancy occur using a SAV file rather than an LP file? I would think that the interactive optimizer and the Python API would use the same core library function(s) to parse an LP file, but I suppose it's possible that some discrepancy in ordering between the two arises.

(11 Mar '13, 17:38) Paul Rubin ♦♦
1

@Paul Rubin OK, I wrote my favourite instance into the SAV format, and re-read it from the command line CPLEX or from its Python API: both need roughly the same number of ticks (the logs, however, are still not exactly the same, but the difference occurs farther). Interestingly, the command line CPLEX gives exactly the same number of ticks on either the LP or SAV file. But to make Python behave as expected, it must read the SAV file. Alas! this may not be the sole reason for this discrepancy: on another instance, the command line needs 315 Kticks, and Python just 37 Kticks!

(12 Mar '13, 11:52) aristide
1
(12 Mar '13, 12:30) aristide
1

@aristide: As @Bo suggested, "cross-posting" your question to IBM's Optimization Forum might be a good idea.

(12 Mar '13, 13:26) fbahr ♦

@aristide: Both the interactive solver and the Python API end up calling the same core library for solving the model. Assuming both run on exactly the same platform, one would expect identical results given identical inputs (at least if a single thread is used). I include parameters among the inputs. Using a SAV file minimizes differences in the input data, but there is no guarantee that the CLI and Python API parse things in identical order.

(12 Mar '13, 13:44) Paul Rubin ♦♦

I think this thread is running in circles, several plausible reasons have been given, but from here on it's shooting in the dark if you're not into the source details of the optimizer, hence I believe it's better answered in CPLEX support forum.

(12 Mar '13, 13:49) Bo Jensen ♦
2

Thank you all for your suggestions, which surely made me discover a great deal of new and interesting things since last saturday! I'll soon clean up my question and post it at the address given by @fbahr. In the case I come up with a definitive answer, I'll add it to this thread. Thank you again for your help, guys!

(12 Mar '13, 14:05) aristide
showing 5 of 12 show 7 more comments

I agree with the previous answers, that the differences in the cuts applied is likely to have a role here. But I would also search through the two logs in more detail.

First make sure the 'preample' you listed is 100% the same for both runs (except for minor differences in the ticks). Even a single number difference during the preample, can have major consequences later on during the optimization.

Secondly, find the first location during the actual iteration log that is different between the two runs. What it says there, might give you an indication of 'why' there is so much difference.

Thirdly, I would try running with Dynamic Search turned Off, and see if that makes any difference.

link

answered 09 Mar '13, 07:46

BjarniMax's gravatar image

BjarniMax
8641312
accept rate: 13%

  1. Yes, I've reverified that the preambles are 100% identical, apart from negligible ticks differences.

  2. I'm going to edit my post to add the logs where they diverge.

  3. Sorry, as a complete newbie in LP, I first need to read the doc to understand what "dynamic search" is, and how to turn it off in both Python API and CPLEX interactive interpreter. The same applies to the suggestions of @Bo Jensen. Sorry about that!

(09 Mar '13, 08:06) aristide

Dynamic search in CPLEX is typically turned off by setting the CPX_PARAM_MIPSEARCH parameter to 1. For Python CPLEX the corresponding command would be: cpx.parameters.mip.strategy.search.set(1)

(09 Mar '13, 09:33) BjarniMax

Thank you @BjarniMax, in the meantime I've found it in the doc (I was serious when I said I should read it :-) So, almost 2 hours ago, I launched a test in Python with the dynamic search off, but it has not terminated yet (1 280 416.03 ticks so far!).

(09 Mar '13, 09:45) aristide

I am finding several things interesting and even strange regarding CPLEX behaviour you are describing. Even though the cuts applied are very different, which we yet do not know the reason for, the logs at the root node are still according you exactly the same. It might be possible that CPLEX has different default settings for its parameters in Python, but I would not have guessed such big difference. Maybe there is something specific in your model, that some changes in the running environment triggers massive changes how CPLEX is operating. With MIP's certainly that is a always a possibility.

(09 Mar '13, 10:27) BjarniMax

The suggestion regading the Dynamic Search was just to see if it affected the "difference" in performance, not necessarily that it would perform any better. If you are already at over million ticks, you can probably safely stop that run. :-)

(09 Mar '13, 10:27) BjarniMax

You can not judge anything from the size of the difference in solution times, it's just the MIP complexity kicking in and the fact that a MIP solver relies on many heuristic choices, just one different order of branching can take a completely different path. I see no reason to suspect any thing unusual here. Depending on how cliques and implications are gathered, in some cases you might add a clique and in other a implied bound cut, since a clique(1) is just a compressed collection of implications.

(09 Mar '13, 10:36) Bo Jensen ♦

Yes, I agree, but we still have the strange mystery why CPLEX is showing completely the same logs all the way through the presolve, probing, and the root node (including adding the cuts), and then decides to go through a completely different solution path shortly after it enters the B&C, as it seems, just because its running under Python.

(09 Mar '13, 10:55) BjarniMax

You're 100% right, but don't tell my computer :-)

Anyway, the Python CPLEX has now terminated with 1 684 934.42 ticks. I have just launched the CPLEX interpreter on the same instance. Again, the logs at the root node are the same, and the first divergence occurs after some ticks. However, the Python log has some more columns (Variable B, NodeID, Parent, Depth) which lack in the CPLEX interpreter log, so I wonder if I correctly set the right parameter (but it does display: "MIP search method: traditional branch-and-cut").

(09 Mar '13, 10:56) aristide

I don't think a dll loaded under two different environments is guaranteed taking the exact same paths, especially not when running multiple threads

(09 Mar '13, 10:58) Bo Jensen ♦

@aristide When you turn off Dynamic Search, CPLEX can use more elaborate callbacks internally, so that could easily explain why you are now getting more information in your logs.

(09 Mar '13, 11:02) BjarniMax

@BjarniMax Certainly, but my doubt was rather about the lack of these new columns in the CPLEX interpreter output.

(09 Mar '13, 11:06) aristide
1

The last comment from @Bo Jensen regarding multiple threads is definitely valid. I would suggest running CPLEX in both environments, with the CPLEX threads parameter (CPLEX_PARAM_THREADS) set to 1 in both cases, and see if they are still running so differently.

(09 Mar '13, 11:07) BjarniMax

@BjarniMax In that case, the Python API wins! I've updated my question accordingly. Thanks!

(09 Mar '13, 11:27) aristide
showing 5 of 13 show 8 more comments

First of all note that

cplex -f my_instance.lp

is not correct syntax, and you should have obtained lots of error messages. I guess what you did was more like

cplex -c "read my_instance.lp" "opt"

What you observe is strange. Using the interactive should indeed yield identical behavior as with using Python. Could you please send me your "my_instance.lp" file by email (achterberg (at) de (dot) ibm (dot) com) so that I can investigate?

Thanks!

Tobias Achterberg

link

answered 15 Mar '13, 10:18

Tobias%20Achterberg's gravatar image

Tobias Achte...
811
accept rate: 0%

@achterberg Thank you for your interest. You may download the LP file at dl.dropbox.com/u/3108405/my_instance.lp

PS: I don't know for previous versions, but CPLEX 12.5.0.0 does accept the -f syntax.

(15 Mar '13, 11:21) aristide

We have found the issue. It is related to the deterministic clock that we are using internally for load balancing of the various methods. We consider this to be a bug, which will (hopefully) be fixed in the next release (not the 12.5.0.1 fix pack but the next release).

There are two main differences in the Python and interactive version. 1. The interactive is creating a "cplex.log" file by default. 2. The Python API enables the "datacheck" parameter by default (because in Python it is very easy to accidentally produce rows with duplicate column entries). Both currently have an impact on the deterministic clock (which they should not have), and this causes very subtle differences in the solver behavior that can, for MIP, lead to significant changes in the evolution of the search tree.

link

answered 21 Mar '13, 06:38

Tobias%20Achterberg's gravatar image

Tobias Achte...
811
accept rate: 0%

@Tobias Achterberg: Sorry, could you please tell me where are these two parameters in the Python API class hierarchy? It surely sounds like a stupid question, but I've just spent half an hour in the online documentation without finding the information. BTW, do you know a flatter and more searchable version of this documentation?

(21 Mar '13, 15:38) aristide
1

To disable the log file in the interactive, use "set log *". To enable the log file in Python, use cplex.set_log_stream().

To disable datacheck in Python, set the "read.datacheck" parameter to 0. How to set parameters in Python is explined in the user's manual at "CPLEX > Getting Started with CPLEX > Tutorials > Python tutorial > Using CPLEX parameters in the CPLEX Python API".

(21 Mar '13, 15:46) Tobias Achte...

@Tobias Achterberg: Thanks for your quick answer. As for "use cplex.set_log_stream()", I actually already use it in my Python application to duplicate the output on stdout and a log file (but didn't realize it was the same log parameter you mentioned in your answer). As for "datacheck", I had of course read this section (among a lot of other parts of the documentation), and did know how to set parameters in Python. What I still can't figure out is where this method lies in the class hierarchy: advance, barrier, clocktype, conflict, etc.? I cannot find the path in the documentation. :-(

(21 Mar '13, 16:06) aristide

@Tobias Achterberg: OK, I've found it at last in "problem.parameters.read.datacheck"... Thanks! I'll now make some testing.

(21 Mar '13, 16:09) aristide

I'm wondering if the floating-point control word is the same in the two cases. Python uses the default floating-point environment. The command line version of cplex could change the floating point environment to e.g control if denormals are flushed to zero.

Even tiny numerical differences can lead to widely different running times for MIP.

link

answered 13 Mar '13, 07:38

Rune%20Sandvik's gravatar image

Rune Sandvik
1012
accept rate: 0%

Thanks to all who responded, good anwers!

We, at IBM CPLEX team, do have a question to ask in return. What is the content of the myinstance.lp ?

We'd be surprised it it was a plain lp file because "cplex -f " expects a command file, not a problem file. Providing a plain lp file as input should trigger many errors.

Can we get the content of the myinstance.lp file?

link

answered 15 Mar '13, 11:59

jfpuget's gravatar image

jfpuget
2.5k310
accept rate: 8%

@jfpuget Ah! I now understand why @Tobias Achterberg was surprised by my command line. My file is certainly a command file instead of a plain LP file. What should be the correct extension? I've posted a link to my file in my answer to Tobias, but strangely this answer is not shown :-(

I update my question with the link.

(15 Mar '13, 12:53) aristide
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "Title")
  • image?![alt text](/path/img.jpg "Title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Tags:

×191
×16
×4

Asked: 09 Mar '13, 03:52

Seen: 5,661 times

Last updated: 23 Mar '13, 14:06

OR-Exchange! Your site for questions, answers, and announcements about operations research.