Profile Pyomo.DAE and identify bottlenecks

[blnicho]

Pyomo.DAE has never been formally profiled and it's possible that there are some simple performance improvements that could be made in the discretization transformations.

[jsiirola]

Archived on the master Performance Proposals Issue (#1430). Closing this performance proposal until active development has begun.

[blnicho]

Some profiling information on a large DAE model (courtesy of @michaelbynum):

INFO:utils:         1397505974 function calls (1392948676 primitive calls) in 3057.029 seconds

   Ordered by: cumulative time
   List reduced from 436 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000 3057.029 3057.029 fs_us.py:38(build_burgers_model)
        2    0.000    0.000 2842.824 1421.412 ...//repos/pyomo/pyomo/core/base/plugin.py:236(apply_to)
        2    0.000    0.000 2842.824 1421.412 ...//repos/pyomo/pyomo/dae/plugins/finitedifference.py:153(_apply_to)
        2    0.001    0.000 2842.823 1421.412 ...//repos/pyomo/pyomo/dae/plugins/finitedifference.py:206(_transformBlock)
        2    0.000    0.000 2150.136 1075.068 ...//repos/pyomo/pyomo/dae/misc.py:101(expand_components)
       49    0.572    0.012 2150.132   43.880 ...//repos/pyomo/pyomo/dae/misc.py:176(update_contset_indexed_component)
  6758664    7.281    0.000 2137.303    0.000 ...//repos/pyomo/pyomo/core/base/util.py:296(__call__)
  4761726    7.413    0.000 2050.095    0.000 ...//repos/pyomo/pyomo/dae/misc.py:381(_disc_eq)
  4761726  142.079    0.000 1997.921    0.000 ...//repos/pyomo/pyomo/dae/misc.py:371(<lambda>)
       15    7.005    0.467 1997.294  133.153 ...//repos/pyomo/pyomo/dae/misc.py:267(_update_constraint)
  1587264    6.891    0.000 1708.466    0.001 ...//repos/pyomo/pyomo/dae/plugins/finitedifference.py:88(_bwd_fun)
  4864181 1197.059    0.000 1210.924    0.000 {built-in method builtins.sorted}
    30/24    0.001    0.000  591.787   24.658 ...//repos/pyomo/pyomo/core/base/block.py:901(add_component)
  4761726  450.909    0.000  450.909    0.000 {method 'index' of 'list' objects}
        3    0.000    0.000  377.587  125.862 ...//repos/pyomo/pyomo/dae/misc.py:374(add_discretization_equations)
       10    3.998    0.400  377.587   37.759 ...//repos/pyomo/pyomo/core/base/constraint.py:791(construct)
        2    0.142    0.071  315.097  157.549 ...//repos/pyomo/pyomo/dae/misc.py:26(generate_finite_elements)
    51234   19.525    0.000  313.794    0.006 {built-in method builtins.max}
4864281/4864223    2.394    0.000  305.773    0.000 ...//repos/pyomo/pyomo/core/base/set.py:1134(__iter__)
  4864252    6.409    0.000  303.368    0.000 ...//repos/pyomo/pyomo/core/base/set.py:1675(_iter_impl)
    51230   18.931    0.000  294.025    0.006 ...//repos/pyomo/pyomo/core/base/set.py:1729(_sort)
 40243909   35.363    0.000  279.358    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:364(__getitem__)
    51230  256.330    0.005  256.330    0.005 ...//repos/pyomo/pyomo/core/base/set.py:1732(<dictcomp>)
       38    0.000    0.000  214.201    5.637 ...//repos/pyomo/pyomo/core/base/block.py:525(__setattr__)
        2    0.091    0.045  214.197  107.099 ...//repos/pyomo/pyomo/core/base/expression.py:358(construct)
    51202    0.201    0.000  213.748    0.004 ...//repos/pyomo/pyomo/dae/integral.py:112(_trap_rule)
3123290/51230    2.567    0.000  213.101    0.004 ...//repos/pyomo/pyomo/core/base/misc.py:53(apply_indexed_rule)
    51202    0.956    0.000  212.407    0.004 {built-in method builtins.sum}
  1638432    6.292    0.000  205.941    0.000 ...//repos/pyomo/pyomo/dae/integral.py:114(<genexpr>)
  3072060   12.568    0.000  185.755    0.000 fs_us.py:122(_intX)
 14490008   10.104    0.000  184.084    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:517(_validate_index)
 14285150   55.650    0.000  173.775    0.000 ...//repos/pyomo/pyomo/core/base/set.py:3624(get)
27341154/25856354   64.627    0.000  172.851    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1591(_generate_sum_expression)
  3481784    2.178    0.000  152.286    0.000 ...//repos/pyomo/pyomo/core/base/constraint.py:1036(add)
       15   26.211    1.747  152.264   10.151 ...//repos/pyomo/pyomo/dae/misc.py:252(_update_var)
  6758666   17.121    0.000  151.194    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:748(_setitem_when_not_present)
  3481784    6.823    0.000  150.108    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:420(__setitem__)
  6246520   48.570    0.000  128.673    0.000 ...//repos/pyomo/pyomo/core/base/constraint.py:407(set_value)
  7936135    2.827    0.000  126.044    0.000 ...//repos/pyomo/pyomo/core/base/var.py:628(add)
 13670636   33.110    0.000  122.261    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1735(_generate_mul_expression)



INFO:utils:         1397505974 function calls (1392948676 primitive calls) in 3057.029 seconds

   Ordered by: internal time
   List reduced from 436 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  4864181 1197.059    0.000 1210.924    0.000 {built-in method builtins.sorted}
  4761726  450.909    0.000  450.909    0.000 {method 'index' of 'list' objects}
    51230  256.330    0.005  256.330    0.005 ...//repos/pyomo/pyomo/core/base/set.py:1732(<dictcomp>)
  4761726  142.079    0.000 1997.921    0.000 ...//repos/pyomo/pyomo/dae/misc.py:371(<lambda>)
27341154/25856354   64.627    0.000  172.851    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1591(_generate_sum_expression)
  8686391   58.583    0.000   59.498    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1003(is_potentially_variable)
 14285150   55.650    0.000  173.775    0.000 ...//repos/pyomo/pyomo/core/base/set.py:3624(get)
 47412373   53.753    0.000   53.753    0.000 {method 'get' of 'dict' objects}
 45995918   48.885    0.000   79.146    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1573(_process_arg)
  6246520   48.570    0.000  128.673    0.000 ...//repos/pyomo/pyomo/core/base/constraint.py:407(set_value)
  7475313   47.629    0.000   53.547    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:961(add)
 14285150   38.794    0.000  103.128    0.000 ...//repos/pyomo/pyomo/core/base/set.py:3633(_find_val)
 40243909   35.363    0.000  279.358    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:364(__getitem__)
 13670636   33.110    0.000  122.261    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1735(_generate_mul_expression)
       15   26.211    1.747  152.264   10.151 ...//repos/pyomo/pyomo/dae/misc.py:252(_update_var)
  6246520   22.730    0.000   36.287    0.000 ...//repos/pyomo/pyomo/core/expr/logical_expr.py:330(_generate_relational_expression)
    51234   19.525    0.000  313.794    0.006 {built-in method builtins.max}
    51230   18.931    0.000  294.025    0.006 ...//repos/pyomo/pyomo/core/base/set.py:1729(_sort)
 28826394   18.354    0.000   23.741    0.000 ...//repos/pyomo/pyomo/core/base/set.py:1243(get)
  6758666   17.121    0.000  151.194    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:748(_setitem_when_not_present)
 42855450   14.726    0.000   49.927    0.000 ...//repos/pyomo/pyomo/core/base/set.py:3654(<genexpr>)
 14285150   13.851    0.000   14.997    0.000 ...//repos/pyomo/pyomo/core/base/set.py:3608(_flatten_product)
 31744860   13.729    0.000   46.399    0.000 ...//repos/pyomo/pyomo/core/base/set.py:465(__contains__)
 37069396   13.708    0.000   16.418    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:154(arg)
  3072060   12.568    0.000  185.755    0.000 fs_us.py:122(_intX)
  7936135   12.189    0.000   24.608    0.000 ...//repos/pyomo/pyomo/core/base/var.py:636(_getitem_when_not_present)
 14490008   10.104    0.000  184.084    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:517(_validate_index)
 22305795   10.035    0.000   12.596    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:956(__init__)
  6144149    9.529    0.000   18.737    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1864(_generate_other_expression)
  1792068    8.959    0.000   78.243    0.000 fs_us.py:103(_pde)
 14285162    8.586    0.000   58.514    0.000 {built-in method builtins.all}
 11008298    8.296    0.000   12.327    0.000 <frozen importlib._bootstrap>:1009(_handle_fromlist)
 10598545    8.246    0.000   34.229    0.000 ...//repos/pyomo/pyomo/dae/misc.py:369(<lambda>)
77654612/77654604    7.632    0.000    7.632    0.000 {built-in method builtins.len}
 42548326    7.508    0.000    7.508    0.000 {built-in method builtins.hasattr}
  4761726    7.413    0.000 2050.095    0.000 ...//repos/pyomo/pyomo/dae/misc.py:381(_disc_eq)
  6041701    7.348    0.000   15.921    0.000 ...//repos/pyomo/pyomo/core/expr/numvalue.py:170(value)
  6758664    7.281    0.000 2137.303    0.000 ...//repos/pyomo/pyomo/core/base/util.py:296(__call__)
  3072089    7.147    0.000   29.023    0.000 ...//repos/pyomo/pyomo/core/base/param.py:488(_getitem_when_not_present)
       15    7.005    0.467 1997.294  133.153 ...//repos/pyomo/pyomo/dae/misc.py:267(_update_constraint)



INFO:utils:         2188548282 function calls (2062359229 primitive calls) in 1290.943 seconds

   Ordered by: cumulative time
   List reduced from 616 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    4.761    4.761 1290.943 1290.943 ...//repos/parapint/parapint/interfaces/interface.py:243(__init__)
        1   30.619   30.619 1269.535 1269.535 ...//repos/pyomo/pyomo/contrib/pynumero/interfaces/pyomo_nlp.py:36(__init__)
        1    4.446    4.446 1049.502 1049.502 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:269(__call__)
        1  146.932  146.932 1045.056 1045.056 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:665(_print_model_NL)
  6246521   18.660    0.000  411.664    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:245(generate_standard_repn)
  6041659   31.580    0.000  375.718    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:973(_generate_standard_repn)
13824118/6041659   86.233    0.000  234.776    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:424(_collect_sum)
73350035/1484801  143.302    0.000  207.003    0.000 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:433(_print_nonlinear_terms_NL)
43008235/6041688   27.041    0.000  189.773    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:946(_collect_standard_repn)
15308888/6041688   18.717    0.000  176.765    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:522(_collect_prod)
 102401/1    0.194    0.000  126.164  126.164 ...//repos/pyomo/pyomo/repn/standard_repn.py:854(_collect_identity)
  7628863    5.296    0.000   94.773    0.000 ...//repos/pyomo/pyomo/core/expr/visitor.py:1150(identify_variables)
  7628863   48.289    0.000   87.239    0.000 ...//repos/pyomo/pyomo/core/expr/visitor.py:429(xbfs_yield_leaves)
        1    0.011    0.011   82.321   82.321 ...//repos/pyomo/pyomo/contrib/pynumero/interfaces/ampl_nlp.py:35(__init__)
 20224361   77.060    0.000   79.010    0.000 ...//repos/pyomo/pyomo/common/collections/component_map.py:105(__setitem__)
        1   67.154   67.154   67.176   67.176 ...//repos/pyomo/pyomo/contrib/pynumero/asl.py:32(__init__)
 12288029   19.986    0.000   65.786    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:671(_collect_pow)
  4556858    3.299    0.000   40.868    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:842(_collect_negation)
 14182683    4.441    0.000   39.896    0.000 ...//repos/pyomo/pyomo/core/base/block.py:1404(component_data_objects)
        8   20.327    2.541   35.516    4.440 {method 'update' of 'dict' objects}
 14182683    9.767    0.000   35.455    0.000 ...//repos/pyomo/pyomo/core/base/block.py:1328(_component_data_iter)
    53/23    0.084    0.002   34.970    1.520 {method 'extend' of 'list' objects}
        1    0.000    0.000   34.887   34.887 ...//repos/pyomo/pyomo/common/env.py:448(__init__)
        1    0.000    0.000   34.885   34.885 ...//repos/pyomo/pyomo/common/env.py:452(<genexpr>)
       10    0.000    0.000   34.885    3.488 ...//repos/pyomo/pyomo/common/env.py:45(_load_dll)
       10    0.002    0.000   34.885    3.488 .../miniconda3/lib/python3.7/ctypes/util.py:319(find_library)
       30    0.004    0.000   34.495    1.150 .../miniconda3/lib/python3.7/subprocess.py:656(__init__)
       30    0.008    0.000   34.487    1.150 .../miniconda3/lib/python3.7/subprocess.py:1383(_execute_child)
        3    0.000    0.000   34.094   11.365 ...//repos/pyomo/pyomo/core/expr/symbol_map.py:72(addSymbols)
       10    0.000    0.000   31.266    3.127 ...//repos/pyomo/pyomo/common/env.py:216(available)
 13772829    4.569    0.000   29.716    0.000 ...//repos/pyomo/pyomo/core/expr/numvalue.py:832(__rmul__)
  7731323   12.144    0.000   29.707    0.000 {method 'writelines' of '_io._IOBase' objects}
  7731391    5.888    0.000   27.131    0.000 {built-in method builtins.sorted}
 15462640   15.867    0.000   26.657    0.000 ...//repos/pyomo/pyomo/core/base/set.py:581(bounds)
 52121716   21.775    0.000   25.227    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:154(arg)
 13772829   20.754    0.000   25.148    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1735(_generate_mul_expression)
 14182690    5.036    0.000   21.243    0.000 ...//repos/pyomo/pyomo/core/base/indexed_component.py:359(iteritems)
  7731320    2.070    0.000   20.464    0.000 ...//repos/pyomo/pyomo/core/base/var.py:77(has_lb)
  7731320    1.991    0.000   19.875    0.000 ...//repos/pyomo/pyomo/core/base/var.py:84(has_ub)
       70   18.839    0.269   18.839    0.269 {built-in method posix.read}



INFO:utils:         2188548282 function calls (2062359229 primitive calls) in 1290.943 seconds

   Ordered by: internal time
   List reduced from 616 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1  146.932  146.932 1045.056 1045.056 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:665(_print_model_NL)
73350035/1484801  143.302    0.000  207.003    0.000 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:433(_print_nonlinear_terms_NL)
13824118/6041659   86.233    0.000  234.776    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:424(_collect_sum)
 20224361   77.060    0.000   79.010    0.000 ...//repos/pyomo/pyomo/common/collections/component_map.py:105(__setitem__)
        1   67.154   67.154   67.176   67.176 ...//repos/pyomo/pyomo/contrib/pynumero/asl.py:32(__init__)
  7628863   48.289    0.000   87.239    0.000 ...//repos/pyomo/pyomo/core/expr/visitor.py:429(xbfs_yield_leaves)
  6041659   31.580    0.000  375.718    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:973(_generate_standard_repn)
        1   30.619   30.619 1269.535 1269.535 ...//repos/pyomo/pyomo/contrib/pynumero/interfaces/pyomo_nlp.py:36(__init__)
43008235/6041688   27.041    0.000  189.773    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:946(_collect_standard_repn)
 52121716   21.775    0.000   25.227    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:154(arg)
 13772829   20.754    0.000   25.148    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1735(_generate_mul_expression)
        8   20.327    2.541   35.516    4.440 {method 'update' of 'dict' objects}
 12288029   19.986    0.000   65.786    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:671(_collect_pow)
       70   18.839    0.269   18.839    0.269 {built-in method posix.read}
15308888/6041688   18.717    0.000  176.765    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:522(_collect_prod)
  6246521   18.660    0.000  411.664    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:245(generate_standard_repn)
107757117   18.198    0.000   18.198    0.000 {method 'write' of '_io.TextIOWrapper' objects}
 15462640   15.867    0.000   26.657    0.000 ...//repos/pyomo/pyomo/core/base/set.py:581(bounds)
 26061185   15.648    0.000   17.002    0.000 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:995(<genexpr>)
       30   15.633    0.521   15.633    0.521 {built-in method _posixsubprocess.fork_exec}
11689413/11484606   15.321    0.000   16.709    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:1003(is_potentially_variable)
 36741950   14.115    0.000   16.511    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:170(args)
 41948631   13.850    0.000   17.506    0.000 ...//repos/pyomo/pyomo/core/expr/visitor.py:1126(visit)
 67789880   13.285    0.000   13.285    0.000 {method 'get' of 'dict' objects}
 20121985   12.630    0.000   12.630    0.000 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:1751(<genexpr>)
  7731323   12.144    0.000   29.707    0.000 {method 'writelines' of '_io._IOBase' objects}
141211189   11.825    0.000   11.825    0.000 {built-in method builtins.id}
 12493040   11.544    0.000   14.665    0.000 ...//repos/pyomo/pyomo/core/base/constraint.py:221(has_lb)
 14182683    9.767    0.000   35.455    0.000 ...//repos/pyomo/pyomo/core/base/block.py:1328(_component_data_iter)
 30566547    9.735    0.000    9.735    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:408(__init__)
100317400    8.838    0.000    8.838    0.000 {method 'append' of 'list' objects}
        1    8.322    8.322   14.789   14.789 ...//repos/pyomo/pyomo/contrib/pynumero/interfaces/ampl_nlp.py:98(_collect_nlp_structure)
85266536/85266378    7.385    0.000    7.386    0.000 {built-in method builtins.len}
 13977844    6.973    0.000    6.973    0.000 ...//repos/pyomo/pyomo/core/expr/symbol_map.py:80(<genexpr>)
 12493040    6.850    0.000   16.422    0.000 ...//repos/pyomo/pyomo/repn/plugins/ampl/ampl_.py:135(_get_bound)
 13977847    6.609    0.000    6.609    0.000 {method 'update' of 'set' objects}
  7731320    6.587    0.000    6.587    0.000 {method 'union' of 'set' objects}
104243432    6.297    0.000    6.297    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:136(nargs)
  6041659    6.075    0.000    9.912    0.000 ...//repos/pyomo/pyomo/repn/standard_repn.py:59(isclose_const)
 84732240    5.910    0.000    5.910    0.000 ...//repos/pyomo/pyomo/core/expr/numeric_expr.py:459(is_expression_type)

[michaelbynum]

I should have mentioned that the first two sets of output are for model construction. The second two outputs are primarily writing an nl file.