|
| 1 | +# Expression Profiling |
| 2 | + |
| 3 | +Part of the appeal of ActivitySim is in its flexibility: it is possible to craft |
| 4 | +a massive variety of mathematical forms and relationships through creative use |
| 5 | +of the expressions found in most component spec files. But as we have all learned |
| 6 | +from Spider-Man, with great power comes great responsibility. Users can write |
| 7 | +arbitrary code in spec files, and the runtime performance of ActivitySim will |
| 8 | +depend on the parsimony and efficiency of that code. |
| 9 | + |
| 10 | +Sometimes these spec files can be large, and it may be difficult to determine |
| 11 | +simply by inspection which expressions in a given spec file are faster or slower. |
| 12 | +ActivitySim now offers an expression-level profiling tool to assist in diagnosing |
| 13 | +performance problems that arise from inefficient spec files. |
| 14 | + |
| 15 | +```{important} |
| 16 | +At this time, |
| 17 | +expression profiling only works for the evaluation of expressions in "legacy" mode. |
| 18 | +It does not work in "sharrow" mode, as the compiled expressions run with sharrow |
| 19 | +are not run in a serial fashion and are not able to be profiled in the same way. |
| 20 | +``` |
| 21 | + |
| 22 | +## Profiling an Entire Model Run |
| 23 | + |
| 24 | +The simplest way to use the expression profiler is to set the |
| 25 | +[`expression_profile`](activitysim.core.configuration.Settings.expression_profile) |
| 26 | +configuration setting in the top level model settings (typically `settings.yaml`): |
| 27 | + |
| 28 | +```yaml |
| 29 | +expression_profile: true |
| 30 | +``` |
| 31 | + |
| 32 | +This will cause the profiler to be activated for all expressions in the model, |
| 33 | +across all components. This includes expressions in the spec files, as well as |
| 34 | +expressions in all preprocessors and annotators. Each time the expressions in |
| 35 | +any spec file are evaluated, the profiler will record the time taken to evaluate |
| 36 | +each expression. An "expr-performance" subdirectory will be created in the model's |
| 37 | +logging directory, and a new log file will be created each time the expressions in |
| 38 | +any spec file are evaluated. The file is named according to the `trace_label` found |
| 39 | +where the expressions are being evaluated. It will include a list of all the evaluated |
| 40 | +expressions from the spec file, along with the time taken to evaluate each expression. |
| 41 | +For multi-processed models, each subprocess will create its own log file directory, |
| 42 | +similar to the logging directory structure for the other model components. |
| 43 | + |
| 44 | +## Summary Outputs |
| 45 | + |
| 46 | +At the end of a model run where the `expression_profile` setting is active, |
| 47 | +ActivitySim will also create a pair of summary files in the "expr-performance" |
| 48 | +subdirectory. The first is named "expression-timing-subcomponents.html", |
| 49 | +and contains a simple concatenation of the runtimes of |
| 50 | +expressions in the various subcomponents stored in the log files, |
| 51 | +filtered to only include expressions that tool a notable amount of time. |
| 52 | +By default, this is set to 0.1 seconds, but can be changed by setting the |
| 53 | +[`expression_profile_cutoff`](activitysim.core.configuration.Settings.expression_profile_cutoff) |
| 54 | +configuration setting in the model settings. |
| 55 | + |
| 56 | +The second file, "expression-timing-components.html", shows an aggregate |
| 57 | +summary of the runtimes for each expression, |
| 58 | +aggregated across all the log files. The aggregation is by model component and |
| 59 | +expression, so that this summary includes the total time taken to evaluate each |
| 60 | +expression within each model component, recognizing that identical expressions |
| 61 | +may be evaluated multiple times in different model subcomponents (e.g. across |
| 62 | +different purposes, or tour numbers, etc.). This more aggregated summary is |
| 63 | +typically the one that will be most useful for identifying expressions that |
| 64 | +provide the most overall potential for performance improvement via streamlining. |
| 65 | + |
| 66 | +Users should note that the expression profiler is not a substitute for good coding |
| 67 | +practices. It will not necessarily identify all performance problems, and it is not |
| 68 | +able to suggest improvements to the expressions. It is simply a tool to help users |
| 69 | +identify which expressions are taking the most time to evaluate, and therefore |
| 70 | +which expressions are the best candidates for improvement. |
| 71 | + |
| 72 | +Also, users should understand that the expression profiler is not directly measuring the |
| 73 | +computational complexity of the expressions, but rather the time taken to evaluate |
| 74 | +the expressions. This time can be affected by a number of factors, including the |
| 75 | +complexity of the expression, the size of the data being processed, and whether |
| 76 | +there are other processes running on the machine at the same time competing for |
| 77 | +resources. For multiprocessing model runs, those other processes may include |
| 78 | +other the subprocesses of ActivitySim, which may lead to surprising results. |
| 79 | + |
| 80 | +There is also no adjustment made for parallelization of the expression evaluations. |
| 81 | +For example, if the same expression is evaluated in parallel across 8 processes on |
| 82 | +a machine with 8 cores, and each process takes 0.1 seconds to evaluate the expression, |
| 83 | +the profiler will still show that the expression took 0.8 seconds to evaluate, even |
| 84 | +though the total wall clock time taken to evaluate the expression across all processes |
| 85 | +was only 0.1 seconds. |
| 86 | + |
| 87 | +Profiling expressions also adds some overhead to the model run, increasing the |
| 88 | +total runtime of the model by a modest but noticeable amount. In consortium |
| 89 | +[experiments](https://github.com/ActivitySim/activitysim/pull/936#issuecomment-3165410169) |
| 90 | +with this tool, runtime for the full-scale SANDAG model was found to |
| 91 | +increase by approximately 12.5% when the profiler was enabled, adding more than |
| 92 | +13 minutes to a model run that already took 105 minutes. Users should thus |
| 93 | +be careful about using the profiler in production runs. It is recommended turn off |
| 94 | +the profiler in production runs, and only use it for debugging and development. |
| 95 | + |
| 96 | +## Profiling Individual Components |
| 97 | + |
| 98 | +The expression profiler can also be used to profile individual components, rather |
| 99 | +than the entire model. This is done by setting the `compute_settings.performance_log` |
| 100 | +attribute for the component in the model settings. This attribute can be set to the |
| 101 | +filename where the profiler log file should be written, which will override |
| 102 | +the default behavior of writing the log file to the "expr-performance" subdirectory. |
| 103 | +This feature only works for components that are run in a single process, and which |
| 104 | +have a `compute_settings` attribute. It is generally not recommended to use this |
| 105 | +feature unless a specific component is suspected of having atypical performance |
| 106 | +problems, as it will not provide the same summary reporting as profiling the entire |
| 107 | +model. |
0 commit comments