Profile in Notebook#

Profiling with Python CProfiler#

Before getting started, this example requires the config flag PFlow.init_tds to be 0, which is the default value.

import andes
from andes.utils.paths import get_case

case_path = get_case("kundur/kundur_full.xlsx")

Passing profile=True, no_output = True to run will enable the profiler and have the results printed.

ss = andes.run(
    case_path, profile=True, routine="tds", no_output=True, default_config=True
)
Working directory: "/home/hacui/repos/andes/examples"
> Loaded generated Python code in "/home/hacui/.andes/pycode".
Parsing input file "/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx"...
Input file parsed in 0.3536 seconds.
System internal structure set up in 0.0412 seconds.
-> System connectivity check results:
  No islanded bus detected.
  System is interconnected.
  Each island has a slack bus correctly defined and enabled.

-> Power flow calculation
           Numba: Off
   Sparse solver: KLU
 Solution method: NR method
Power flow initialized in 0.0051 seconds.
0: |F(x)| = 14.9282832
1: |F(x)| = 3.608627841
2: |F(x)| = 0.1701107882
3: |F(x)| = 0.002038626956
4: |F(x)| = 3.745103977e-07
Converged in 5 iterations in 0.0045 seconds.
Initialization for dynamics completed in 0.0368 seconds.
Initialization was successful.
<Toggle 1>: Line.Line_8 status changed to 0 at t=2.0 sec.
Simulation to t=20.00 sec completed in 0.9577 seconds.
         2126948 function calls (2100484 primitive calls) in 1.634 seconds

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

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.006    0.006    1.065    1.065 /home/hacui/repos/andes/andes/routines/tds.py:326(run)
      603    0.001    0.000    0.891    0.001 /home/hacui/repos/andes/andes/routines/tds.py:521(itm_step)
      603    0.051    0.000    0.890    0.001 /home/hacui/repos/andes/andes/routines/daeint.py:27(step)
     2025    0.006    0.000    0.703    0.000 /home/hacui/repos/andes/andes/routines/tds.py:820(fg_update)
    10176    0.060    0.000    0.646    0.000 /home/hacui/repos/andes/andes/system.py:1672(call_models)
        1    0.000    0.000    0.558    0.558 /home/hacui/repos/andes/andes/main.py:275(load)
 1040/207    0.003    0.000    0.423    0.002 <frozen importlib._bootstrap>:1022(_find_and_load)
  960/129    0.002    0.000    0.420    0.003 <frozen importlib._bootstrap>:987(_find_and_load_unlocked)
   847/34    0.001    0.000    0.419    0.012 <frozen importlib._bootstrap_external>:877(exec_module)
   905/66    0.002    0.000    0.419    0.006 {built-in method builtins.exec}
  1246/34    0.001    0.000    0.418    0.012 <frozen importlib._bootstrap>:233(_call_with_frames_removed)
  925/130    0.002    0.000    0.415    0.003 <frozen importlib._bootstrap>:664(_load_unlocked)
     2030    0.001    0.000    0.367    0.000 /home/hacui/repos/andes/andes/system.py:1047(g_update)
        1    0.000    0.000    0.355    0.355 /home/hacui/repos/andes/andes/io/__init__.py:115(parse)
        1    0.000    0.000    0.353    0.353 /home/hacui/repos/andes/andes/io/xlsx.py:88(read)
    20279    0.082    0.000    0.349    0.000 /home/hacui/repos/andes/andes/core/model/model.py:963(g_update)
       35    0.000    0.000    0.270    0.008 /home/hacui/repos/andes/andes/utils/lazyimport.py:61(__maybe_import__)
       34    0.000    0.000    0.214    0.006 /home/hacui/repos/andes/andes/utils/lazyimport.py:73(__getattr__)
        1    0.000    0.000    0.213    0.213 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/__init__.py:1(<module>)
        1    0.000    0.000    0.169    0.169 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/core/api.py:1(<module>)
        1    0.000    0.000    0.161    0.161 /home/hacui/repos/andes/andes/system.py:93(__init__)
  109/107    0.000    0.000    0.138    0.001 /home/hacui/mambaforge/envs/a/lib/python3.10/importlib/__init__.py:108(import_module)
  109/107    0.000    0.000    0.138    0.001 <frozen importlib._bootstrap>:1038(_gcd_import)
        1    0.000    0.000    0.122    0.122 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/io/excel/_base.py:460(read_excel)
  254/196    0.000    0.000    0.108    0.001 {built-in method builtins.__import__}
     2030    0.001    0.000    0.101    0.000 /home/hacui/repos/andes/andes/system.py:1033(f_update)
        1    0.000    0.000    0.100    0.100 /home/hacui/repos/andes/andes/system.py:1800(import_models)
    79/52    0.000    0.000    0.097    0.002 <frozen importlib._bootstrap_external>:1182(exec_module)
    79/52    0.082    0.001    0.097    0.002 {built-in method _imp.exec_dynamic}
