Timing results of CPLEX Python API adding linear constraints by name, by index, or by creating an LP file

testcase.log.txt

2017-06-21 09:20:44,754 INFO:__main__ Using 100 constraints
2017-06-21 09:20:44,755 INFO:__main__ Average constraint size: 602.970000
2017-06-21 09:20:44,759 INFO:__main__ Using Python API starting now
2017-06-21 09:20:44,764 INFO:__main__ Sending variables to CPLEX
2017-06-21 09:20:44,790 INFO:__main__ Sending objective function to CPLEX
2017-06-21 09:20:44,792 INFO:__main__ Sending constraints to CPLEX
2017-06-21 09:20:50,662 INFO:__main__ Solving model
2017-06-21 09:20:50,728 INFO:__main__ Solution status: MIP_optimal
2017-06-21 09:20:50,729 INFO:__main__ Objective value: 100.0
2017-06-21 09:20:50,729 INFO:__main__ Using Python API starting now
2017-06-21 09:20:50,734 INFO:__main__ Sending variables to CPLEX
2017-06-21 09:20:50,756 INFO:__main__ Sending objective function to CPLEX
2017-06-21 09:20:50,758 INFO:__main__ Sending constraints to CPLEX
2017-06-21 09:20:56,871 INFO:__main__ Solving model
2017-06-21 09:20:56,950 INFO:__main__ Solution status: MIP_optimal
2017-06-21 09:20:56,950 INFO:__main__ Objective value: 100.0
2017-06-21 09:20:56,951 INFO:__main__ Using Python API starting now
2017-06-21 09:20:56,957 INFO:__main__ Sending variables to CPLEX
2017-06-21 09:20:56,983 INFO:__main__ Sending objective function to CPLEX
2017-06-21 09:20:56,986 INFO:__main__ Sending constraints to CPLEX
2017-06-21 09:21:02,897 INFO:__main__ Solving model
2017-06-21 09:21:02,965 INFO:__main__ Solution status: MIP_optimal
2017-06-21 09:21:02,965 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:02,966 INFO:__main__ Using Python API starting now
2017-06-21 09:21:02,971 INFO:__main__ Sending variables to CPLEX
2017-06-21 09:21:02,992 INFO:__main__ Sending objective function to CPLEX
2017-06-21 09:21:02,995 INFO:__main__ Sending constraints to CPLEX
2017-06-21 09:21:08,748 INFO:__main__ Solving model
2017-06-21 09:21:08,816 INFO:__main__ Solution status: MIP_optimal
2017-06-21 09:21:08,816 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:08,817 INFO:__main__ Using Python API starting now
2017-06-21 09:21:08,822 INFO:__main__ Sending variables to CPLEX
2017-06-21 09:21:08,843 INFO:__main__ Sending objective function to CPLEX
2017-06-21 09:21:08,846 INFO:__main__ Sending constraints to CPLEX
2017-06-21 09:21:14,861 INFO:__main__ Solving model
2017-06-21 09:21:14,934 INFO:__main__ Solution status: MIP_optimal
2017-06-21 09:21:14,934 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:14,936 INFO:__main__ Python starting to write file
2017-06-21 09:21:14,937 INFO:__main__ Objective written
2017-06-21 09:21:14,991 INFO:__main__ Constraints written
2017-06-21 09:21:15,005 INFO:__main__ Bounds written
2017-06-21 09:21:15,027 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,099 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,100 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,100 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,101 INFO:__main__ Objective written
2017-06-21 09:21:15,155 INFO:__main__ Constraints written
2017-06-21 09:21:15,167 INFO:__main__ Bounds written
2017-06-21 09:21:15,186 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,256 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,258 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,258 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,259 INFO:__main__ Objective written
2017-06-21 09:21:15,315 INFO:__main__ Constraints written
2017-06-21 09:21:15,327 INFO:__main__ Bounds written
2017-06-21 09:21:15,348 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,418 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,420 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,420 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,421 INFO:__main__ Objective written
2017-06-21 09:21:15,474 INFO:__main__ Constraints written
2017-06-21 09:21:15,487 INFO:__main__ Bounds written
2017-06-21 09:21:15,507 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,574 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,576 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,576 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,577 INFO:__main__ Objective written
2017-06-21 09:21:15,633 INFO:__main__ Constraints written
2017-06-21 09:21:15,646 INFO:__main__ Bounds written
2017-06-21 09:21:15,666 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,733 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,735 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,736 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,736 INFO:__main__ Objective written
2017-06-21 09:21:15,790 INFO:__main__ Constraints written
2017-06-21 09:21:15,803 INFO:__main__ Bounds written
2017-06-21 09:21:15,822 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:15,891 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:15,894 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:15,894 INFO:__main__ Python starting to write file
2017-06-21 09:21:15,895 INFO:__main__ Objective written
2017-06-21 09:21:15,959 INFO:__main__ Constraints written
2017-06-21 09:21:15,971 INFO:__main__ Bounds written
2017-06-21 09:21:15,991 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:16,065 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:16,066 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:16,067 INFO:__main__ Python starting to write file
2017-06-21 09:21:16,067 INFO:__main__ Objective written
2017-06-21 09:21:16,124 INFO:__main__ Constraints written
2017-06-21 09:21:16,136 INFO:__main__ Bounds written
2017-06-21 09:21:16,157 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:16,226 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:16,228 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:16,228 INFO:__main__ Python starting to write file
2017-06-21 09:21:16,229 INFO:__main__ Objective written
2017-06-21 09:21:16,286 INFO:__main__ Constraints written
2017-06-21 09:21:16,299 INFO:__main__ Bounds written
2017-06-21 09:21:16,318 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:16,393 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:16,395 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:16,395 INFO:__main__ Python starting to write file
2017-06-21 09:21:16,396 INFO:__main__ Objective written
2017-06-21 09:21:16,448 INFO:__main__ Constraints written
2017-06-21 09:21:16,461 INFO:__main__ Bounds written
2017-06-21 09:21:16,481 INFO:__main__ File written, calling CPLEX in subprocess
2017-06-21 09:21:16,551 INFO:__main__ CPLEX subprocess finished, parsing output
2017-06-21 09:21:16,553 INFO:__main__ Objective value: 100.0
2017-06-21 09:21:16,553 INFO:__main__ CPLEX took 6.035164 seconds on average
2017-06-21 09:21:16,553 INFO:__main__ Writing file/subprocess took 0.159848 seconds on average
2017-06-21 09:21:16,553 INFO:__main__ Manual worst-case caching took 0.163523 seconds on average

