{ "cells": [ { "cell_type": "code", "execution_count": 1, "id": "96f63fad", "metadata": { "execution": { "iopub.execute_input": "2026-10-02T14:44:35.101060Z", "iopub.status.busy": "2026-10-02T14:44:35.100857Z", "iopub.status.idle": "2026-10-02T14:44:35.105130Z", "shell.execute_reply": "2026-10-02T14:44:35.104336Z" }, "papermill": { "duration": 0.00743, "end_time": "2026-10-02T14:44:35.105760+00:00", "exception": false, "start_time": "2026-10-02T14:44:35.098330+00:00", "status": "completed" }, "tags": [ "remove-input", "active-ipynb", "remove-output" ] }, "outputs": [], "source": [ "try:\n", " from openmdao.utils.notebook_utils import notebook_mode # noqa: F401\n", "except ImportError:\n", " !python -m pip install openmdao[notebooks]" ] }, { "cell_type": "markdown", "id": "6efa4c37", "metadata": { "papermill": { "duration": 0.001036, "end_time": "2026-10-02T14:44:35.108235+00:00", "exception": false, "start_time": "2026-10-02T14:44:35.107199+00:00", "status": "completed" }, "tags": [] }, "source": [ "# Timing Systems under MPI\n", "\n", "There is a way to view timings for methods called on specific group and component instances in \n", "an OpenMDAO model when running under MPI. It displays how that model spends its time \n", "across MPI processes.\n", "\n", "The simplest way to use it is via the command line using the `openmdao timing` command. For example:\n", "``` bash\n", " mpirun -n openmdao timing \n", "```\n", "\n", "This will collect the timing data and generate a text report that could look something like this:\n", "\n", "```\n", " Problem: main method: _solve_nonlinear\n", "\n", " Parallel group: traj.phases (ncalls = 3)\n", "\n", " System Rank Avg Time Min Time Max_time Total Time\n", " ------ ---- -------- -------- -------- ----------\n", " groundroll 0 0.0047 0.0047 0.0048 0.0141\n", " rotation 0 0.0047 0.0047 0.0047 0.0141\n", " ascent 0 0.0084 0.0083 0.0085 0.0252\n", " accel 0 0.0042 0.0042 0.0042 0.0127\n", " climb1 0 0.0281 0.0065 0.0713 0.0843\n", " climb2 1 21.7054 1.0189 57.5102 65.1161\n", " climb2 2 21.6475 1.0189 57.3367 64.9426\n", " climb2 3 21.7052 1.0188 57.5101 65.1156\n", "\n", " Parallel group: traj2.phases (ncalls = 3)\n", "\n", " System Rank Avg Time Min Time Max_time Total Time\n", " ------ ---- -------- -------- -------- ----------\n", " desc1 0 0.0479 0.0041 0.1357 0.1438\n", " desc1 1 0.0481 0.0041 0.1362 0.1444\n", " desc2 2 0.0381 0.0035 0.1072 0.1143\n", " desc2 3 0.0381 0.0035 0.1073 0.1144\n", "\n", " Parallel group: traj.phases.climb2.rhs_all.prop.eng.env_pts (ncalls = 3)\n", "\n", " System Rank Avg Time Min Time Max_time Total Time\n", " ------ ---- -------- -------- -------- ----------\n", " node_2 1 4.7018 0.2548 13.0702 14.1055\n", " node_5 1 4.6113 0.2532 12.5447 13.8338\n", " node_8 1 5.4608 0.2538 15.3201 16.3824\n", " node_11 1 5.8348 0.2525 13.3362 17.5044\n", " node_1 2 4.8227 0.2534 13.3842 14.4680\n", " node_4 2 5.1912 0.2526 14.4703 15.5737\n", " node_7 2 5.4818 0.2524 15.3875 16.4454\n", " node_10 2 4.3591 0.2530 12.2027 13.0773\n", " node_0 3 5.0172 0.2501 14.1460 15.0515\n", " node_3 3 5.1350 0.2493 14.3048 15.4050\n", " node_6 3 5.3238 0.2487 14.9546 15.9715\n", " node_9 3 4.9638 0.2502 14.0088 14.8914\n", "```\n", "\n", "There will be a section of the report for each ParallelGroup in the model, and each section has\n", "a header containing the name of the ParallelGroup method being called and the number of times that\n", "method was called. Each section contains a line for each subsystem in that ParallelGroup for each MPI \n", "rank where that subsystem is active. Each of those lines will show the subsystem name, the MPI rank, \n", "and the average, minimum, maximum, and total execution time for that subsystem on that rank.\n", "\n", "In the table shown above, the model was run using 4 processes, and we can see that in the \n", "`traj.phases` parallel group, there is an uneven distribution of average execution times among its \n", "6 subsystems. The `traj.phases.climb2` subsystem takes far longer to execute (approximately \n", "21 seconds vs. a fraction of a second) than any of the other subsystems in `traj.phases`, so it makes \n", "sense that it is being given more processes (3) than the others. In fact, all of the other subsystems \n", "share a single process. The relative execution times are so different in this case that it would\n", "probably decrease the overall execution time if all of the subsystems in `traj.phases` were run\n", "on all 4 processes. This is certainly true if we assume that the execution time of `climb2` will\n", "decrease in a somewhat linear fashion as we let it run on more processes. If that's the case then\n", "we could estimate the sequential execution time of `climb2` to be around 65 seconds, so, assuming\n", "linear speedup it's execution time would decrease to around 16 seconds, which is about 5 seconds\n", "faster than the case shown in the table. The sum of execution times of all of the other subsystems\n", "combined is only about 1/20th of a second, so duplicating all of them on all processes will cost us\n", "far less than we saved by running `climb2` on 4 processes instead of 3.\n", "\n", "If the `openmdao timing` command is run with a `-v` option of 'browser' (see arguments below), then \n", "an interactive table view will be shown in the browser and might look something like this:\n", "\n", "![An example of a timing viewer](timing_viewer.png)\n", "\n", "There is a row in the table for each method specified for each group or component instance in the model, on each MPI rank. The default method is `_solve_nonlinear`, which gives a good view of how the timing of nonlinear\n", "execution breaks down for different parts of the system tree. `_solve_nonlinear` is a framework method\n", "that calls `compute` for explicit components and `apply_nonlinear` for implicit ones. If you're more\n", "interested in timing of derivative computations, you could use the `-f` or `--function` args \n", "(see arg descriptions below) to add `_linearize`, which calls `compute_partials` for explicit components \n", "and `linearize` for implicit ones, and/or `_apply_linear`, which calls `compute_jacvec_product`\n", "for explicit components or `apply_linear` for implicit ones. The reason to add the framework\n", "methods `_solve_nonlinear`, `_linearize`, and `_apply_linear` instead of the component level ones\n", "like `compute`, etc. is that the framework methods are called on both groups and components\n", "and so provide a clearer way to view timing contributions of subsystems to their parent ParallelGroup\n", "whether those subsystems happen to be components or groups.\n", "\n", "There are columns in the table for mpi rank, number of procs, level in the system tree, whether a system is the child of a parallel group or not, problem name, system path, method name, number of calls, total time, percent of total time, average time, min time, and max time. If the case was not run\n", "under more than one MPI process, then the columns for mpi rank, number of procs, parallel columns will\n", "not be shown. All columns are sortable, and most are filterable except those containing floating \n", "point numbers.\n", "\n", "\n", "Documentation of options for all commands described here can be obtained by running the command followed by the -h option. For example:\n", "\n", "``` bash\n", " openmdao timing -h\n", "```\n", "\n", "```\n", "usage: openmdao timing [-h] [-o OUTFILE] [-f FUNCS] [-v VIEW] [--use_context] file\n", "\n", "positional arguments:\n", " file Python file containing the model, or pickle file containing previously recorded timing\n", " data.\n", "\n", "optional arguments:\n", " -h, --help show this help message and exit\n", " -o OUTFILE Name of output file where timing data will be stored. By default it goes to\n", " \"timings.pkl\".\n", " -f FUNCS, --func FUNCS\n", " Time a specified function. Can be applied multiple times to specify multiple functions.\n", " Default methods are ['_apply_linear', '_solve_nonlinear'].\n", " -v VIEW, --view VIEW View of the output. Default view is 'text', which shows timing for each direct child of a\n", " parallel group across all ranks. Other options are ['browser', 'dump', 'none'].\n", " --use_context If set, timing will only be active within a timing_context.\n", "\n", "```\n", "\n", "If you don't like the default set of methods, you can specify your own using the `-f` or `--funct` options. \n", "This option can be applied multiple times to specify multiple functions.\n", "\n", "The `-v` and `--view` options default to \"text\", showing a table like the one above. You can also \n", "choose \"browser\" which will display an interactive table in a browser, \"dump\" which will give you \n", "essentially an ascii dump of the table data, or \"none\" which generates no output other than a pickle \n", "file, typically \"timings.pkl\" that contains the timing data and can be used for later viewing.\n", "\n", "The `--use_context` option is for occasions when you only want to time a certain portion of your script. \n", "In that case, you can wrap the code of interest in a `timing_context` context manager as shown below." ] }, { "cell_type": "code", "execution_count": 2, "id": "d7b830c5", "metadata": { "execution": { "iopub.execute_input": "2026-10-02T14:44:35.111053Z", "iopub.status.busy": "2026-10-02T14:44:35.110925Z", "iopub.status.idle": "2026-10-02T14:44:35.794828Z", "shell.execute_reply": "2026-10-02T14:44:35.794037Z" }, "papermill": { "duration": 0.686674, "end_time": "2026-10-02T14:44:35.796013+00:00", "exception": false, "start_time": "2026-10-02T14:44:35.109339+00:00", "status": "completed" }, "tags": [] }, "outputs": [], "source": [ "from openmdao.visualization.timing_viewer.timer import timing_context\n", "\n", "# do some stuff that I don't want to time...\n", "\n", "with timing_context():\n", " # do stuff I want to time\n", " pass\n", "\n", "# do some other stuff that I don't want to time..." ] }, { "cell_type": "markdown", "id": "f7430b2d", "metadata": { "papermill": { "duration": 0.001156, "end_time": "2026-10-02T14:44:35.798623+00:00", "exception": false, "start_time": "2026-10-02T14:44:35.797467+00:00", "status": "completed" }, "tags": [] }, "source": [ "```{Warning}\n", "If the `use_context` option is set, timing will not occur anywhere outside of `timing_context`, so be careful not to use that option on a script that doesn't use a `timing_context`, because in that case, no timing will be done. \n", "```\n", "\n", "```{Warning}\n", "If you *don't* specify `use_context` but your script *does* contain a `timing_context`, then that `timing_context` will be ignored and timing info will be collected for the entire script anyway.\n", "```\n", "\n", "After your script is finished running, you should see a new file called *timings.pkl* in your current directory. This is a pickle file containing all of the timing data. If you specified a view option of \"browser\", you'll also see a file called *timing_report.html* which can be opened in a browser to view the interactive timings table discussed earlier.\n", "\n", "\n", "```{Warning}\n", "If your script exits with a nonzero exit code, the timing data will not be saved to a file.\n", "```\n" ] } ], "metadata": { "celltoolbar": "Tags", "kernelspec": { "display_name": "Python 3", "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.13.14" }, "orphan": true, "papermill": { "default_parameters": {}, "duration": 1.774879, "end_time": "2026-10-02T14:44:36.215889+00:00", "environment_variables": {}, "exception": null, "input_path": "/home/runner/work/OpenMDAO/OpenMDAO/openmdao/docs/openmdao_book/features/debugging/profiling/timing.ipynb", "output_path": "/home/runner/work/OpenMDAO/OpenMDAO/openmdao/docs/_executed_book/features/debugging/profiling/timing.ipynb", "parameters": {}, "start_time": "2026-10-02T14:44:34.441010+00:00", "version": "2.7.0" } }, "nbformat": 4, "nbformat_minor": 5 }