1636/1630    0.009    0.000    0.097    0.000 {built-in method builtins.__build_class__}
        1    0.000    0.000    0.097    0.097 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/io/excel/_base.py:1520(__init__)
        1    0.000    0.000    0.094    0.094 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/io/excel/_openpyxl.py:534(__init__)
    20279    0.039    0.000    0.086    0.000 /home/hacui/repos/andes/andes/core/model/model.py:935(f_update)
     2030    0.002    0.000    0.084    0.000 /home/hacui/repos/andes/andes/system.py:989(l_update_eq)
        4    0.000    0.000    0.083    0.021 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/compat/_optional.py:81(import_optional_dependency)
 1864/802    0.002    0.000    0.082    0.000 <frozen importlib._bootstrap>:1053(_handle_fromlist)
        1    0.000    0.000    0.080    0.080 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/openpyxl/__init__.py:1(<module>)
     2025    0.076    0.000    0.076    0.000 /home/hacui/.andes/pycode/GENROU.py:20(g_update)
        1    0.000    0.000    0.069    0.069 /home/hacui/mambaforge/envs/a/lib/python3.10/site-packages/pandas/core/arrays/__init__.py:1(<module>)
    20279    0.011    0.000    0.068    0.000 /home/hacui/repos/andes/andes/core/model/model.py:712(l_check_eq)


-> Single process finished in 1.7222 seconds.

Profiling with line_profiler.#

line_profiler provides line-based profiling results for functions.

Install with pip install line_profiler and restart the notebook.

import andes
from andes.utils.paths import get_case

case_path = get_case("kundur/kundur_full.xlsx")

Profile power flow#

Pass the function name to profile to the magic %lprun, followed by a call to the function itself or an upper-level function.

Results will be shown in a popup window.

%load_ext line_profiler

%lprun -f andes.routines.pflow.PFlow.run andes.run(case_path, no_output=True, default_config=True)
Working directory: "/home/hacui/repos/andes/examples"
> Reloaded generated Python code of module "pycode".
Parsing input file "/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx"...
Input file parsed in 0.0498 seconds.
System internal structure set up in 0.0402 seconds.
-> System connectivity check results:
  No islanded bus detected.
  System is interconnected.
  Each island has a slack bus correctly defined and enabled.

-> Power flow calculation
           Numba: Off
   Sparse solver: KLU
 Solution method: NR method
Power flow initialized in 0.0050 seconds.
0: |F(x)| = 14.9282832
1: |F(x)| = 3.608627841
2: |F(x)| = 0.1701107882
3: |F(x)| = 0.002038626956
4: |F(x)| = 3.745103977e-07
Converged in 5 iterations in 0.0041 seconds.
-> Single process finished in 0.2605 seconds.
Timer unit: 1e-09 s

