With cplex, solver_io='python' is much slower than solver_io='nl' or default

[mfripp]

A comment on stackoverflow mentioned that CPLEX's python bindings should be faster than the 'nl' (AMPL-style) interface or the default (which I think interacts with the cplex executable directly), especially with Pyomo versions >= 4.3.11323. However, on my system I have not found this to be the case. In the example below, the solver takes about 8x longer when using the solver_io='python' option than it does with the other options. This is on Mac OS X 10.11.6, with Python 2.7, CPLEX 12.6.0.0 and Pyomo 4.4.1.

import time
from pyomo.environ import *
from pyomo.opt import SolverFactory

def solve(*args, **kwargs):
    # define the model
    n_steps = 100000
    m = ConcreteModel()
    m.STEPS = Set(initialize=range(n_steps))
    m.target = Param(m.STEPS, initialize=lambda m, s: 1.0)
    m.Build = Var()
    m.Operate = Var(m.STEPS)
    m.Meet_Target = Constraint(m.STEPS, rule=lambda m, s: m.Operate[s] >= m.target[s])
    m.Operate_Limit = Constraint(m.STEPS, rule=lambda m, s: m.Operate[s] <= m.Build)
    m.MinCost = Objective(
        rule=lambda m: n_steps * m.Build + sum(1.0 * m.Operate[s] for s in m.STEPS), 
        sense=minimize
    )

    # solve the model
    opt = SolverFactory(*args, **kwargs)
    start_time = time.time()
    results = opt.solve(m)
    m.solutions.load_from(results)

    print "solve({}): MinCost={}, time={}".format(
        ", ".join([repr(a) for a in args] + [str(k)+"="+repr(a) for k, a in kwargs.items()]),
        value(m.MinCost), time.time() - start_time)

solve("cplex")                      # 9.2s
solve("cplex", solver_io="nl")      # 9.2s
solve("cplex", solver_io="python")  # 73.3s
solve("cplexamp")                   # 9.2s

I am pleased to note that these times are all 20-35% faster in Pyomo 4.4.1 than they were in 4.3.11377. But the "python" bindings are clearly lagging.

[ghackebeil]

Wow! Thanks for the example! We shall have a look.

[ghackebeil]

Here is some relevant profiling:

   Ordered by: internal time, cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
1       47.189   47.189   48.069   48.069  {cplex._internal.py1013_cplex1260.Pylolmat_to_CHBmat}
100001  23.235   0.000    23.235   0.000   {cplex._internal.py1013_cplex1260.CPXXgetcolindex}
1       1.674    1.674    83.555   83.555  CPLEXDirect.py:341(_populate_cplex_instance)
200001  1.583    0.000    3.361    0.000   canonical_repn.py:821(coopr3_generate_canonical_repn)

Looks like it's all in an internal Cplex method. Might be something we should contact them about.

[mfripp]

Thanks for looking into this. It looks like the cplex module is doing something pretty inefficient with the model data. Not sure how to persuade IBM to fix it though. They'd probably want to see a version of this model written to run directly with their python api, and another version written to run with the cplex binary. That's a little beyond what I can do right now.