coin-or / python-mip

Python-MIP: collection of Python tools for the modeling and solution of Mixed-Integer Linear programs
Eclipse Public License 2.0
525 stars 92 forks source link

model initialisation time #135

Closed nick-gorman closed 3 years ago

nick-gorman commented 4 years ago

Hi,

I was wondering why the model take time to initialise and can I speed this up in some way. In the example below the model takes approximately 1.5 s to load and when running as part of a more complicated piece of code takes 2.5 s to load. For my work I need to solve many MIPs so it becomes a bottleneck.

from mip import Model
from time import time

t0 = time()

x = Model("example")

print('load mip model {}'.format(time() - t0))
jurasofish commented 4 years ago

Hey Nick,

I run lots of small models as well, and I find that clearing the model rather than recreating it is much faster. First creation seems to be much slower than subsequent ones too.

BUT, 2.5 seconds is a bit extreme, no idea why it's so high for you. i'm on os/python/mip versions shown below.

from mip import Model, xsum, maximize, BINARY
import time

def knapsack(m):
    p = [10, 13, 18, 31, 7, 15]
    w = [11, 15, 20, 35, 10, 33]
    c, I = 47, range(len(w))
    x = [m.add_var(var_type=BINARY) for i in I]
    m.objective = maximize(xsum(p[i] * x[i] for i in I))
    m += xsum(w[i] * x[i] for i in I) <= c
    m.verbose = False
    m.optimize()

# Create and solve a model a few times.
for i in range(5):
    t1 = time.perf_counter()
    model = Model()
    print(f'run {i}: {(time.perf_counter() - t1)*1000:.3f}ms')
    knapsack(model)  # Make it do something at least.

# Clear model instead of recreating it.
t1 = time.perf_counter()
model.clear()
print(f'cleared {(time.perf_counter() - t1)*1000:.3f}ms')
knapsack(model)
run 0: 84.211ms
run 1: 6.889ms
run 2: 7.165ms
run 3: 6.914ms
run 4: 6.583ms
cleared 0.259ms
>>> import sys; print('Python %s on %s' % (sys.version, sys.platform)); import mip; print('mip', mip.__version__)
Python 3.7.7 (default, Mar 26 2020, 10:32:53) 
[Clang 4.0.1 (tags/RELEASE_401/final)] on darwin
mip 1.8.2
nick-gorman commented 4 years ago

Hi Jurasofish,

Your comment made me think that maybe it was the loading of the solvers by mip that is slowing things down. Anyway I was just testing things out, and found that the below was way faster.

Any ideas why?

from mip import Model, CBC
from time import time

t0 = time()

x = Model("example", solver_name=CBC)

print('load mip model {}'.format(time() - t0))
load mip model 0.04258871078491211
jurasofish commented 4 years ago

Oh damn, way faster if you specify the solver explicitly! I've got some changes to make.

I'd guess it's to do with the code that searches for the solver. I'll profile it and get back https://github.com/coin-or/python-mip/blob/326a88c0b31d1f4956271ffd57ca93452e50d83c/mip/model.py#L74-L105

from mip import Model, xsum, maximize, BINARY, CBC
import time

def knapsack(m):
    p = [10, 13, 18, 31, 7, 15]
    w = [11, 15, 20, 35, 10, 33]
    c, I = 47, range(len(w))
    x = [m.add_var(var_type=BINARY) for i in I]
    m.objective = maximize(xsum(p[i] * x[i] for i in I))
    m += xsum(w[i] * x[i] for i in I) <= c
    m.verbose = False
    m.optimize()

# Create and solve a model a few times.
for i in range(5):
    t1 = time.perf_counter()
    model = Model(solver_name=CBC)
    print(f'run {i}: {(time.perf_counter() - t1)*1000:.3f}ms')
    knapsack(model)  # Make it do something at least.

# Clear model instead of recreating it.
t1 = time.perf_counter()
model.clear()
print(f'cleared {(time.perf_counter() - t1)*1000:.3f}ms')
knapsack(model)
run 0: 93.020ms
run 1: 0.076ms
run 2: 0.074ms
run 3: 0.073ms
run 4: 0.087ms
cleared 0.247ms
jurasofish commented 4 years ago

Okay, I've modified the test script so that it calls from mip.gurobi import SolverGurobi and from mip.cbc import SolverCbc straight away - this brings the time for the first instantiation of a Model object close to the normal time (that is, doesn't take ages the first time). So, profiling the __init__ function of the Model object becomes valid because the first run doesn't take ages.

from mip import Model, xsum, maximize, BINARY, CBC
import time

# These take ages the first time, which is usually when a Model is instantiated
# for the first time.
try:
    from mip.gurobi import SolverGurobi
except ImportError:
    pass
from mip.cbc import SolverCbc

def knapsack(m):
    p = [10, 13, 18, 31, 7, 15]
    w = [11, 15, 20, 35, 10, 33]
    c, I = 47, range(len(w))
    x = [m.add_var(var_type=BINARY) for i in I]
    m.objective = maximize(xsum(p[i] * x[i] for i in I))
    m += xsum(w[i] * x[i] for i in I) <= c
    m.verbose = False
    m.optimize()