Total time: 0.0114298 s
File: /home/hacui/repos/andes/andes/routines/pflow.py
Function: run at line 211

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   211                                               def run(self, **kwargs):
   212                                                   """
   213                                                   Solve the power flow using the selected method.
   214                                           
   215                                                   Returns
   216                                                   -------
   217                                                   bool
   218                                                       convergence status
   219                                                   """
   220                                           
   221         1       1363.0   1363.0      0.0          system = self.system
   222         1        581.0    581.0      0.0          if self.config.check_conn == 1:
   223         1    1378597.0    1e+06     12.1              self.system.connectivity()
   224                                           
   225         1     250450.0 250450.0      2.2          self.summary()
   226         1    5393416.0    5e+06     47.2          self.init()
   227                                           
   228         1        401.0    401.0      0.0          if system.dae.m == 0:
   229                                                       logger.error("Loaded case contains no power flow element.")
   230                                                       system.exit_code = 1
   231                                                       return False
   232                                           
   233         1        762.0    762.0      0.0          method = self.config.method.lower()
   234                                           
   235         1       4629.0   4629.0      0.0          t0, _ = elapsed()
   236                                           
   237                                                   # ---------- Call solution methods ----------
   238         1        251.0    251.0      0.0          if method == 'nr':
   239         1    4163484.0    4e+06     36.4              self.nr_solve()
   240                                                   elif method == 'nk':
   241                                                       self.newton_krylov()
   242                                           
   243         1       5711.0   5711.0      0.0          t1, s1 = elapsed(t0)
   244         1        311.0    311.0      0.0          self.exec_time = t1 - t0
   245                                           
   246         1        260.0    260.0      0.0          if not self.converged:
   247                                                       if abs(self.mis[-1] - self.mis[-2]) < self.config.tol:
   248                                                           max_idx = np.argmax(np.abs(system.dae.xy))
   249                                                           name = system.dae.xy_name[max_idx]
   250                                                           logger.error('Mismatch is not correctable possibly due to large load-generation imbalance.')
   251                                                           logger.error('Largest mismatch on equation associated with <%s>', name)
   252                                                       else:
   253                                                           logger.error('Power flow failed after %d iterations for "%s".', self.niter + 1, system.files.case)
   254                                           
   255                                                   else:
   256         1     222407.0 222407.0      1.9              logger.info('Converged in %d iterations in %s.', self.niter + 1, s1)
   257                                           
   258                                                       # make a copy of power flow solutions
   259         1       3146.0   3146.0      0.0              self.x_sol = system.dae.x.copy()
   260         1        862.0    862.0      0.0              self.y_sol = system.dae.y.copy()
   261                                           
   262         1        441.0    441.0      0.0              if self.config.init_tds:
   263                                                           system.TDS.init()
   264         1        330.0    330.0      0.0              if self.config.report:
   265         1       1803.0   1803.0      0.0                  system.PFlow.report()
   266                                           
   267         1        491.0    491.0      0.0          system.exit_code = 0 if self.converged else 1
   268         1        110.0    110.0      0.0          return self.converged

Alternatively, do

ss = andes.load(case_path, no_output=True, default_config=True)

%lprun -f ss.PFlow.run ss.PFlow.run()
Working directory: "/home/hacui/repos/andes/examples"
> Reloaded generated Python code of module "pycode".
Parsing input file "/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx"...
Input file parsed in 0.0293 seconds.
System internal structure set up in 0.0231 seconds.
-> System connectivity check results:
  No islanded bus detected.
  System is interconnected.
  Each island has a slack bus correctly defined and enabled.

-> Power flow calculation
           Numba: Off
   Sparse solver: KLU
 Solution method: NR method
Power flow initialized in 0.0043 seconds.
0: |F(x)| = 14.9282832
1: |F(x)| = 3.608627841
2: |F(x)| = 0.1701107882
3: |F(x)| = 0.002038626956
4: |F(x)| = 3.745103977e-07
Converged in 5 iterations in 0.0040 seconds.
Timer unit: 1e-09 s