testcase.py

#!/usr/bin/env python3
"""Testing the speed of adding linear constraints via CPLEX Python API"""
import random
import logging
import subprocess
import timeit
import cplex


CPLEX_PATH = ("/home/enigma/opt/ibm/"
              "ILOG/CPLEX_Studio127/cplex/bin/x86-64_linux/cplex")

# pylint: disable=C0103,R0914,R0912,W0621

logging.basicConfig(level=logging.INFO,
                    format='%(asctime)s %(levelname)s:%(name)s %(message)s')
logger = logging.getLogger(__name__)


def do_cplex(both_vars, objective, con_indices, con_values, rhss, self_cache=False):
    """Use Python API to CPLEX to solve problem"""
    logger.info("Using Python API starting now")
    _cplex = cplex.Cplex()

    # Create specific debugging objects for CPLEX to use
    class CplexLogInfo(object):
        """A logging object for CPLEX that will use the logging module."""
        def __init__(self, _logger):
            self._logger = _logger

        def write(self, msg):
            """Write an INFO level message"""
            for line in msg.split("\n"):
                if line.rstrip():
                    self._logger.debug("CPLEX: %s", line.rstrip())

        def flush(self):
            """Fake flush() function."""
            pass

    class CplexLogWarn(object):
        """A logging object for CPLEX that will use the logging module."""
        def __init__(self, _logger):
            self._logger = _logger

        def write(self, msg):
            """Write an WARN level message"""
            for line in msg.split("\n"):
                if line.rstrip():
                    self._logger.warn("CPLEX: %s", line.rstrip())

        def flush(self):
            """Fake flush() function."""
            pass

    warning_logger = CplexLogWarn(logger)
    _cplex.set_warning_stream(warning_logger)
    if logger.getEffectiveLevel() != logging.DEBUG:
        _cplex.set_results_stream(None)
        _cplex.set_log_stream(None)
    else:
        info_logger = CplexLogInfo(logger)
        _cplex.set_results_stream(info_logger)
        _cplex.set_log_stream(info_logger)

    types = [_cplex.variables.type.binary] * len(both_vars)
    logger.info("Sending variables to CPLEX")
    added = _cplex.variables.add(names=both_vars, types=types)
    if self_cache:
        lookup = {}
        for index in added:
            lookup[var_names[index]] = index

    logger.info("Sending objective function to CPLEX")
    _cplex.objective.set_linear(objective)
    _cplex.objective.set_sense(_cplex.objective.sense.maximize)
    expressions = []
    senses = []
    names = []
    number = 1
    for indices, values in zip(con_indices, con_values):
        if self_cache:
            index = []
            for var_name in indices:
                index.append(lookup[var_name])
            lin_expr = cplex.SparsePair(ind=index, val=values)
        else:
            lin_expr = cplex.SparsePair(ind=indices, val=values)
        names.append("c%d" % number)
        number += 1
        sense = 'L'
        expressions.append(lin_expr)
        senses.append(sense)
    logger.info("Sending constraints to CPLEX")
    _cplex.linear_constraints.add(lin_expr=expressions,
                                  senses=senses,
                                  rhs=rhss,
                                  names=names)
    logger.info("Solving model")
    _cplex.write("cplex-saved-file.lp")
    _cplex.solve()
    status = _cplex.solution.get_status()
    status_string = _cplex.solution.status[status]
    logger.info("Solution status: %s", status_string)
    if status != _cplex.solution.status.MIP_optimal:
        logger.warning("No optimal solution found")
        return
    objective_value = _cplex.solution.get_objective_value()
    logger.info("Objective value: %s", objective_value)


