{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "# Profile in Notebook" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Profiling with Python CProfiler" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Before getting started, this example requires the config flag `PFlow.init_tds` to be `0`, which is the default value." ] }, { "cell_type": "code", "execution_count": 1, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:01.143169Z", "start_time": "2021-03-18T00:45:00.625170Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:51.284759Z", "iopub.status.busy": "2021-09-26T22:41:51.284343Z", "iopub.status.idle": "2021-09-26T22:41:51.870015Z", "shell.execute_reply": "2021-09-26T22:41:51.870533Z" } }, "outputs": [], "source": [ "import andes\n", "from andes.utils.paths import get_case\n", "\n", "case_path = get_case('kundur/kundur_full.xlsx')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Passing `profile=True, no_output = True` to `run` will enable the profiler and have the results printed." ] }, { "cell_type": "code", "execution_count": 2, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:04.746020Z", "start_time": "2021-03-18T00:45:01.145480Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:51.873974Z", "iopub.status.busy": "2021-09-26T22:41:51.872776Z", "iopub.status.idle": "2021-09-26T22:41:55.836681Z", "shell.execute_reply": "2021-09-26T22:41:55.837403Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "Working directory: \"/home/hacui/repos/andes/examples\"\n", "Loaded config from file \"/home/hacui/.andes/andes.rc\"\n", "Loaded generated Python code in \"/home/hacui/.andes/pycode\".\n", "Parsing input file \"/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx\"...\n", "Input file parsed in 0.2928 seconds.\n", "System internal structure set up in 0.0339 seconds.\n", "-> System connectivity check results:\n", " No islanded bus detected.\n", " A total of 1 island(s) detected.\n", " Each island has a slack bus correctly defined and enabled.\n", "\n", "-> Power flow calculation\n", " Sparse solver: KLU\n", " Solution method: NR method\n", "Numba compilation initiated with caching.\n", "Power flow initialized in 0.2752 seconds.\n", "0: |F(x)| = 14.9282832\n", "1: |F(x)| = 3.608627841\n", "2: |F(x)| = 3.371691245\n", "3: |F(x)| = 3.38335788\n", "4: |F(x)| = 1.643469337\n", "5: |F(x)| = 0.2341714002\n", "6: |F(x)| = 0.03397375079\n", "7: |F(x)| = 0.0009863888463\n", "8: |F(x)| = 1.354810848e-06\n", "9: |F(x)| = 2.629008122e-12\n", "Converged in 10 iterations in 0.0072 seconds.\n", "\n", "-> Time Domain Simulation Summary:\n", "Sparse Solver: KLU\n", "Simulation time: 0.0-20.0 s.\n", "Fixed step size: h=33.33 ms. Shrink if not converged.\n", "Numba compilation initiated with caching.\n", "PQ.vcmp out of limits \n", "\n", " idx | Flag | Input Value | Limit\n", "------+------+-------------+------\n", " PQ_1 | zl | 0.833 | 0.900\n", "\n", "\n", "Initialization for dynamics completed in 0.1149 seconds.\n", "Initialization was successful.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ ": Line.Line_8 status changed to 0 at t=2.0 sec. \n", "100%|███████████████████████████████| 100/100 [00:00<00:00, 142.57%/s]" ] }, { "name": "stderr", "output_type": "stream", "text": [ "Simulation completed in 0.7017 seconds.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ "\n" ] }, { "name": "stderr", "output_type": "stream", "text": [ "\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ " 2468624 function calls (2438847 primitive calls) in 1.587 seconds\n", "\n", " Ordered by: cumulative time\n", " List reduced from 7730 to 40 due to restriction <40>\n", "\n", " ncalls tottime percall cumtime percall filename:lineno(function)\n", " 1 0.004 0.004 0.824 0.824 /home/hacui/repos/andes/andes/routines/tds.py:280(run)\n", " 603 0.000 0.000 0.687 0.001 /home/hacui/repos/andes/andes/routines/tds.py:416(itm_step)\n", " 603 0.048 0.000 0.687 0.001 /home/hacui/repos/andes/andes/routines/daeint.py:27(step)\n", " 10103 0.052 0.000 0.611 0.000 /home/hacui/repos/andes/andes/system.py:1658(call_models)\n", " 2003 0.006 0.000 0.546 0.000 /home/hacui/repos/andes/andes/routines/tds.py:703(fg_update)\n", " 1164/205 0.003 0.000 0.498 0.002 :1002(_find_and_load)\n", " 1097/139 0.002 0.000 0.496 0.004 :967(_find_and_load_unlocked)\n", " 988/57 0.001 0.000 0.493 0.009 :844(exec_module)\n", " 1465/57 0.000 0.000 0.493 0.009 :220(_call_with_frames_removed)\n", " 1070/139 0.002 0.000 0.491 0.004 :659(_load_unlocked)\n", " 1062/115 0.002 0.000 0.490 0.004 {built-in method builtins.exec}\n", " 1 0.000 0.000 0.479 0.479 /home/hacui/repos/andes/andes/main.py:270(load)\n", " 1 0.000 0.000 0.293 0.293 /home/hacui/repos/andes/andes/io/__init__.py:98(parse)\n", " 1 0.000 0.000 0.292 0.292 /home/hacui/repos/andes/andes/io/xlsx.py:87(read)\n", " 1 0.000 0.000 0.285 0.285 /home/hacui/repos/andes/andes/routines/pflow.py:169(run)\n", " 61 0.000 0.000 0.283 0.005 /home/hacui/repos/andes/andes/utils/lazyimport.py:61(__maybe_import__)\n", " 60 0.000 0.000 0.281 0.005 /home/hacui/repos/andes/andes/utils/lazyimport.py:73(__getattr__)\n", " 2014 0.001 0.000 0.276 0.000 /home/hacui/repos/andes/andes/system.py:1004(g_update)\n", " 1 0.000 0.000 0.276 0.276 /home/hacui/repos/andes/andes/routines/pflow.py:62(init)\n", " 20095 0.127 0.000 0.259 0.000 /home/hacui/repos/andes/andes/core/model.py:1324(g_update)\n", " 2 0.000 0.000 0.213 0.106 /home/hacui/repos/andes/andes/system.py:757(init)\n", " 356/229 0.001 0.000 0.211 0.001 {built-in method builtins.__import__}\n", " 43 0.000 0.000 0.202 0.005 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/pandas/util/_decorators.py:302(wrapper)\n", " 2 0.000 0.000 0.199 0.099 /home/hacui/repos/andes/andes/system.py:682(_init_numba)\n", " 15 0.000 0.000 0.198 0.013 /home/hacui/repos/andes/andes/core/model.py:1698(numba_jitify)\n", " 36 0.000 0.000 0.198 0.006 /home/hacui/repos/andes/andes/core/model.py:2019(to_jit)\n", " 1 0.000 0.000 0.191 0.191 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/numba/__init__.py:1()\n", "3655/2445 0.002 0.000 0.184 0.000 :1033(_handle_fromlist)\n", " 1 0.000 0.000 0.182 0.182 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/pandas/io/excel/_base.py:330(read_excel)\n", " 94/93 0.000 0.000 0.181 0.002 /home/hacui/mambaforge/envs/a/lib/python3.9/importlib/__init__.py:109(import_module)\n", " 94/93 0.000 0.000 0.180 0.002 :1018(_gcd_import)\n", " 1 0.000 0.000 0.153 0.153 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/pandas/io/excel/_base.py:1166(__init__)\n", " 1 0.000 0.000 0.151 0.151 /home/hacui/repos/andes/andes/system.py:93(__init__)\n", " 1 0.000 0.000 0.151 0.151 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/pandas/io/excel/_openpyxl.py:506(__init__)\n", " 26 0.000 0.000 0.150 0.006 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/numba/core/dispatcher.py:340(_compile_for_args)\n", " 4 0.000 0.000 0.141 0.035 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/pandas/compat/_optional.py:64(import_optional_dependency)\n", " 26 0.000 0.000 0.138 0.005 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/numba/core/dispatcher.py:864(compile)\n", " 1 0.000 0.000 0.138 0.138 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/openpyxl/__init__.py:4()\n", " 26 0.000 0.000 0.135 0.005 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/numba/core/caching.py:636(load_overload)\n", " 1 0.000 0.000 0.131 0.131 /home/hacui/mambaforge/envs/a/lib/python3.9/site-packages/openpyxl/workbook/__init__.py:4()\n", "\n", "\n", "-> Single process finished in 1.7134 seconds.\n" ] } ], "source": [ "ss = andes.run(case_path, profile=True, routine='tds', no_output=True)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Profiling with `line_profiler`." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`line_profiler` provides line-based profiling results for functions. \n", "\n", "Install with `pip install line_profiler` and restart the notebook." ] }, { "cell_type": "code", "execution_count": 3, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:04.755264Z", "start_time": "2021-03-18T00:45:04.751789Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:55.842268Z", "iopub.status.busy": "2021-09-26T22:41:55.841760Z", "iopub.status.idle": "2021-09-26T22:41:55.845264Z", "shell.execute_reply": "2021-09-26T22:41:55.844565Z" } }, "outputs": [], "source": [ "import andes\n", "from andes.utils.paths import get_case\n", "\n", "case_path = get_case('kundur/kundur_full.xlsx')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Profile power flow " ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Pass the function name to profile to the magic `%lprun`, followed by a call to the function itself or an upper-level function.\n", "\n", "Results will be shown in a popup window." ] }, { "cell_type": "code", "execution_count": 4, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:05.289558Z", "start_time": "2021-03-18T00:45:04.756814Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:55.853967Z", "iopub.status.busy": "2021-09-26T22:41:55.853488Z", "iopub.status.idle": "2021-09-26T22:41:56.483582Z", "shell.execute_reply": "2021-09-26T22:41:56.486239Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "Working directory: \"/home/hacui/repos/andes/examples\"\n", "Reloaded generated Python code of module \"pycode\".\n", "Parsing input file \"/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx\"...\n", "Input file parsed in 0.0882 seconds.\n", "System internal structure set up in 0.0450 seconds.\n", "-> System connectivity check results:\n", " No islanded bus detected.\n", " A total of 1 island(s) detected.\n", " Each island has a slack bus correctly defined and enabled.\n", "\n", "-> Power flow calculation\n", " Sparse solver: KLU\n", " Solution method: NR method\n", "Power flow initialized in 0.0064 seconds.\n", "0: |F(x)| = 14.9282832\n", "1: |F(x)| = 3.608627841\n", "2: |F(x)| = 0.1701107882\n", "3: |F(x)| = 0.002038626956\n", "4: |F(x)| = 3.745103977e-07\n", "Converged in 5 iterations in 0.0050 seconds.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ "-> Single process finished in 0.3018 seconds.\n" ] } ], "source": [ "%load_ext line_profiler\n", "\n", "%lprun -f andes.routines.pflow.PFlow.run andes.run(case_path, no_output=True, default_config=True)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Alternatively, do" ] }, { "cell_type": "code", "execution_count": 5, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:05.550955Z", "start_time": "2021-03-18T00:45:05.292174Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:56.489675Z", "iopub.status.busy": "2021-09-26T22:41:56.489252Z", "iopub.status.idle": "2021-09-26T22:41:56.714187Z", "shell.execute_reply": "2021-09-26T22:41:56.714794Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "Working directory: \"/home/hacui/repos/andes/examples\"\n", "Reloaded generated Python code of module \"pycode\".\n", "Parsing input file \"/home/hacui/repos/andes/andes/cases/kundur/kundur_full.xlsx\"...\n", "Input file parsed in 0.0341 seconds.\n", "System internal structure set up in 0.0315 seconds.\n", "-> System connectivity check results:\n", " No islanded bus detected.\n", " A total of 1 island(s) detected.\n", " Each island has a slack bus correctly defined and enabled.\n", "\n", "-> Power flow calculation\n", " Sparse solver: KLU\n", " Solution method: NR method\n", "Power flow initialized in 0.0021 seconds.\n", "0: |F(x)| = 14.9282832\n", "1: |F(x)| = 3.608627841\n", "2: |F(x)| = 0.1701107882\n", "3: |F(x)| = 0.002038626956\n", "4: |F(x)| = 3.745103977e-07\n", "Converged in 5 iterations in 0.0030 seconds.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ "-> Single process finished in 0.1183 seconds.\n" ] } ], "source": [ "ss = andes.run(case_path, no_output=True, default_config=True)" ] }, { "cell_type": "code", "execution_count": 6, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:05.643255Z", "start_time": "2021-03-18T00:45:05.555237Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:56.717630Z", "iopub.status.busy": "2021-09-26T22:41:56.716839Z", "iopub.status.idle": "2021-09-26T22:41:56.794287Z", "shell.execute_reply": "2021-09-26T22:41:56.794895Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "System internal structure set up in 0.0203 seconds.\n", "-> System connectivity check results:\n", " No islanded bus detected.\n", " A total of 1 island(s) detected.\n", " Each island has a slack bus correctly defined and enabled.\n", "\n", "-> Power flow calculation\n", " Sparse solver: KLU\n", " Solution method: NR method\n", "Power flow initialized in 0.0059 seconds.\n", "0: |F(x)| = 14.9282832\n", "1: |F(x)| = 3.608627841\n", "2: |F(x)| = 0.1701107882\n", "3: |F(x)| = 0.002038626956\n", "4: |F(x)| = 3.745103977e-07\n", "Converged in 5 iterations in 0.0042 seconds.\n" ] } ], "source": [ "ss.reset()\n", "%lprun -f ss.PFlow.run ss.PFlow.run()" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "To dig into the Newton Raphson iteration steps, profile each step instead with:" ] }, { "cell_type": "code", "execution_count": 7, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:05.736950Z", "start_time": "2021-03-18T00:45:05.648221Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:56.797548Z", "iopub.status.busy": "2021-09-26T22:41:56.796772Z", "iopub.status.idle": "2021-09-26T22:41:56.879205Z", "shell.execute_reply": "2021-09-26T22:41:56.879818Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "System internal structure set up in 0.0197 seconds.\n", "-> System connectivity check results:\n", " No islanded bus detected.\n", " A total of 1 island(s) detected.\n", " Each island has a slack bus correctly defined and enabled.\n", "\n", "-> Power flow calculation\n", " Sparse solver: KLU\n", " Solution method: NR method\n", "Power flow initialized in 0.0059 seconds.\n", "0: |F(x)| = 14.9282832\n", "1: |F(x)| = 3.608627841\n", "2: |F(x)| = 0.1701107882\n", "3: |F(x)| = 0.002038626956\n", "4: |F(x)| = 3.745103977e-07\n", "Converged in 5 iterations in 0.0042 seconds.\n" ] } ], "source": [ "ss.reset()\n", "%lprun -f ss.PFlow.nr_step ss.PFlow.run()" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Profile time-domain simulation" ] }, { "cell_type": "code", "execution_count": 8, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:09.446492Z", "start_time": "2021-03-18T00:45:05.743150Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:56.882500Z", "iopub.status.busy": "2021-09-26T22:41:56.881761Z", "iopub.status.idle": "2021-09-26T22:41:59.789202Z", "shell.execute_reply": "2021-09-26T22:41:59.788931Z" } }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "\n", "-> Time Domain Simulation Summary:\n", "Sparse Solver: KLU\n", "Simulation time: 0.0-20.0 s.\n", "Fixed step size: h=33.33 ms. Shrink if not converged.\n", "Initialization for dynamics completed in 0.0536 seconds.\n", "Initialization was successful.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ ": Line.Line_8 status changed to 0 at t=2.0 sec. \n", "100%|███████████████████████████████| 100/100 [00:00<00:00, 101.60%/s]" ] }, { "name": "stderr", "output_type": "stream", "text": [ "Simulation completed in 0.9845 seconds.\n" ] }, { "name": "stdout", "output_type": "stream", "text": [ "\n" ] } ], "source": [ "%lprun -f ss.TDS.itm_step ss.TDS.run()" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Cleanup" ] }, { "cell_type": "code", "execution_count": 9, "metadata": { "ExecuteTime": { "end_time": "2021-03-18T00:45:10.807143Z", "start_time": "2021-03-18T00:45:09.448316Z" }, "execution": { "iopub.execute_input": "2021-09-26T22:41:59.791386Z", "iopub.status.busy": "2021-09-26T22:41:59.790444Z", "iopub.status.idle": "2021-09-26T22:42:00.549283Z", "shell.execute_reply": "2021-09-26T22:42:00.549530Z" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "\r\n", " _ _ | Version 1.5.7.post27.dev0+g9e0e253e\r\n", " /_\\ _ _ __| |___ ___ | Python 3.9.7 on Linux, 12/14/2021 02:51:15 PM\r\n", " / _ \\| ' \\/ _` / -_|_-< | \r\n", " /_/ \\_\\_||_\\__,_\\___/__/ | This program comes with ABSOLUTELY NO WARRANTY.\r\n", "\r\n", "No output file found in the working directory.\r\n" ] } ], "source": [ "!andes misc -C" ] } ], "metadata": { "interpreter": { "hash": "4c42303ec617988e96980582546035234a0dbb343f6614254a1d5bddbb9babb9" }, "kernelspec": { "display_name": "Python 3 (ipykernel)", "language": "python", "name": "python3" }, "language_info": { "codemirror_mode": { "name": "ipython", "version": 3 }, "file_extension": ".py", "mimetype": "text/x-python", "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", "version": "3.9.10" }, "varInspector": { "cols": { "lenName": 16, "lenType": 16, "lenVar": 40 }, "kernels_config": { "python": { "delete_cmd_postfix": "", "delete_cmd_prefix": "del ", "library": "var_list.py", "varRefreshCmd": "print(var_dic_list())" }, "r": { "delete_cmd_postfix": ") ", "delete_cmd_prefix": "rm(", "library": "var_list.r", "varRefreshCmd": "cat(var_dic_list()) " } }, "types_to_exclude": [ "module", "function", "builtin_function_or_method", "instance", "_Feature" ], "window_display": false } }, "nbformat": 4, "nbformat_minor": 4 }