Total time: 0.0109119 s
File: /home/hacui/repos/andes/andes/routines/pflow.py
Function: run at line 211

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   211                                               def run(self, **kwargs):
   212                                                   """
   213                                                   Solve the power flow using the selected method.
   214                                           
   215                                                   Returns
   216                                                   -------
   217                                                   bool
   218                                                       convergence status
   219                                                   """
   220                                           
   221         1        972.0    972.0      0.0          system = self.system
   222         1        511.0    511.0      0.0          if self.config.check_conn == 1:
   223         1    1557962.0    2e+06     14.3              self.system.connectivity()
   224                                           
   225         1     253977.0 253977.0      2.3          self.summary()
   226         1    4784035.0    5e+06     43.8          self.init()
   227                                           
   228         1        451.0    451.0      0.0          if system.dae.m == 0:
   229                                                       logger.error("Loaded case contains no power flow element.")
   230                                                       system.exit_code = 1
   231                                                       return False
   232                                           
   233         1        842.0    842.0      0.0          method = self.config.method.lower()
   234                                           
   235         1       4840.0   4840.0      0.0          t0, _ = elapsed()
   236                                           
   237                                                   # ---------- Call solution methods ----------
   238         1        211.0    211.0      0.0          if method == 'nr':
   239         1    4053092.0    4e+06     37.1              self.nr_solve()
   240                                                   elif method == 'nk':
   241                                                       self.newton_krylov()
   242                                           
   243         1       5711.0   5711.0      0.1          t1, s1 = elapsed(t0)
   244         1        200.0    200.0      0.0          self.exec_time = t1 - t0
   245                                           
   246         1        241.0    241.0      0.0          if not self.converged:
   247                                                       if abs(self.mis[-1] - self.mis[-2]) < self.config.tol:
   248                                                           max_idx = np.argmax(np.abs(system.dae.xy))
   249                                                           name = system.dae.xy_name[max_idx]
   250                                                           logger.error('Mismatch is not correctable possibly due to large load-generation imbalance.')
   251                                                           logger.error('Largest mismatch on equation associated with <%s>', name)
   252                                                       else:
   253                                                           logger.error('Power flow failed after %d iterations for "%s".', self.niter + 1, system.files.case)
   254                                           
   255                                                   else:
   256         1     241955.0 241955.0      2.2              logger.info('Converged in %d iterations in %s.', self.niter + 1, s1)
   257                                           
   258                                                       # make a copy of power flow solutions
   259         1       3116.0   3116.0      0.0              self.x_sol = system.dae.x.copy()
   260         1        701.0    701.0      0.0              self.y_sol = system.dae.y.copy()
   261                                           
   262         1        562.0    562.0      0.0              if self.config.init_tds:
   263                                                           system.TDS.init()
   264         1        241.0    241.0      0.0              if self.config.report:
   265         1       1753.0   1753.0      0.0                  system.PFlow.report()
   266                                           
   267         1        441.0    441.0      0.0          system.exit_code = 0 if self.converged else 1
   268         1        110.0    110.0      0.0          return self.converged

To dig into the Newton Raphson iteration steps, profile each step instead with:

ss = andes.load(case_path, no_output=True, default_config=True)
%lprun -f ss.PFlow.nr_step ss.PFlow.run()
Working directory: "/home/hacui/repos/andes/examples"
> Reloaded generated Python code of module "pycode".
Parsing input file "/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx"...
Input file parsed in 0.0299 seconds.
System internal structure set up in 0.0242 seconds.
-> System connectivity check results:
  No islanded bus detected.
  System is interconnected.
  Each island has a slack bus correctly defined and enabled.

-> Power flow calculation
           Numba: Off
   Sparse solver: KLU
 Solution method: NR method
Power flow initialized in 0.0045 seconds.
0: |F(x)| = 14.9282832
1: |F(x)| = 3.608627841
2: |F(x)| = 0.1701107882
3: |F(x)| = 0.002038626956
4: |F(x)| = 3.745103977e-07
Converged in 5 iterations in 0.0040 seconds.
Timer unit: 1e-09 s