# Create and solve a model a few times.
for i in range(5):
    t1 = time.perf_counter()
    model = Model()
    print(f'run {i}: {(time.perf_counter() - t1)*1000:.3f}ms')
    knapsack(model)  # Make it do something at least.

# Clear model instead of recreating it.
t1 = time.perf_counter()
model.clear()
print(f'cleared {(time.perf_counter() - t1)*1000:.3f}ms')
knapsack(model)
run 0: 9.018ms
run 1: 6.288ms
run 2: 6.180ms
run 3: 6.194ms
run 4: 6.145ms
cleared 0.194ms

Profiling instantiation of the Model object hows that trying to import Gurobi takes up ~90% of the time.

(nev) michael-nev:scratches michael$ kernprof -l -v load_time_mip.py 
run 0: 36.893ms
run 1: 15.476ms
run 2: 15.175ms
run 3: 19.644ms
run 4: 18.104ms
cleared 0.234ms
Wrote profile results to load_time_mip.py.lprof
Timer unit: 1e-06 s

Total time: 0.104803 s
File: /opt/miniconda3/envs/nev/lib/python3.7/site-packages/mip/model.py
Function: __init__ at line 62

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    62                                               @profile
    63                                               def __init__(
    64                                                   self: "Model",
    65                                                   name: str = "",
    66                                                   sense: str = MINIMIZE,
    67                                                   solver_name: str = "",
    68                                                   solver: Optional[Solver] = None,
    69                                               ):
    70                                                   """Model constructor
    71                                           
    72                                                   Creates a Mixed-Integer Linear Programming Model. The default model
    73                                                   optimization direction is Minimization. To store and optimize the model
    74                                                   the MIP package automatically searches and connects in runtime to the
    75                                                   dynamic library of some MIP solver installed on your computer, nowadays
    76                                                   gurobi and cbc are supported. This solver is automatically selected,
    77                                                   but you can force the selection of a specific solver with the parameter
    78                                                   solver_name.
    79                                           
    80                                                   Args:
    81                                                       name (str): model name
    82                                                       sense (str): MINIMIZATION ("MIN") or MAXIMIZATION ("MAX")
    83                                                       solver_name(str): gurobi or cbc, searches for which
    84                                                           solver is available if not informed
    85                                                       solver(Solver): a (:class:`~mip.solver.Solver`) object; note that
    86                                                           if this argument is provided, solver_name will be ignored
    87                                                   """
    88         5         28.0      5.6      0.0          self._ownSolver = True
    89                                                   # initializing variables with default values
    90         5          4.0      0.8      0.0          self.solver_name = solver_name
    91         5          3.0      0.6      0.0          self.solver = solver  # type: Optional[Solver]
    92                                           
    93                                                   # reading solver_name from an environment variable (if applicable)
    94         5          4.0      0.8      0.0          if not solver:
    95         5         63.0     12.6      0.1              if not self.solver_name and "solver_name" in environ:
    96                                                           self.solver_name = environ["solver_name"]
    97         5         22.0      4.4      0.0              if not self.solver_name and "solver_name".upper() in environ:
    98                                                           self.solver_name = environ["solver_name".upper()]
    99                                           
   100                                                       # creating a solver instance
   101         5          4.0      0.8      0.0              if self.solver_name.upper() in ["GUROBI", "GRB"]:
   102                                                           from mip.gurobi import SolverGurobi
   103                                           
   104                                                           self.solver = SolverGurobi(self, name, sense)
   105         5          5.0      1.0      0.0              elif self.solver_name.upper() == "CBC":
   106                                                           from mip.cbc import SolverCbc
   107                                           
   108                                                           self.solver = SolverCbc(self, name, sense)
   109                                                       else:
   110                                                           # checking which solvers are available
   111         5          4.0      0.8      0.0                  try:
   112         5      95309.0  19061.8     90.9                      from mip.gurobi import SolverGurobi
   113                                           
   114                                                               has_gurobi = True
   115         5          6.0      1.2      0.0                  except ImportError:
   116         5        258.0     51.6      0.2                      has_gurobi = False
   117                                           
   118         5          3.0      0.6      0.0                  if has_gurobi:
   119                                                               from mip.gurobi import SolverGurobi
   120                                           
   121                                                               self.solver = SolverGurobi(self, name, sense)
   122                                                               self.solver_name = GUROBI
   123                                                           else:
   124         5         25.0      5.0      0.0                      from mip.cbc import SolverCbc
   125                                           
   126         5       8951.0   1790.2      8.5                      self.solver = SolverCbc(self, name, sense)
   127         5          4.0      0.8      0.0                      self.solver_name = CBC
   128                                           
   129                                                   # list of constraints and variables
   130         5         10.0      2.0      0.0          self.constrs = ConstrList(self)
   131         5         12.0      2.4      0.0          self.vars = VarList(self)
   132                                           
   133         5          6.0      1.2      0.0          self._status = OptimizationStatus.LOADED
   134                                           
   135                                                   # initializing additional control variables
   136         5          3.0      0.6      0.0          self.__cuts = -1
   137         5          2.0      0.4      0.0          self.__cut_passes = -1
   138         5          3.0      0.6      0.0          self.__clique = -1
   139         5          4.0      0.8      0.0          self.__preprocess = -1
   140         5          3.0      0.6      0.0          self.__cuts_generator = None
   141         5          2.0      0.4      0.0          self.__lazy_constrs_generator = None
   142         5          5.0      1.0      0.0          self.__start = None
   143         5          3.0      0.6      0.0          self.__threads = 0
   144         5          5.0      1.0      0.0          self.__lp_method = LP_Method.AUTO
   145         5          3.0      0.6      0.0          self.__n_cols = 0
   146         5          1.0      0.2      0.0          self.__n_rows = 0
   147         5          5.0      1.0      0.0          self.__gap = INF
   148         5          3.0      0.6      0.0          self.__store_search_progress_log = False
   149         5         13.0      2.6      0.0          self.__plog = ProgressLog()
   150         5          4.0      0.8      0.0          self.__integer_tol = 1e-6
   151         5          4.0      0.8      0.0          self.__infeas_tol = 1e-6
   152         5          3.0      0.6      0.0          self.__opt_tol = 1e-6
   153         5          4.0      0.8      0.0          self.__max_mip_gap = 1e-4
   154         5          3.0      0.6      0.0          self.__max_mip_gap_abs = 1e-10
   155         5          2.0      0.4      0.0          self.__seed = 0
   156         5          3.0      0.6      0.0          self.__round_int_vars = True
   157         5          4.0      0.8      0.0          self.__sol_pool_size = 10