def do_filewriting(both_vars, objective, con_indices, con_values, rhss):
    """Write an LP file, then load the LP file into a cplex subprocess"""
    logger.info("Python starting to write file")
    with open("python-writing-file.lp", "w") as outfile:
        outfile.write("Maximize")
        (first_name, first_value) = objective[0]
        outfile.write(" obj: %f %s" % (first_value, first_name))
        for name, value in objective[1:]:
            outfile.write(" + %f %s" % (value, name))
        logger.info("Objective written")
        outfile.write("\nSubject To\n")
        number = 1
        for indices, values, rhs in zip(con_indices, con_values, rhss):
            outfile.write(" c%d: " % (number))
            first = True
            for index, value in zip(indices, values):
                if value > 0:
                    if not first:
                        outfile.write(" + ")
                    outfile.write("%f %s" % (value, index))
                    first = False
                elif value < 0:
                    outfile.write(" - %f %s" % (-value, index))
                    first = False
            outfile.write(" <= %f\n" % (rhs))
            number += 1
        logger.info("Constraints written")
        outfile.write("Bounds\n")
        for name in both_vars:
            outfile.write("0 <= %s <= 1\n" % name)
        logger.info("Bounds written")
        outfile.write("Binaries\n")
        line_length = 0
        for name in both_vars:
            if line_length + len(name) + 2 >= 80:
                outfile.write("\n")
                line_length = 0
            outfile.write(" %s " % name)
            line_length += len(name) + 2
        outfile.write("\nEnd")

    logger.info("File written, calling CPLEX in subprocess")
    run = subprocess.run([CPLEX_PATH, "-c", "read python-writing-file.lp",
                          "mipopt", "display solution variables *"],
                         stdout=subprocess.PIPE, encoding=u"utf-8")
    output = run.stdout.split("\n")
    logger.info("CPLEX subprocess finished, parsing output")
    feasible = False
    for line in output:
        if line:
            if line[:31] == 'MIP - Integer optimal solution:':
                obj = float(line[46:])
                feasible = True
    if feasible:
        logger.info("Objective value: %s", obj)


# Main
num_obj_vars = 100
num_other_vars = 30000
chance_other_var_in_constraint = 0.02
number_iterations = 5

objs = []
objective = []
others = []
rhss = []
indices = []
values = []
constraint_size = 0
for i in range(num_other_vars):
    others.append("V%s" % i)
for i in range(num_obj_vars):
    objs.append("O%s" % i)
    con_indices = []
    con_values = []
    objective.append(("O%s" % i, 1.0))
    for x in range(num_other_vars):
        if random.random() < chance_other_var_in_constraint:
            con_indices.append("V%s" % x)
            con_values.append((random.random() - 0.5) * 2)
    constraint_size += len(con_indices)
    indices.append(con_indices)
    values.append(con_values)
    rhss.append(random.random() * 50)
both_vars = list(objs)
both_vars.extend(others)
logger.info("Using %d constraints", len(indices))
average_constraint_size = constraint_size / num_obj_vars
logger.info("Average constraint size: %f", (average_constraint_size))
c = timeit.Timer("do_cplex(both_vars, objective, indices, values, rhss)",
                 "from __main__ import do_cplex, both_vars, objective, "
                 "indices, values, rhss")
cplex_time = c.timeit(number_iterations) / number_iterations
p = timeit.Timer("do_filewriting(both_vars, objective, indices, values, rhss)",
                 "from __main__ import do_filewriting, both_vars, objective, "
                 "indices, values, rhss")
python_time = p.timeit(number_iterations) / number_iterations
s = timeit.Timer("do_filewriting(both_vars, objective, indices, values, rhss, "
                 "True)",
                 "from __main__ import do_filewriting, both_vars, objective, "
                 "indices, values, rhss")
smart_time = p.timeit(number_iterations) / number_iterations

logger.info("CPLEX took %f seconds on average", cplex_time)
logger.info("Writing file/subprocess took %f seconds on average", python_time)
logger.info("Manual worst-case caching took %f seconds on average", smart_time)

If I'm reading the code correctly, it looks like there are some issues with smart_time. It is actually calculated using the p Timer. Also, the s Timer uses do_filewriting with an extra True argument that doesn't exist. I'm guessing you meant to use do_cplex in the s Timer, but if I try that, I get a: "NameError: name 'var_names' is not defined". At any rate, I understand the gist of your test, and I'm only mentioning this in case you want to update it.