Total time: 0.00289216 s
File: /home/hacui/repos/andes/andes/routines/pflow.py
Function: nr_step at line 104

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   104                                               def nr_step(self):
   105                                                   """
   106                                                   Solve a single iteration step using the Newton-Raphson method.
   107                                           
   108                                                   Returns
   109                                                   -------
   110                                                   float
   111                                                       maximum absolute mismatch
   112                                                   """
   113                                           
   114         5       2064.0    412.8      0.1          system = self.system
   115                                           
   116                                                   # ---------- Build numerical DAE----------
   117         5    1288374.0 257674.8     44.5          self.fg_update()
   118                                           
   119                                                   # ---------- update the Jacobian on conditions ----------
   120         5       2365.0    473.0      0.1          if self.config.method != 'dishonest' or (self.niter < self.config.n_factorize):
   121         5    1263947.0 252789.4     43.7              system.j_update(self.models)
   122         5       4048.0    809.6      0.1              self.solver.worker.new_A = True
   123                                           
   124                                                   # ---------- prepare and solve linear equations ----------
   125         5      12294.0   2458.8      0.4          self.res[:system.dae.n] = -system.dae.f[:]
   126         5       9229.0   1845.8      0.3          self.res[system.dae.n:] = -system.dae.g[:]
   127                                           
   128        10      15200.0   1520.0      0.5          self.A = sparse([[system.dae.fx, system.dae.gx],
   129         5       1994.0    398.8      0.1                           [system.dae.fy, system.dae.gy]])
   130                                           
   131         5       1422.0    284.4      0.0          if not self.config.linsolve:
   132         5      95764.0  19152.8      3.3              self.inc = self.solver.solve(self.A, self.res)
   133                                                   else:
   134                                                       self.inc = self.solver.linsolve(self.A, self.res)
   135                                           
   136         5      15670.0   3134.0      0.5          system.dae.x += np.ravel(self.inc[:system.dae.n])
   137         5      11501.0   2300.2      0.4          system.dae.y += np.ravel(self.inc[system.dae.n:])
   138                                           
   139                                                   # find out variables associated with maximum mismatches
   140         5        591.0    118.2      0.0          fmax = 0
   141         5       1232.0    246.4      0.0          if system.dae.n > 0:
   142                                                       fmax_idx = np.argmax(np.abs(system.dae.f))
   143                                                       fmax = system.dae.f[fmax_idx]
   144                                                       logger.debug("Max. diff mismatch %.10g on %s", fmax, system.dae.x_name[fmax_idx])
   145                                           
   146         5      28063.0   5612.6      1.0          gmax_idx = np.argmax(np.abs(system.dae.g))
   147         5       2987.0    597.4      0.1          gmax = system.dae.g[gmax_idx]
   148         5      87689.0  17537.8      3.0          logger.debug("Max. algeb mismatch %.10g on %s", gmax, system.dae.y_name[gmax_idx])
   149                                           
   150         5       6012.0   1202.4      0.2          mis = max(abs(fmax), abs(gmax))
   151         5      41141.0   8228.2      1.4          system.vars_to_models()
   152                                           
   153         5        570.0    114.0      0.0          return mis

Profile time-domain simulation#

xy = ss.TDS.init()
Initialization for dynamics completed in 0.0209 seconds.
Initialization was successful.
%lprun -f ss.TDS.itm_step ss.TDS.run()
-> Time Domain Simulation Summary:
Sparse Solver: KLU
Simulation time: 0.0-20.0 s.
Fixed step size: h=33.33 ms. Shrink if not converged.
<Toggle 1>: Line.Line_8 status changed to 0 at t=2.0 sec.
Simulation to t=20.00 sec completed in 0.9426 seconds.
Timer unit: 1e-09 s

Total time: 0.882568 s
File: /home/hacui/repos/andes/andes/routines/tds.py
Function: itm_step at line 521

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   521                                               def itm_step(self):
   522                                                   """
   523                                                   Integrate for the step size of ``self.h`` using implicit trapezoid method.
   524                                           
   525                                                   Returns
   526                                                   -------
   527                                                   bool
   528                                                       Convergence status in ``self.converged``.
   529                                           
   530                                                   """
   531       602  882567523.0    1e+06    100.0          return self.method.step(self)

Cleanup#

!andes misc -C
No output file found in the working directory.