nick-gorman commented 4 years ago

Awesome, thanks for your help with this.

h-g-s commented 4 years ago

Hi,

When the first object of a solver is created it loads the cbc module, which searches for files and loads a dynamic library. This does not happens in the subsequent creations. Maybe you could write a test with a loop to create it many times to average the creation time ?

On 12/08/2020 01:41, nick-gorman wrote:

Hi,

I was wondering why the model take time to initialise and can I speed this up in some way. In the example below the model takes approximately 1.5 s to load and when running as part of a more complicated piece of code takes 2.5 s to load. For my work I need to solve many MIPs so it becomes a bottleneck.

|from mip import Model from time import time t0 = time() x = Model("example") print('load mip model {}'.format(time() - t0)) |

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/coin-or/python-mip/issues/135, or unsubscribe https://github.com/notifications/unsubscribe-auth/AB4VZOWO4I3NTRQWJIWZXADSAIMPRANCNFSM4P4B3DQQ.

--

Haroldo Gambini Santos Computing Department Universidade Federal de Ouro Preto - UFOP email: haroldo@ufop.edu.br home/research page: www.decom.ufop.br/haroldo

It has long been an axiom of mine that the little things are infinitely the most important. -- Sir Arthur Conan Doyle, "A Case of Identity"

h-g-s commented 4 years ago

On 12/08/2020 02:46, Michael Jurasovic wrote:

Oh damn, way faster if you specify the solver explicitly! I've got some changes to make.

I'd guess it's to do with the code that searches for the solver. I'll profile it and get back https://github.com/coin-or/python-mip/blob/326a88c0b31d1f4956271ffd57ca93452e50d83c/mip/model.py#L74-L105 https://github.com/coin-or/python-mip/blob/326a88c0b31d1f4956271ffd57ca93452e50d83c/mip/model.py#L74-L105

True ! It searches for different versions of Gurobi, this may slow down a lot. from mip import Model,xsum,maximize,BINARY,CBC import time

def knapsack(m): p = [10,13,18,31,7,15] w = [11,15,20,35,10,33] c,I = 47,range(len(w)) x = [m.add_var(var_type=BINARY)for i in I] m.objective = maximize(xsum(p[i] x[i]for i in I)) m += xsum(w[i] x[i]for i in I)<= c m.verbose = False m.optimize()

Create and solve a model a few times.

for i in range(5): t1 = time.perf_counter() model = Model(solver_name=CBC) print(f'run {i}: {(time.perf_counter() - t1)*1000:.3f}ms') knapsack(model)# Make it do something at least.

Clear model instead of recreating it.

t1 = time.perf_counter() model.clear() print(f'cleared {(time.perf_counter() - t1)*1000:.3f}ms') knapsack(model) |run 0: 93.020ms run 1: 0.076ms run 2: 0.074ms run 3: 0.073ms run 4: 0.087ms cleared 0.247ms |

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/coin-or/python-mip/issues/135#issuecomment-672610398, or unsubscribe https://github.com/notifications/unsubscribe-auth/AB4VZOXAMQL33YG3FM56EK3SAIUELANCNFSM4P4B3DQQ.

--

Haroldo Gambini Santos Computing Department Universidade Federal de Ouro Preto - UFOP email: haroldo@ufop.edu.br home/research page: www.decom.ufop.br/haroldo

It has long been an axiom of mine that the little things are infinitely the most important. -- Sir Arthur Conan Doyle, "A Case of Identity"

h-g-s commented 3 years ago

Hi @nick-gorman , this seems to be solved in 1.12, I'll close it for now, you can open again if some problem remains.