{ "cells": [ { "cell_type": "markdown", "metadata": { "button": false, "new_sheet": false, "run_control": { "read_only": false }, "slideshow": { "slide_type": "slide" } }, "source": [ "# Debugging Performance Issues\n", "\n", "Most chapters of this book deal with _functional_ issues – that is, issues related to the _functionality_ (or its absence) of the code in question. However, debugging can also involve _nonfunctional_ issues, however – performance, usability, reliability, and more. In this chapter, we give a short introduction on how to debug such nonfunctional issues, notably _performance_ issues." ] }, { "cell_type": "code", "execution_count": 1, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:36:57.653006Z", "iopub.status.busy": "2025-01-20T09:36:57.652395Z", "iopub.status.idle": "2025-01-20T09:36:57.756849Z", "shell.execute_reply": "2025-01-20T09:36:57.756438Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [ { "data": { "text/html": [ "\n", " \n", " " ], "text/plain": [ "" ] }, "execution_count": 1, "metadata": {}, "output_type": "execute_result" } ], "source": [ "from bookutils import YouTubeVideo\n", "YouTubeVideo(\"0tMeB9G0uUI\")" ] }, { "cell_type": "markdown", "metadata": { "button": false, "new_sheet": false, "run_control": { "read_only": false }, "slideshow": { "slide_type": "subslide" } }, "source": [ "**Prerequisites**\n", "\n", "* This chapter leverages visualization capabilities from [the chapter on statistical debugging](StatisticalDebugger.ipynb).\n", "* We also show how to debug nonfunctional issues using [delta debugging](DeltaDebugger.ipynb)." ] }, { "cell_type": "code", "execution_count": 2, "metadata": { "button": false, "execution": { "iopub.execute_input": "2025-01-20T09:36:57.779119Z", "iopub.status.busy": "2025-01-20T09:36:57.778981Z", "iopub.status.idle": "2025-01-20T09:36:57.781315Z", "shell.execute_reply": "2025-01-20T09:36:57.781036Z" }, "new_sheet": false, "run_control": { "read_only": false }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import bookutils.setup" ] }, { "cell_type": "code", "execution_count": 3, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:36:57.782559Z", "iopub.status.busy": "2025-01-20T09:36:57.782453Z", "iopub.status.idle": "2025-01-20T09:36:58.719078Z", "shell.execute_reply": "2025-01-20T09:36:58.718389Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import StatisticalDebugger\n", "import DeltaDebugger" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "skip" } }, "source": [ "## Synopsis\n", "\n", "\n", "To [use the code provided in this chapter](Importing.ipynb), write\n", "\n", "```python\n", ">>> from debuggingbook.PerformanceDebugger import \n", "```\n", "\n", "and then make use of the following features.\n", "\n", "\n", "This chapter provides a class `PerformanceDebugger` that allows measuring and visualizing the time taken per line in a function.\n", "\n", "```python\n", ">>> with PerformanceDebugger(TimeCollector) as debugger:\n", ">>> for i in range(100):\n", ">>> s = remove_html_markup('foo')\n", "```\n", "The distribution of executed time within each function can be obtained by printing out the debugger:\n", "\n", "```python\n", ">>> print(debugger)\n", " 238 5% def remove_html_markup(s): # type: ignore\n", " 239 2% tag = False\n", " 240 2% quote = False\n", " 241 2% out = \"\"\n", " 242 0%\n", " 243 16% for c in s:\n", " 244 14% assert tag or not quote\n", " 245 0%\n", " 246 14% if c == '<' and not quote:\n", " 247 2% tag = True\n", " 248 11% elif c == '>' and not quote:\n", " 249 2% tag = False\n", " 250 8% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 8% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 2% return out\n", "\n", "\n", "```\n", "The sum of all percentages in a function should always be 100%.\n", "\n", "These percentages can also be visualized, where darker shades represent higher percentage values:\n", "\n", "```python\n", ">>> debugger\n", "```\n", "
 238 def remove_html_markup(s):  # type: ignore
\n", "
 239     tag = False
\n", "
 240     quote = False
\n", "
 241     out = ""
\n", "
 242  
\n", "
 243     for c in s:
\n", "
 244         assert tag or not quote
\n", "
 245  
\n", "
 246         if c == '<' and not quote:
\n", "
 247             tag = True
\n", "
 248         elif c == '>' and not quote:
\n", "
 249             tag = False
\n", "
 250         elif (c == '"' or c == "'") and tag:
\n", "
 251             quote = not quote
\n", "
 252         elif not tag:
\n", "
 253             out = out + c
\n", "
 254  
\n", "
 255     return out
\n", "\n", "\n", "The abstract `MetricCollector` class allows subclassing to build more collectors, such as `HitCollector`.\n", "\n", "![](PICS/PerformanceDebugger-synopsis-1.svg)\n", "\n" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Measuring Performance\n", "\n", "The solution to debugging performance issues fits in two simple rules:\n", "\n", "1. _Measure_ performance\n", "2. _Break down_ how individual parts of your code contribute to performance.\n", "\n", "The first part, actually _measuring_ performance, is key here. Developers often take elaborated guesses on which aspects of their code impact performance, and think about all possible ways to optimize their code – and at the same time, making it harder to understand, harder to evolve, and harder to maintain. In most cases, such guesses are wrong. Instead, _measure_ performance of your program, _identify_ the very few parts that may need to get improved, and again _measure_ the impact of your changes." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "Almost all programming languages offer a way to measure performance and breaking it down to individual parts of the code – a means also known as *profiling*. Profiling works by measuring the execution time for each function (or even more fine-grained location) in your program. This can be achieved by\n", "\n", "1. _Instrumenting_ or _tracing_ code such that the current time at entry and exit of each function (or line), thus determining the time spent. In Python, this is achieved by profilers like [profile or cProfile](https://docs.python.org/3/library/profile.html)\n", "\n", "2. _Sampling_ the current function call stack at regular intervals, and thus assessing which functions are most active (= take the most time) during execution. For Python, the [scalene](https://github.com/plasma-umass/scalene) profiler works this way.\n", "\n", "Pretty much all programming languages support profiling, either through measuring, sampling, or both. As a rule of thumb, _interpreted_ languages more frequently support measuring (as it is easy to implement in an interpreter), while _compiled_ languages more frequently support sampling (because instrumentation requires recompilation). Python is lucky to support both methods." ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "### Tracing Execution Profiles\n", "\n", "Let us illustrate profiling in a simple example. The `ChangeCounter` class (which we will encounter in the [chapter on mining version histories](ChangeCounter.ipynb)) reads in a version history from a git repository. Yet, it takes more than a minute to read in the debugging book change history:" ] }, { "cell_type": "code", "execution_count": 4, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:36:58.721514Z", "iopub.status.busy": "2025-01-20T09:36:58.721338Z", "iopub.status.idle": "2025-01-20T09:36:58.953733Z", "shell.execute_reply": "2025-01-20T09:36:58.953335Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from ChangeCounter import ChangeCounter, debuggingbook_change_counter # minor dependency" ] }, { "cell_type": "code", "execution_count": 5, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:36:58.955439Z", "iopub.status.busy": "2025-01-20T09:36:58.955307Z", "iopub.status.idle": "2025-01-20T09:36:58.957098Z", "shell.execute_reply": "2025-01-20T09:36:58.956859Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import Timer" ] }, { "cell_type": "code", "execution_count": 6, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:36:58.958358Z", "iopub.status.busy": "2025-01-20T09:36:58.958257Z", "iopub.status.idle": "2025-01-20T09:38:53.958717Z", "shell.execute_reply": "2025-01-20T09:38:53.958168Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "with Timer.Timer() as t:\n", " change_counter = debuggingbook_change_counter(ChangeCounter)" ] }, { "cell_type": "code", "execution_count": 7, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:38:53.961754Z", "iopub.status.busy": "2025-01-20T09:38:53.961611Z", "iopub.status.idle": "2025-01-20T09:38:53.964352Z", "shell.execute_reply": "2025-01-20T09:38:53.964138Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "114.99636066693347" ] }, "execution_count": 7, "metadata": {}, "output_type": "execute_result" } ], "source": [ "t.elapsed_time()" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The Python `profile` and `cProfile` modules offer a simple way to identify the most time-consuming functions. They are invoked using the `run()` function, whose argument is the command to be profiled. The output reports, for each function encountered:\n", "\n", "* How often it was called (`ncalls` column)\n", "* How much time was spent in the given function, _excluding_ time spent in calls to sub-functions (`tottime` column)\n", "* The fraction of `tottime` / `ncalls` (first `percall` column)\n", "* How much time was spent in the given function, _including_ time spent in calls to sub-functions (`cumtime` column)\n", "* The fraction of `cumtime` / `percall` (second `percall` column)\n", "\n", "Let us have a look at the profile we obtain:" ] }, { "cell_type": "code", "execution_count": 8, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:38:53.965894Z", "iopub.status.busy": "2025-01-20T09:38:53.965797Z", "iopub.status.idle": "2025-01-20T09:38:53.967312Z", "shell.execute_reply": "2025-01-20T09:38:53.967100Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import cProfile" ] }, { "cell_type": "code", "execution_count": 9, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:38:53.968441Z", "iopub.status.busy": "2025-01-20T09:38:53.968364Z", "iopub.status.idle": "2025-01-20T09:41:00.565662Z", "shell.execute_reply": "2025-01-20T09:41:00.565254Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ " 41673535 function calls (41472571 primitive calls) in 126.578 seconds\n", "\n", " Ordered by: cumulative time\n", "\n", " ncalls tottime percall cumtime percall filename:lineno(function)\n", " 2618 0.010 0.000 346.536 0.132 threading.py:1117(join)\n", "2631/2623 0.013 0.000 346.465 0.132 threading.py:1155(_wait_for_tstate_lock)\n", "23850/18599 0.066 0.000 342.649 0.018 {method 'acquire' of '_thread.lock' objects}\n", " 1361 0.008 0.000 126.887 0.093 repository.py:213(traverse_commits)\n", " 2/1 0.000 0.000 126.577 126.577 {built-in method builtins.exec}\n", " 2/1 0.000 0.000 126.577 126.577 :1()\n", " 2/1 0.000 0.000 126.577 126.577 ChangeCounter.ipynb:168(debuggingbook_change_counter)\n", " 1 0.000 0.000 126.577 126.577 ChangeCounter.ipynb:51(__init__)\n", " 1 0.000 0.000 126.577 126.577 ChangeCounter.ipynb:88(mine)\n", " 1 0.000 0.000 126.536 126.536 _base.py:646(__exit__)\n", " 1 0.000 0.000 126.536 126.536 thread.py:220(shutdown)\n", " 2618/1 0.034 0.000 126.536 126.536 threading.py:1018(_bootstrap)\n", " 2618/1 0.017 0.000 126.536 126.536 threading.py:1058(_bootstrap_inner)\n", " 2618/1 0.008 0.000 126.536 126.536 ipkernel.py:744(run_closure)\n", " 2618/1 14.680 0.006 126.536 126.536 threading.py:1001(run)\n", " 4/1 0.000 0.000 126.536 126.536 thread.py:70(_worker)\n", " 13/2 0.018 0.001 126.536 63.268 {method 'get' of '_queue.SimpleQueue' objects}\n", " 1360 0.158 0.000 126.203 0.093 ChangeCounter.ipynb:102(mine_commit)\n", " 1360 0.036 0.000 122.340 0.090 commit.py:753(modified_files)\n", " 1307 0.371 0.000 122.268 0.094 diff.py:184(diff)\n", " 1307 14.272 0.011 99.437 0.076 diff.py:583(_index_from_patch_format)\n", " 1307 0.048 0.000 79.488 0.061 cmd.py:97(handle_process_output)\n", "2614/1307 34.571 0.013 64.790 0.050 cmd.py:144(pump_stream)\n", " 125 29.203 0.234 42.094 0.337 {built-in method time.sleep}\n", "5336/5034 0.041 0.000 20.039 0.004 {method 'close' of '_io.BufferedReader' objects}\n", " 15102 0.081 0.000 18.502 0.001 diff.py:412(__init__)\n", " 14273 0.017 0.000 18.112 0.001 base.py:481(submodules)\n", " 14273 0.043 0.000 18.095 0.001 util.py:1270(list_items)\n", "33008/33002 0.053 0.000 18.037 0.001 {method 'extend' of 'list' objects}\n", " 42819 0.184 0.000 17.985 0.000 base.py:1571(iter_items)\n", " 1362 0.083 0.000 8.400 0.006 cmd.py:1523(_call_process)\n", " 1362 0.149 0.000 8.282 0.006 cmd.py:1079(execute)\n", " 1308 0.048 0.000 8.132 0.006 cmd.py:986()\n", " 1362 0.169 0.000 7.767 0.006 subprocess.py:807(__init__)\n", " 1362 0.210 0.000 7.494 0.006 subprocess.py:1791(_execute_child)\n", " 72725 0.091 0.000 6.520 0.000 util.py:248(__getattr__)\n", " 131552 0.380 0.000 5.990 0.000 cmd.py:1659(__get_object_header)\n", " 42819 0.036 0.000 5.883 0.000 base.py:715(commit)\n", "99911/28546 0.066 0.000 5.426 0.000 tree.py:361(__getitem__)\n", "99911/28546 0.246 0.000 5.389 0.000 tree.py:231(join)\n", " 42819 0.028 0.000 5.352 0.000 symbolic.py:290(_get_commit)\n", " 42819 0.049 0.000 5.324 0.000 symbolic.py:280(_get_object)\n", " 1362 5.100 0.004 5.100 0.004 {built-in method _posixsubprocess.fork_exec}\n", " 57092 0.063 0.000 4.758 0.000 tree.py:210(_set_cache_)\n", " 74460 0.151 0.000 4.722 0.000 db.py:44(stream)\n", " 234578 4.671 0.000 4.671 0.000 {method 'readline' of '_io.BufferedReader' objects}\n", " 29 0.001 0.000 4.562 0.157 base_events.py:1915(_run_once)\n", " 29/28 0.000 0.000 4.558 0.163 selectors.py:558(select)\n", " 74460 0.185 0.000 4.441 0.000 cmd.py:1695(stream_object_data)\n", " 57092 0.046 0.000 4.156 0.000 symbolic.py:156(dereference_recursive)\n", " 114185 0.109 0.000 4.109 0.000 symbolic.py:269(_get_ref_info)\n", " 114185 0.342 0.000 4.000 0.000 symbolic.py:221(_get_ref_info_helper)\n", " 14273 0.058 0.000 3.264 0.000 base.py:229(_config_parser)\n", " 57092 0.120 0.000 3.111 0.000 base.py:136(new_from_sha)\n", " 57092 0.126 0.000 2.642 0.000 db.py:39(info)\n", " 57092 0.066 0.000 2.408 0.000 cmd.py:1667(get_object_header)\n", " 14273 0.061 0.000 2.131 0.000 fun.py:230(rev_parse)\n", " 14273 0.046 0.000 2.059 0.000 fun.py:150(name_to_object)\n", " 131659 1.881 0.000 1.946 0.000 {built-in method _io.open}\n", " 1362 1.676 0.001 1.676 0.001 {built-in method posix.read}\n", " 15633 0.034 0.000 1.660 0.000 commit.py:241(_set_cache_)\n", "114505/100018 0.110 0.000 1.542 0.000 config.py:111(assure_data_present)\n", " 869 0.019 0.000 1.512 0.002 ChangeCounter.ipynb:121(update_stats)\n", " 14273 0.023 0.000 1.471 0.000 util.py:82(__init__)\n", " 1736 0.002 0.000 1.468 0.001 commit.py:214(content)\n", " 1736 0.004 0.000 1.466 0.001 commit.py:222(_get_undecoded_content)\n", " 14379 0.051 0.000 1.457 0.000 config.py:315(__init__)\n", " 14379 0.077 0.000 1.402 0.000 configparser.py:582(__init__)\n", " 74460 0.085 0.000 1.343 0.000 cmd.py:863(read)\n", " 58827 0.024 0.000 1.271 0.000 base.py:137(read)\n", " 148919 1.250 0.000 1.250 0.000 {method 'read' of '_io.BufferedReader' objects}\n", " 57092 0.724 0.000 1.161 0.000 fun.py:77(tree_entries_from_data)\n", "114505/100127 0.087 0.000 1.114 0.000 config.py:589(read)\n", " 14379 0.249 0.000 1.042 0.000 configparser.py:1287(__init__)\n", " 1307 0.953 0.001 0.953 0.001 {method 'join' of 'bytes' objects}\n", " 14272983 0.812 0.000 0.812 0.000 {method 'append' of 'list' objects}\n", " 114185 0.398 0.000 0.766 0.000 symbolic.py:173(_check_ref_name_valid)\n", " 14379 0.331 0.000 0.726 0.000 config.py:439(_read)\n", " 1735 0.001 0.000 0.665 0.000 base.py:192(data_stream)\n", " 114393 0.448 0.000 0.544 0.000 {method 'read' of '_io.TextIOWrapper' objects}\n", " 15633 0.126 0.000 0.534 0.000 commit.py:782(_deserialize)\n", " 14379 0.507 0.000 0.507 0.000 {built-in method builtins.dir}\n", " 15102 0.004 0.000 0.445 0.000 ChangeCounter.ipynb:112(include)\n", " 15102 0.014 0.000 0.441 0.000 ChangeCounter.ipynb:176(filter)\n", " 36455 0.053 0.000 0.440 0.000 commit.py:276(new_path)\n", " 131552 0.035 0.000 0.431 0.000 cmd.py:1646(_get_persistent_cmd)\n", " 1971717 0.393 0.000 0.393 0.000 {method 'match' of 're.Pattern' objects}\n", " 881745 0.352 0.000 0.352 0.000 cmd.py:972(__getattribute__)\n", " 499555 0.179 0.000 0.352 0.000 compat.py:117(safe_decode)\n", " 16462 0.006 0.000 0.330 0.000 commit.py:633(committer_date)\n", " 16462 0.007 0.000 0.324 0.000 commit.py:254(committed_datetime)\n", " 161261 0.193 0.000 0.321 0.000 posixpath.py:71(join)\n", " 131552 0.294 0.000 0.294 0.000 {method 'flush' of '_io.BufferedWriter' objects}\n", " 36076 0.051 0.000 0.289 0.000 pathlib.py:437(__str__)\n", " 57197 0.063 0.000 0.285 0.000 configparser.py:743(get)\n", " 14379 0.178 0.000 0.267 0.000 configparser.py:1210(__init__)\n", " 1362 0.041 0.000 0.243 0.000 os.py:748(copy)\n", " 31266 0.081 0.000 0.239 0.000 util.py:326(parse_actor_and_date)\n", " 2720 0.018 0.000 0.235 0.000 repository.py:245(_iter_commits)\n", " 128776 0.234 0.000 0.234 0.000 {method '__exit__' of '_io._IOBase' objects}\n", " 1086219 0.180 0.000 0.226 0.000 {built-in method builtins.getattr}\n", " 131552 0.152 0.000 0.226 0.000 cmd.py:1601(_parse_object_header)\n", " 806682 0.130 0.000 0.219 0.000 cmd.py:792(__getattr__)\n", " 1362 0.066 0.000 0.215 0.000 subprocess.py:1282(_close_pipe_fds)\n", " 1182431 0.212 0.000 0.212 0.000 {method 'decode' of 'bytes' objects}\n", " 131552 0.112 0.000 0.208 0.000 cmd.py:1632(_prepare_ref)\n", " 189736 0.164 0.000 0.206 0.000 base.py:100(__init__)\n", "2110652/2110648 0.201 0.000 0.205 0.000 {built-in method builtins.isinstance}\n", " 115598 0.094 0.000 0.204 0.000 base.py:231(__init__)\n", " 36075 0.025 0.000 0.199 0.000 pathlib.py:551(drive)\n", " 57092 0.104 0.000 0.198 0.000 util.py:111(get_object_type_by_name)\n", " 28884 0.129 0.000 0.191 0.000 util.py:91(mode_str_to_int)\n", " 115492 0.067 0.000 0.185 0.000 {built-in method builtins.any}\n", " 36073 0.022 0.000 0.174 0.000 pathlib.py:407(_load_parts)\n", " 2283688 0.164 0.000 0.164 0.000 {built-in method builtins.ord}\n", " 74138 0.064 0.000 0.163 0.000 commit.py:109(__init__)\n", " 58452 0.039 0.000 0.156 0.000 tree.py:192(__init__)\n", " 36073 0.060 0.000 0.146 0.000 pathlib.py:387(_parse_path)\n", " 2618 0.009 0.000 0.145 0.000 ipkernel.py:768(init_closure)\n", " 231540 0.074 0.000 0.137 0.000 os.py:841(fsencode)\n", " 2618 0.061 0.000 0.136 0.000 threading.py:884(__init__)\n", " 100015 0.093 0.000 0.134 0.000 util.py:272(join_path)\n", " 16462 0.016 0.000 0.132 0.000 util.py:211(from_timestamp)\n", " 57197 0.061 0.000 0.123 0.000 configparser.py:1122(_unify_values)\n", " 96807 0.046 0.000 0.121 0.000 os.py:709(__getitem__)\n", " 28546 0.020 0.000 0.121 0.000 base.py:437(index)\n", " 342554 0.070 0.000 0.118 0.000 symbolic.py:215()\n", " 2618 0.019 0.000 0.116 0.000 threading.py:975(start)\n", " 382507 0.115 0.000 0.115 0.000 {method 'split' of 'str' objects}\n", " 561325 0.110 0.000 0.110 0.000 {method 'endswith' of 'str' objects}\n", " 4086 0.061 0.000 0.103 0.000 contextlib.py:530(callback)\n", " 28546 0.017 0.000 0.101 0.000 base.py:140(__init__)\n", " 114393 0.069 0.000 0.097 0.000 codecs.py:319(decode)\n", " 896928 0.091 0.000 0.091 0.000 {built-in method builtins.len}\n", " 142986 0.072 0.000 0.091 0.000 config.py:218(__getitem__)\n", " 57197 0.056 0.000 0.089 0.000 __init__.py:1009(__getitem__)\n", " 1362 0.037 0.000 0.084 0.000 util.py:529(remove_password_if_present)\n", " 28546 0.013 0.000 0.083 0.000 base.py:172(_index_path)\n", " 14382 0.011 0.000 0.082 0.000 config.py:536(_has_includes)\n", " 2618 0.080 0.000 0.080 0.000 {built-in method _thread.start_new_thread}\n", " 32688 0.013 0.000 0.080 0.000 subprocess.py:1880()\n", " 98064 0.015 0.000 0.079 0.000 _collections_abc.py:868(__iter__)\n", " 101200 0.073 0.000 0.078 0.000 config.py:205(__setitem__)\n", " 330089 0.078 0.000 0.078 0.000 {method 'startswith' of 'str' objects}\n", " 1362 0.010 0.000 0.077 0.000 subprocess.py:1688(_get_handles)\n", " 460031 0.076 0.000 0.076 0.000 {method 'encode' of 'str' objects}\n", " 91562 0.076 0.000 0.076 0.000 {method 'search' of 're.Pattern' objects}\n", " 30204 0.010 0.000 0.075 0.000 diff.py:570(_pick_best_path)\n", " 28546 0.018 0.000 0.073 0.000 base.py:122(__init__)\n", " 28650 0.023 0.000 0.071 0.000 util.py:309(join_path_native)\n", " 14378 0.017 0.000 0.070 0.000 config.py:539(_included_paths)\n", " 31266 0.032 0.000 0.069 0.000 util.py:808(_from_string)\n", " 30204 0.034 0.000 0.065 0.000 diff.py:105(decode_path)\n", " 98064 0.036 0.000 0.064 0.000 os.py:732(__iter__)\n", " 2618 0.026 0.000 0.063 0.000 threading.py:637(wait)\n", " 114393 0.051 0.000 0.062 0.000 codecs.py:309(__init__)\n", " 36178 0.020 0.000 0.061 0.000 pathlib.py:1157(__init__)\n", " 193404 0.029 0.000 0.059 0.000 os.py:795(decode)\n", " 104 0.001 0.000 0.057 0.001 util.py:171(wrapper)\n", " 104 0.000 0.000 0.056 0.001 base.py:1404(module)\n", " 105 0.002 0.000 0.056 0.001 base.py:172(__init__)\n", " 16462 0.051 0.000 0.056 0.000 {built-in method fromtimestamp}\n", " 42820 0.023 0.000 0.055 0.000 base.py:450(head)\n", " 1362 0.019 0.000 0.053 0.000 os.py:654(get_exec_path)\n", " 162871 0.053 0.000 0.053 0.000 {method 'split' of 'bytes' objects}\n", " 173310 0.051 0.000 0.051 0.000 typing.py:392(inner)\n", " 164720 0.030 0.000 0.051 0.000 posixpath.py:41(_get_sep)\n", " 130562 0.050 0.000 0.050 0.000 {built-in method sys.intern}\n", " 306845 0.049 0.000 0.049 0.000 {method 'strip' of 'str' objects}\n", " 57098 0.033 0.000 0.049 0.000 :1390(_handle_fromlist)\n", " 114185 0.038 0.000 0.048 0.000 symbolic.py:52(_git_dir)\n", " 74460 0.028 0.000 0.047 0.000 base.py:128(__new__)\n", " 249923 0.046 0.000 0.046 0.000 {built-in method binascii.a2b_hex}\n", " 28546 0.033 0.000 0.045 0.000 symbolic.py:596(to_full_path)\n", " 96807 0.024 0.000 0.045 0.000 os.py:791(encode)\n", " 57093 0.024 0.000 0.044 0.000 :645(parent)\n", " 1361 0.008 0.000 0.044 0.000 _base.py:612(result_iterator)\n", " 159181 0.044 0.000 0.044 0.000 {method 'group' of 're.Match' objects}\n", " 183342 0.044 0.000 0.044 0.000 {built-in method __new__ of type object at 0x10119c990}\n", " 16462 0.038 0.000 0.043 0.000 {method 'astimezone' of 'datetime.datetime' objects}\n", " 1308 0.003 0.000 0.042 0.000 subprocess.py:1135(_get_devnull)\n", " 505424 0.042 0.000 0.042 0.000 {built-in method posix.fspath}\n", " 1361 0.000 0.000 0.042 0.000 git.py:110(get_list_commits)\n", " 36178 0.025 0.000 0.041 0.000 pathlib.py:358(__init__)\n", " 57092 0.025 0.000 0.040 0.000 base.py:35(__new__)\n", " 1308 0.006 0.000 0.040 0.000 util.py:500(finalize_process)\n", " 131684 0.040 0.000 0.040 0.000 {method 'write' of '_io.BufferedWriter' objects}\n", " 1308 0.039 0.000 0.039 0.000 {built-in method posix.open}\n", " 3966 0.007 0.000 0.039 0.000 threading.py:323(wait)\n", " 28546 0.023 0.000 0.038 0.000 configparser.py:855(has_option)\n", " 2668 0.004 0.000 0.038 0.000 subprocess.py:1259(wait)\n", " 2615 0.018 0.000 0.038 0.000 cmd.py:796(wait)\n", " 150627 0.037 0.000 0.037 0.000 {method 'startswith' of 'bytes' objects}\n", " 1414 0.008 0.000 0.037 0.000 cmd.py:789(__del__)\n", " 1360 0.020 0.000 0.036 0.000 _base.py:314(_result_or_cancel)\n", " 52 0.000 0.000 0.035 0.001 base.py:1427(module_exists)\n", " 2668 0.004 0.000 0.034 0.000 subprocess.py:2021(_wait)\n", " 1361 0.002 0.000 0.034 0.000 commit.py:512(_iter_from_process_or_stream)\n", " 36073 0.015 0.000 0.033 0.000 pathlib.py:429(_format_parsed_parts)\n", " 86935 0.019 0.000 0.033 0.000 diff.py:535(b_path)\n", " 42821 0.028 0.000 0.033 0.000 head.py:50(__init__)\n", " 172947 0.032 0.000 0.032 0.000 {method 'rstrip' of 'str' objects}\n", " 31266 0.024 0.000 0.031 0.000 util.py:146(utctz_to_altz)\n", " 2618 0.007 0.000 0.030 0.000 threading.py:588(__init__)\n", " 58346 0.029 0.000 0.029 0.000 config.py:208(add)\n", " 28651 0.022 0.000 0.029 0.000 configparser.py:630(sections)\n", " 1361 0.002 0.000 0.029 0.000 subprocess.py:2008(_try_wait)\n", " 4086 0.028 0.000 0.028 0.000 contextlib.py:475(_create_cb_wrapper)\n", " 1414 0.003 0.000 0.028 0.000 cmd.py:754(_terminate)\n", " 137045 0.027 0.000 0.027 0.000 {built-in method binascii.b2a_hex}\n", " 114393 0.027 0.000 0.027 0.000 {built-in method _codecs.utf_8_decode}\n", " 71949 0.027 0.000 0.027 0.000 {built-in method builtins.setattr}\n", " 1 0.001 0.001 0.027 0.027 _base.py:583(map)\n", "13128/1362 0.015 0.000 0.027 0.000 cmd.py:1477(_unpack_args)\n", " 15102 0.008 0.000 0.027 0.000 commit.py:595(committer)\n", " 102684 0.027 0.000 0.027 0.000 typing.py:1766(_no_init_or_replace_init)\n", " 1467 0.027 0.000 0.027 0.000 {built-in method posix.waitpid}\n", " 1362 0.018 0.000 0.026 0.000 contextlib.py:567(__exit__)\n", " 1339 0.017 0.000 0.025 0.000 parse.py:452(urlsplit)\n", " 143236 0.024 0.000 0.024 0.000 {built-in method builtins.hasattr}\n", " 77634 0.024 0.000 0.024 0.000 {method 'groups' of 're.Match' objects}\n", " 86183 0.024 0.000 0.024 0.000 {method 'rpartition' of 'str' objects}\n", " 106 0.000 0.000 0.023 0.000 cmd.py:1710(clear_cache)\n", " 2618 0.003 0.000 0.023 0.000 threading.py:616(set)\n", " 74460 0.021 0.000 0.021 0.000 base.py:132(__init__)\n", " 1362 0.021 0.000 0.021 0.000 warnings.py:484(__enter__)\n", " 1568 0.013 0.000 0.021 0.000 ipkernel.py:775(_clean_thread_parent_frames)\n", " 36073 0.013 0.000 0.020 0.000 posixpath.py:138(splitroot)\n", " 143118 0.020 0.000 0.020 0.000 {function _OMD.__getitem__ at 0x10fbd0ae0}\n", " 12050 0.014 0.000 0.020 0.000 threading.py:299(__enter__)\n", " 28546 0.014 0.000 0.019 0.000 util.py:42(sm_name)\n", " 3979 0.015 0.000 0.019 0.000 threading.py:277(__init__)\n", " 1362 0.019 0.000 0.019 0.000 contextlib.py:481(__init__)\n", " 104 0.000 0.000 0.018 0.000 base.py:327(__del__)\n", " 104 0.000 0.000 0.018 0.000 base.py:333(close)\n", " 1360 0.013 0.000 0.018 0.000 commit.py:796(_parse_diff)\n", " 28546 0.013 0.000 0.017 0.000 base.py:168(__ne__)\n", " 16462 0.017 0.000 0.017 0.000 util.py:191(__init__)\n", " 57092 0.017 0.000 0.017 0.000 base.py:38(__init__)\n", " 2618 0.016 0.000 0.016 0.000 threading.py:1356(_make_invoke_excepthook)\n", " 3979 0.004 0.000 0.016 0.000 threading.py:424(notify_all)\n", " 14273 0.013 0.000 0.016 0.000 util.py:1169(__new__)\n", " 1360 0.002 0.000 0.015 0.000 thread.py:165(submit)\n", " 57197 0.015 0.000 0.015 0.000 __init__.py:999(__init__)\n", " 87496 0.015 0.000 0.015 0.000 {method 'lower' of 'str' objects}\n", " 36178 0.009 0.000 0.015 0.000 pathlib.py:1164(__new__)\n", " 6810 0.014 0.000 0.014 0.000 {built-in method posix.close}\n", " 4140 0.014 0.000 0.014 0.000 {built-in method posix.pipe}\n", " 418/210 0.001 0.000 0.014 0.000 fun.py:99(find_submodule_git_dir)\n", " 24658 0.009 0.000 0.014 0.000 conf.py:52(get)\n", " 28884 0.013 0.000 0.013 0.000 {method 'sub' of 're.Pattern' objects}\n", " 4086 0.011 0.000 0.013 0.000 contextlib.py:548(_push_exit_callback)\n", " 206052 0.013 0.000 0.013 0.000 typing.py:2183(cast)\n", " 144090 0.013 0.000 0.013 0.000 config.py:435(optionxform)\n", " 1360 0.006 0.000 0.013 0.000 _base.py:428(result)\n", " 74460 0.012 0.000 0.012 0.000 cmd.py:852(__init__)\n", " 78889 0.012 0.000 0.012 0.000 {method 'readline' of '_io.BytesIO' objects}\n", " 29090 0.008 0.000 0.012 0.000 parse.py:193(_userinfo)\n", " 14545 0.005 0.000 0.012 0.000 parse.py:160(password)\n", " 2726 0.002 0.000 0.012 0.000 {built-in method builtins.next}\n", " 1307 0.012 0.000 0.012 0.000 {method 'finditer' of 're.Pattern' objects}\n", " 3992 0.004 0.000 0.011 0.000 threading.py:394(notify)\n", " 114393 0.011 0.000 0.011 0.000 codecs.py:260(__init__)\n", " 74460 0.011 0.000 0.011 0.000 cmd.py:939(__del__)\n", " 31266 0.009 0.000 0.011 0.000 util.py:789(__init__)\n", " 7948 0.011 0.000 0.011 0.000 {built-in method _thread.allocate_lock}\n", " 35964 0.008 0.000 0.011 0.000 posixpath.py:131(splitdrive)\n", " 57197 0.010 0.000 0.010 0.000 base.py:381(common_dir)\n", " 16462 0.009 0.000 0.010 0.000 mailmap.py:16(get_developer)\n", " 105 0.000 0.000 0.010 0.000 base.py:660(config_reader)\n", " 5236 0.009 0.000 0.010 0.000 threading.py:1485(current_thread)\n", " 2618 0.005 0.000 0.010 0.000 _weakrefset.py:85(add)\n", " 105 0.000 0.000 0.010 0.000 base.py:683(_config_reader)\n", " 2 0.000 0.000 0.010 0.005 repository.py:179(_prep_repo)\n", " 1363 0.001 0.000 0.009 0.000 contextlib.py:141(__exit__)\n", " 2614 0.008 0.000 0.008 0.000 threading.py:839(_newname)\n", " 1363 0.004 0.000 0.008 0.000 contextlib.py:299(helper)\n", " 14545 0.003 0.000 0.008 0.000 parse.py:156(username)\n", " 15102 0.005 0.000 0.008 0.000 commit.py:660(msg)\n", " 57092 0.008 0.000 0.008 0.000 base.py:52(type)\n", " 1360 0.001 0.000 0.008 0.000 thread.py:184(_adjust_thread_count)\n", " 1362 0.003 0.000 0.008 0.000 warnings.py:168(simplefilter)\n", " 2618 0.006 0.000 0.007 0.000 threading.py:1108(_delete)\n", " 14382 0.004 0.000 0.007 0.000 config.py:398(__del__)\n", " 14084 0.005 0.000 0.007 0.000 diff.py:531(a_path)\n", " 62532 0.007 0.000 0.007 0.000 {built-in method builtins.abs}\n", " 523 0.001 0.000 0.007 0.000 fun.py:57(is_git_dir)\n", " 57092 0.007 0.000 0.007 0.000 base.py:60(size)\n", " 36074 0.007 0.000 0.007 0.000 {method 'join' of 'str' objects}\n", " 1 0.000 0.000 0.007 0.007 base.py:758(iter_commits)\n", " 1 0.000 0.000 0.007 0.007 commit.py:299(iter_items)\n", " 2618 0.002 0.000 0.007 0.000 threading.py:1045(_set_tstate_lock)\n", " 1360 0.001 0.000 0.007 0.000 threading.py:468(acquire)\n", " 71895 0.007 0.000 0.007 0.000 {built-in method builtins.callable}\n", " 57092 0.007 0.000 0.007 0.000 base.py:42(binsha)\n", " 2932 0.004 0.000 0.007 0.000 posixpath.py:179(dirname)\n", " 1362 0.007 0.000 0.007 0.000 {built-in method posix.access}\n", " 14273 0.004 0.000 0.006 0.000 base.py:162(__eq__)\n", " 9308 0.006 0.000 0.006 0.000 {method 'release' of '_thread.lock' objects}\n", " 2 0.000 0.000 0.006 0.003 git.py:77(clear)\n", " 12050 0.004 0.000 0.006 0.000 threading.py:302(__exit__)\n", " 1363 0.002 0.000 0.006 0.000 contextlib.py:132(__enter__)\n", " 50746 0.006 0.000 0.006 0.000 util.py:198(utcoffset)\n", " 28651 0.006 0.000 0.006 0.000 {method 'keys' of 'collections.OrderedDict' objects}\n", " 14379 0.004 0.000 0.006 0.000 configparser.py:1329(__iter__)\n", " 28650 0.005 0.000 0.005 0.000 util.py:303(to_native_path_linux)\n", " 31326 0.005 0.000 0.005 0.000 {method 'endswith' of 'bytes' objects}\n", " 1360 0.001 0.000 0.005 0.000 thread.py:54(run)\n", " 57197 0.005 0.000 0.005 0.000 configparser.py:335(before_get)\n", " 26334 0.005 0.000 0.005 0.000 {method 'get' of 'dict' objects}\n", " 1360 0.001 0.000 0.005 0.000 _base.py:328(__init__)\n", " 65848 0.005 0.000 0.005 0.000 util.py:204(dst)\n", " 5493 0.002 0.000 0.005 0.000 base.py:186(hexsha)\n", " 12392 0.004 0.000 0.004 0.000 cmd.py:338(__getattribute)\n", " 42821 0.004 0.000 0.004 0.000 symbolic.py:77(__init__)\n", " 869 0.004 0.000 0.004 0.000 ChangeCounter.ipynb:145(update_changes)\n", " 1467 0.001 0.000 0.004 0.000 abc.py:117(__instancecheck__)\n", " 15739 0.004 0.000 0.004 0.000 {method 'pop' of 'list' objects}\n", " 1362 0.002 0.000 0.004 0.000 warnings.py:184(_add_filter)\n", " 784 0.004 0.000 0.004 0.000 threading.py:1535(enumerate)\n", " 1472 0.004 0.000 0.004 0.000 {built-in method posix.stat}\n", " 28754 0.004 0.000 0.004 0.000 base.py:372(working_tree_dir)\n", " 13877 0.004 0.000 0.004 0.000 threading.py:1198(ident)\n", " 14383 0.003 0.000 0.004 0.000 config.py:410(release)\n", " 3988 0.004 0.000 0.004 0.000 {method 'add' of 'set' objects}\n", " 4086 0.001 0.000 0.004 0.000 contextlib.py:477(_exit_wrapper)\n", " 6597 0.002 0.000 0.004 0.000 threading.py:314(_is_owned)\n", " 14273 0.004 0.000 0.004 0.000 fun.py:219(to_commit)\n", " 17052 0.004 0.000 0.004 0.000 {method 'strip' of 'bytes' objects}\n", " 1363 0.002 0.000 0.004 0.000 contextlib.py:104(__init__)\n", " 1467 0.004 0.000 0.004 0.000 {built-in method _abc._abc_instancecheck}\n", " 1360 0.001 0.000 0.003 0.000 conf.py:272(is_commit_filtered)\n", " 7854 0.003 0.000 0.003 0.000 threading.py:1236(daemon)\n", " 869 0.003 0.000 0.003 0.000 ChangeCounter.ipynb:137(update_size)\n", " 5441 0.003 0.000 0.003 0.000 {method '__enter__' of '_thread.RLock' objects}\n", " 1048 0.000 0.000 0.003 0.000 genericpath.py:39(isdir)\n", " 1339 0.003 0.000 0.003 0.000 parse.py:119(_coerce_args)\n", " 15633 0.003 0.000 0.003 0.000 {method 'read' of '_io.BytesIO' objects}\n", " 105 0.000 0.000 0.003 0.000 pathlib.py:1022(read_text)\n", " 2618 0.002 0.000 0.003 0.000 threading.py:1081(_stop)\n", " 1361 0.003 0.000 0.003 0.000 __init__.py:1529(info)\n", " 105 0.000 0.000 0.003 0.000 pathlib.py:1005(open)\n", " 15102 0.003 0.000 0.003 0.000 {method 'end' of 're.Match' objects}\n", " 1360 0.001 0.000 0.003 0.000 commit.py:568(author)\n", " 1361 0.001 0.000 0.003 0.000 _base.py:537(set_result)\n", " 1362 0.003 0.000 0.003 0.000 {built-in method sys.exc_info}\n", " 2618 0.002 0.000 0.003 0.000 _weakrefset.py:39(_remove)\n", " 36074 0.003 0.000 0.003 0.000 pathlib.py:569(_tail)\n", " 36075 0.003 0.000 0.003 0.000 pathlib.py:560(root)\n", " 1 0.000 0.000 0.003 0.003 git.py:39(__init__)\n", " 8085 0.003 0.000 0.003 0.000 {method 'append' of 'collections.deque' objects}\n", " 1 0.000 0.000 0.003 0.003 git.py:86(_open_repository)\n", " 1413 0.001 0.000 0.003 0.000 commit.py:669(parents)\n", " 14379 0.002 0.000 0.003 0.000 config.py:378(_acquire_lock)\n", " 14079 0.003 0.000 0.003 0.000 {method '__exit__' of '_thread.RLock' objects}\n", " 31/30 0.000 0.000 0.003 0.000 events.py:86(_run)\n", " 109 0.000 0.000 0.003 0.000 pathlib.py:447(__fspath__)\n", " 13090 0.003 0.000 0.003 0.000 {built-in method _thread.get_ident}\n", " 2614 0.001 0.000 0.003 0.000 base.py:178(__str__)\n", " 13795 0.002 0.000 0.002 0.000 {method 'start' of 're.Match' objects}\n", " 31/30 0.000 0.000 0.002 0.000 {method 'run' of '_contextvars.Context' objects}\n", " 1360 0.001 0.000 0.002 0.000 commit.py:559(hash)\n", " 2614 0.002 0.000 0.002 0.000 threading.py:1251(daemon)\n", " 15102 0.002 0.000 0.002 0.000 commit.py:155(__init__)\n", " 2618 0.002 0.000 0.002 0.000 {built-in method _thread._set_sentinel}\n", " 9539 0.002 0.000 0.002 0.000 {method 'replace' of 'str' objects}\n", " 1360 0.001 0.000 0.002 0.000 _base.py:364(cancel)\n", " 6609 0.002 0.000 0.002 0.000 {method '__enter__' of '_thread.lock' objects}\n", " 14273 0.002 0.000 0.002 0.000 util.py:1172(__init__)\n", " 1362 0.002 0.000 0.002 0.000 {method 'remove' of 'list' objects}\n", " 2722 0.001 0.000 0.002 0.000 subprocess.py:1233(poll)\n", " 14379 0.002 0.000 0.002 0.000 {built-in method builtins.iter}\n", " 3966 0.001 0.000 0.002 0.000 threading.py:311(_acquire_restore)\n", " 315 0.001 0.000 0.002 0.000 util.py:517(expand_path)\n", " 2615 0.001 0.000 0.002 0.000 cmd.py:977(__getattr__)\n", " 3966 0.001 0.000 0.002 0.000 threading.py:308(_release_save)\n", " 2615 0.001 0.000 0.002 0.000 encoding.py:1(force_bytes)\n", " 1362 0.002 0.000 0.002 0.000 {built-in method builtins.sorted}\n", " 14379 0.002 0.000 0.002 0.000 configparser.py:1170(converters)\n", " 16462 0.002 0.000 0.002 0.000 developer.py:27(__init__)\n", " 105 0.000 0.000 0.002 0.000 configparser.py:804(getboolean)\n", " 2618 0.001 0.000 0.002 0.000 threading.py:1038(_set_ident)\n", " 10716 0.002 0.000 0.002 0.000 {method '__exit__' of '_thread.lock' objects}\n", " 1418 0.001 0.000 0.001 0.000 cmd.py:294(dashify)\n", " 1360 0.001 0.000 0.001 0.000 _base.py:497(set_running_or_notify_cancel)\n", " 1362 0.001 0.000 0.001 0.000 _collections_abc.py:819(keys)\n", " 14377 0.001 0.000 0.001 0.000 base.py:390(bare)\n", " 105 0.000 0.000 0.001 0.000 configparser.py:783(_get_conv)\n", " 1361 0.001 0.000 0.001 0.000 subprocess.py:1961(_handle_exitstatus)\n", " 1362 0.001 0.000 0.001 0.000 warnings.py:505(__exit__)\n", " 1362 0.001 0.000 0.001 0.000 __init__.py:1517(debug)\n", " 105 0.000 0.000 0.001 0.000 configparser.py:780(_get)\n", " 1362 0.001 0.000 0.001 0.000 contextlib.py:564(__enter__)\n", " 3966 0.001 0.000 0.001 0.000 {method 'remove' of 'collections.deque' objects}\n", " 5283 0.001 0.000 0.001 0.000 {method 'insert' of 'list' objects}\n", " 13 0.000 0.000 0.001 0.000 iostream.py:118(_run_event_pipe_gc)\n", " 14386 0.001 0.000 0.001 0.000 config.py:764(read_only)\n", " 1361 0.001 0.000 0.001 0.000 subprocess.py:1120(__del__)\n", " 4086 0.001 0.000 0.001 0.000 {method 'pop' of 'collections.deque' objects}\n", " 1339 0.001 0.000 0.001 0.000 :1()\n", " 5462 0.001 0.000 0.001 0.000 {method 'items' of 'dict' objects}\n", " 2618 0.001 0.000 0.001 0.000 threading.py:1042(_set_native_id)\n", " 105 0.000 0.000 0.001 0.000 __init__.py:174(search)\n", " 53 0.000 0.000 0.001 0.000 subprocess.py:2208(terminate)\n", " 1362 0.001 0.000 0.001 0.000 cmd.py:1466(transform_kwargs)\n", " 2723 0.001 0.000 0.001 0.000 __init__.py:1790(isEnabledFor)\n", " 3 0.000 0.000 0.001 0.000 config.py:710(write)\n", " 1362 0.001 0.000 0.001 0.000 {method 'rfind' of 'bytes' objects}\n", " 2627 0.001 0.000 0.001 0.000 threading.py:1222(is_alive)\n", " 313 0.000 0.000 0.001 0.000 cmd.py:662(is_cygwin)\n", " 2618 0.001 0.000 0.001 0.000 {method 'discard' of 'set' objects}\n", " 5228 0.001 0.000 0.001 0.000 diff.py:235()\n", " 317 0.000 0.000 0.001 0.000 genericpath.py:27(isfile)\n", " 105 0.000 0.000 0.001 0.000 genericpath.py:16(exists)\n", " 53 0.000 0.000 0.001 0.000 subprocess.py:2176(send_signal)\n", " 4083 0.001 0.000 0.001 0.000 subprocess.py:1973(_internal_poll)\n", " 1339 0.001 0.000 0.001 0.000 {method 'lstrip' of 'str' objects}\n", " 2/1 0.000 0.000 0.001 0.001 config.py:127(flush_changes)\n", " 317 0.000 0.000 0.001 0.000 posixpath.py:408(abspath)\n", " 105 0.001 0.000 0.001 0.000 __init__.py:280(_compile)\n", " 7863 0.001 0.000 0.001 0.000 threading.py:601(is_set)\n", " 1 0.000 0.000 0.001 0.001 base.py:698(config_writer)\n", " 1339 0.001 0.000 0.001 0.000 {method 'find' of 'str' objects}\n", " 1362 0.001 0.000 0.001 0.000 warnings.py:458(__init__)\n", " 1570 0.001 0.000 0.001 0.000 {method 'rfind' of 'str' objects}\n", " 105 0.000 0.000 0.001 0.000 pathlib.py:719(__truediv__)\n", " 1362 0.001 0.000 0.001 0.000 cmd.py:749(__init__)\n", " 4 0.000 0.000 0.001 0.000 util.py:1050(_obtain_lock)\n", " 105 0.000 0.000 0.001 0.000 cmd.py:947(__init__)\n", " 4 0.000 0.000 0.001 0.000 util.py:1026(_obtain_lock_or_raise)\n", " 105 0.000 0.000 0.001 0.000 db.py:34(__init__)\n", " 26 0.000 0.000 0.001 0.000 tasks.py:653(sleep)\n", " 313 0.000 0.000 0.001 0.000 util.py:486(is_cygwin_git)\n", " 1362 0.001 0.000 0.001 0.000 subprocess.py:268(_cleanup)\n", " 1 0.000 0.000 0.001 0.001 config.py:866(set_value)\n", " 13 0.000 0.000 0.001 0.000 futures.py:313(_set_result_unless_cancelled)\n", " 105 0.000 0.000 0.001 0.000 pathlib.py:711(joinpath)\n", " 1360 0.000 0.000 0.001 0.000 git.py:140(get_commit_from_gitpython)\n", " 4086 0.001 0.000 0.001 0.000 {built-in method _warnings._filters_mutated}\n", " 527 0.000 0.000 0.001 0.000 posixpath.py:60(isabs)\n", " 1051 0.001 0.000 0.001 0.000 {built-in method posix._path_normpath}\n", " 53 0.001 0.000 0.001 0.000 {built-in method posix.kill}\n", " 3136 0.001 0.000 0.001 0.000 {method 'keys' of 'dict' objects}\n", " 1416 0.000 0.000 0.000 0.000 {method 'update' of 'dict' objects}\n", " 1365 0.000 0.000 0.000 0.000 {method 'put' of '_queue.SimpleQueue' objects}\n", " 107 0.000 0.000 0.000 0.000 pathlib.py:380(with_segments)\n", " 1360 0.000 0.000 0.000 0.000 threading.py:124(RLock)\n", " 105 0.000 0.000 0.000 0.000 _collections_abc.py:811(__contains__)\n", " 15 0.000 0.000 0.000 0.000 {method 'set_result' of '_asyncio.Future' objects}\n", " 1672 0.000 0.000 0.000 0.000 {method 'values' of 'dict' objects}\n", " 105 0.000 0.000 0.000 0.000 loose.py:77(__init__)\n", " 2618 0.000 0.000 0.000 0.000 {built-in method _thread.get_native_id}\n", " 53 0.000 0.000 0.000 0.000 {method 'close' of '_io.BufferedWriter' objects}\n", " 2614 0.000 0.000 0.000 0.000 {built-in method _thread.daemon_threads_allowed}\n", " 2638 0.000 0.000 0.000 0.000 {method 'locked' of '_thread.lock' objects}\n", " 126 0.000 0.000 0.000 0.000 {built-in method posix.getppid}\n", " 104 0.000 0.000 0.000 0.000 base.py:288(abspath)\n", " 1467 0.000 0.000 0.000 0.000 {method 'pop' of 'dict' objects}\n", " 106 0.000 0.000 0.000 0.000 base.py:633(_get_config_path)\n", " 3 0.000 0.000 0.000 0.000 config.py:664(_write)\n", " 104 0.000 0.000 0.000 0.000 mman.py:408(collect)\n", " 2 0.000 0.000 0.000 0.000 zmqstream.py:583(_handle_events)\n", " 2724 0.000 0.000 0.000 0.000 subprocess.py:1311(_on_error_fd_closer)\n", " 315 0.000 0.000 0.000 0.000 posixpath.py:256(expanduser)\n", " 1361 0.000 0.000 0.000 0.000 {built-in method posix.waitstatus_to_exitcode}\n", " 13 0.000 0.000 0.000 0.000 iostream.py:127(_event_pipe_gc)\n", " 1361 0.000 0.000 0.000 0.000 {built-in method posix.WIFSTOPPED}\n", " 45 0.000 0.000 0.000 0.000 config.py:668(write_section)\n", " 2753 0.000 0.000 0.000 0.000 {built-in method time.monotonic}\n", " 1360 0.000 0.000 0.000 0.000 _base.py:398(__get_result)\n", " 15 0.000 0.000 0.000 0.000 base_events.py:784(call_soon)\n", " 13 0.000 0.000 0.000 0.000 base_events.py:742(call_later)\n", " 1 0.000 0.000 0.000 0.000 asyncio.py:200(_handle_events)\n", " 313 0.000 0.000 0.000 0.000 util.py:455(_is_cygwin_git)\n", " 105 0.000 0.000 0.000 0.000 base.py:113(__init__)\n", " 1362 0.000 0.000 0.000 0.000 {built-in method sys.audit}\n", " 1364 0.000 0.000 0.000 0.000 {method 'get_nowait' of '_queue.SimpleQueue' objects}\n", " 13 0.000 0.000 0.000 0.000 base_events.py:766(call_at)\n", " 104 0.000 0.000 0.000 0.000 mman.py:303(_collect_lru_region)\n", " 2/1 0.000 0.000 0.000 0.000 ioloop.py:742(_run_callback)\n", " 315 0.000 0.000 0.000 0.000 posixpath.py:320(expandvars)\n", " 2 0.000 0.000 0.000 0.000 zmqstream.py:624(_handle_recv)\n", " 1307 0.000 0.000 0.000 0.000 diff.py:172(_process_diff_args)\n", " 1339 0.000 0.000 0.000 0.000 parse.py:421(_checknetloc)\n", " 1362 0.000 0.000 0.000 0.000 _collections_abc.py:845(__init__)\n", " 58 0.000 0.000 0.000 0.000 cmd.py:1450(transform_kwarg)\n", " 1361 0.000 0.000 0.000 0.000 _base.py:337(_invoke_callbacks)\n", " 105 0.000 0.000 0.000 0.000 configparser.py:1142(_convert_to_boolean)\n", " 16 0.000 0.000 0.000 0.000 base_events.py:813(_call_soon)\n", " 2 0.000 0.000 0.000 0.000 zmqstream.py:556(_run_callback)\n", " 2 0.000 0.000 0.000 0.000 iostream.py:157(_handle_event)\n", " 2 0.000 0.000 0.000 0.000 iostream.py:276()\n", " 2 0.000 0.000 0.000 0.000 iostream.py:278(_really_send)\n", " 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\n", " 1360 0.000 0.000 0.000 0.000 thread.py:48(__init__)\n", " 104 0.000 0.000 0.000 0.000 base.py:351(__ne__)\n", " 2 0.000 0.000 0.000 0.000 socket.py:703(send_multipart)\n", " 943 0.000 0.000 0.000 0.000 {built-in method _stat.S_ISDIR}\n", " 1360 0.000 0.000 0.000 0.000 commit.py:536(__init__)\n", " 1339 0.000 0.000 0.000 0.000 parse.py:108(_noop)\n", " 5 0.000 0.000 0.000 0.000 attrsettr.py:43(__getattr__)\n", " 13 0.000 0.000 0.000 0.000 events.py:155(cancel)\n", " 1361 0.000 0.000 0.000 0.000 {method '_is_owned' of '_thread.RLock' objects}\n", " 3 0.000 0.000 0.000 0.000 zmqstream.py:663(_rebuild_io_state)\n", " 29 0.000 0.000 0.000 0.000 events.py:36(__init__)\n", " 1 0.000 0.000 0.000 0.000 git.py:92(_discover_main_branch)\n", " 57 0.000 0.000 0.000 0.000 base_events.py:733(time)\n", " 1 0.000 0.000 0.000 0.000 base.py:1041(active_branch)\n", " 5 0.000 0.000 0.000 0.000 attrsettr.py:66(_get_attr_opt)\n", " 869 0.000 0.000 0.000 0.000 ChangeCounter.ipynb:155(update_elems)\n", " 1 0.000 0.000 0.000 0.000 zmqstream.py:694()\n", " 1 0.000 0.000 0.000 0.000 symbolic.py:402(_get_reference)\n", " 3 0.000 0.000 0.000 0.000 zmqstream.py:686(_update_handler)\n", " 13 0.000 0.000 0.000 0.000 events.py:111(__init__)\n", " 45 0.000 0.000 0.000 0.000 config.py:242(items_all)\n", " 13 0.000 0.000 0.000 0.000 base_events.py:446(create_future)\n", " 88 0.000 0.000 0.000 0.000 config.py:861(_value_to_string)\n", " 2 0.000 0.000 0.000 0.000 pathlib.py:1228(resolve)\n", " 2 0.000 0.000 0.000 0.000 util.py:1057(_release_lock)\n", " 1 0.000 0.000 0.000 0.000 kernelbase.py:324(_flush)\n", " 1 0.000 0.000 0.000 0.000 util.py:245(rmfile)\n", " 2 0.000 0.000 0.000 0.000 posixpath.py:423(realpath)\n", " 8 0.000 0.000 0.000 0.000 {built-in method posix.lstat}\n", " 132 0.000 0.000 0.000 0.000 config.py:235(getall)\n", " 16 0.000 0.000 0.000 0.000 enum.py:1545(__or__)\n", " 104 0.000 0.000 0.000 0.000 base.py:346(__eq__)\n", " 1 0.000 0.000 0.000 0.000 {built-in method posix.remove}\n", " 43 0.000 0.000 0.000 0.000 {built-in method builtins.max}\n", " 2 0.000 0.000 0.000 0.000 posixpath.py:432(_joinrealpath)\n", " 1 0.000 0.000 0.000 0.000 conf.py:85(sanity_check_filters)\n", " 72 0.000 0.000 0.000 0.000 enum.py:1538(_get_value)\n", " 14 0.000 0.000 0.000 0.000 socket.py:626(send)\n", " 1 0.000 0.000 0.000 0.000 zmqstream.py:427(flush)\n", " 13 0.000 0.000 0.000 0.000 threading.py:515(release)\n", " 1 0.000 0.000 0.000 0.000 kernelbase.py:302(poll_control_queue)\n", " 8 0.000 0.000 0.000 0.000 enum.py:1556(__and__)\n", " 210 0.000 0.000 0.000 0.000 {built-in method _io.text_encoding}\n", " 8 0.000 0.000 0.000 0.000 threading.py:857(_maintain_shutdown_locks)\n", " 211 0.000 0.000 0.000 0.000 {built-in method _stat.S_ISREG}\n", " 59 0.000 0.000 0.000 0.000 {method 'find' of 'bytes' objects}\n", " 1 0.000 0.000 0.000 0.000 selector_events.py:129(_read_from_self)\n", " 3 0.000 0.000 0.000 0.000 config.py:238(items)\n", " 2 0.000 0.000 0.000 0.000 pathlib.py:1398(expanduser)\n", " 13 0.000 0.000 0.000 0.000 events.py:72(cancel)\n", " 30 0.000 0.000 0.000 0.000 selector_events.py:750(_process_events)\n", " 1 0.000 0.000 0.000 0.000 conf.py:302(_check_timezones)\n", " 88 0.000 0.000 0.000 0.000 encoding.py:11(force_text)\n", " 13 0.000 0.000 0.000 0.000 {built-in method _heapq.heappop}\n", " 1 0.000 0.000 0.000 0.000 symbolic.py:879(from_path)\n", " 1 0.000 0.000 0.000 0.000 conf.py:310(_replace_timezone)\n", " 1 0.000 0.000 0.000 0.000 repository.py:44(__init__)\n", " 31 0.000 0.000 0.000 0.000 enum.py:720(__call__)\n", " 59 0.000 0.000 0.000 0.000 {method 'rstrip' of 'bytes' objects}\n", " 2 0.000 0.000 0.000 0.000 socket.py:774(recv_multipart)\n", " 2 0.000 0.000 0.000 0.000 pathlib.py:835(stat)\n", " 107 0.000 0.000 0.000 0.000 {built-in method builtins.issubclass}\n", " 1 0.000 0.000 0.000 0.000 thread.py:127(__init__)\n", " 2 0.000 0.000 0.000 0.000 {method 'recv' of '_socket.socket' objects}\n", " 4 0.000 0.000 0.000 0.000 weakref.py:369(remove)\n", " 1 0.000 0.000 0.000 0.000 queues.py:186(put)\n", " 105 0.000 0.000 0.000 0.000 base.py:70(__init__)\n", " 1 0.000 0.000 0.000 0.000 queues.py:209(put_nowait)\n", " 1 0.000 0.000 0.000 0.000 conf.py:26(__init__)\n", " 1 0.000 0.000 0.000 0.000 asyncio.py:225(add_callback)\n", " 1 0.000 0.000 0.000 0.000 futures.py:396(_call_set_state)\n", " 1 0.000 0.000 0.000 0.000 conf.py:202(build_args)\n", " 2 0.000 0.000 0.000 0.000 repository.py:154(_is_remote)\n", " 13 0.000 0.000 0.000 0.000 {built-in method _heapq.heappush}\n", " 1 0.000 0.000 0.000 0.000 zmqstream.py:468(update_flag)\n", " 15 0.000 0.000 0.000 0.000 {built-in method _contextvars.copy_context}\n", " 4 0.000 0.000 0.000 0.000 zmqstream.py:542(sending)\n", " 2 0.000 0.000 0.000 0.000 typing.py:1221(__instancecheck__)\n", " 1 0.000 0.000 0.000 0.000 base_events.py:837(call_soon_threadsafe)\n", " 15 0.000 0.000 0.000 0.000 {method 'cancelled' of '_asyncio.Future' objects}\n", " 35 0.000 0.000 0.000 0.000 {method 'popleft' of 'collections.deque' objects}\n", " 31 0.000 0.000 0.000 0.000 enum.py:1123(__new__)\n", " 4 0.000 0.000 0.000 0.000 queue.py:97(empty)\n", " 2 0.000 0.000 0.000 0.000 traitlets.py:676(__get__)\n", " 1 0.000 0.000 0.000 0.000 {method 'replace' of 'datetime.datetime' objects}\n", " 1 0.000 0.000 0.000 0.000 queues.py:225(get)\n", " 2 0.000 0.000 0.000 0.000 typing.py:1492(__subclasscheck__)\n", " 14 0.000 0.000 0.000 0.000 {built-in method builtins.min}\n", " 14 0.000 0.000 0.000 0.000 {built-in method _asyncio.get_running_loop}\n", " 1 0.000 0.000 0.000 0.000 concurrent.py:182(future_set_result_unless_cancelled)\n", " 57 0.000 0.000 0.000 0.000 base_events.py:2010(get_debug)\n", " 1 0.000 0.000 0.000 0.000 threading.py:457(__init__)\n", " 8 0.000 0.000 0.000 0.000 {method 'difference_update' of 'set' objects}\n", " 1 0.000 0.000 0.000 0.000 git.py:343(__del__)\n", " 1 0.000 0.000 0.000 0.000 selector_events.py:141(_write_to_self)\n", " 1 0.000 0.000 0.000 0.000 __init__.py:230(utcoffset)\n", " 1 0.000 0.000 0.000 0.000 poll.py:80(poll)\n", " 4 0.000 0.000 0.000 0.000 weakref.py:427(__setitem__)\n", " 28/1 1.717 0.061 0.000 0.000 {method 'control' of 'select.kqueue' objects}\n", " 1 0.000 0.000 0.000 0.000 conf.py:72(_check_only_one_from_commit)\n", " 1 0.000 0.000 0.000 0.000 configparser.py:869(set)\n", " 1 0.000 0.000 0.000 0.000 {method 'send' of '_socket.socket' objects}\n", " 29 0.000 0.000 0.000 0.000 base_events.py:538(_check_closed)\n", " 1 0.000 0.000 0.000 0.000 reference.py:54(__init__)\n", " 4 0.000 0.000 0.000 0.000 typing.py:1285(__hash__)\n", " 8 0.000 0.000 0.000 0.000 {method 'partition' of 'str' objects}\n", " 1 0.000 0.000 0.000 0.000 conf.py:79(_check_only_one_to_commit)\n", " 2 0.000 0.000 0.000 0.000 queues.py:322(_consume_expired)\n", " 2 0.000 0.000 0.000 0.000 base_events.py:1900(_add_callback)\n", " 8 0.000 0.000 0.000 0.000 conf.py:43(set_value)\n", " 1 0.000 0.000 0.000 0.000 util.py:1009(__del__)\n", " 2 0.000 0.000 0.000 0.000 abc.py:121(__subclasscheck__)\n", " 2 0.000 0.000 0.000 0.000 iostream.py:216(_check_mp_mode)\n", " 1 0.000 0.000 0.000 0.000 queues.py:256(get_nowait)\n", " 1 0.000 0.000 0.000 0.000 reference.py:120(name)\n", " 13 0.000 0.000 0.000 0.000 base_events.py:1910(_timer_handle_cancelled)\n", " 1 0.000 0.000 0.000 0.000 queues.py:317(__put_internal)\n", " 2 0.000 0.000 0.000 0.000 traitlets.py:629(get)\n", " 3 0.000 0.000 0.000 0.000 config.py:756(_assure_writable)\n", " 2 0.000 0.000 0.000 0.000 iostream.py:213(_is_master_process)\n", " 1 0.000 0.000 0.000 0.000 {method 'reverse' of 'list' objects}\n", " 8 0.000 0.000 0.000 0.000 {built-in method _stat.S_ISLNK}\n", " 4 0.000 0.000 0.000 0.000 queue.py:209(_qsize)\n", " 1 0.000 0.000 0.000 0.000 conf.py:61(_sanity_check_repos)\n", " 2 0.000 0.000 0.000 0.000 conf.py:192(only_one_filter)\n", " 5 0.000 0.000 0.000 0.000 {method 'upper' of 'str' objects}\n", " 2 0.000 0.000 0.000 0.000 util.py:1012(_lock_file_path)\n", " 2 0.000 0.000 0.000 0.000 {built-in method _abc._abc_subclasscheck}\n", " 1 0.000 0.000 0.000 0.000 conf.py:151(get_starting_commit)\n", " 1 0.000 0.000 0.000 0.000 conf.py:175(get_ending_commit)\n", " 1 0.000 0.000 0.000 0.000 conf.py:123(_check_correct_filters_order)\n", " 8 0.000 0.000 0.000 0.000 util.py:1016(_has_lock)\n", " 4 0.000 0.000 0.000 0.000 {built-in method builtins.hash}\n", " 5 0.000 0.000 0.000 0.000 zmqstream.py:538(receiving)\n", " 1 0.000 0.000 0.000 0.000 queues.py:312(_put)\n", " 3 0.000 0.000 0.000 0.000 git.py:63(repo)\n", " 1 0.000 0.000 0.000 0.000 queues.py:173(qsize)\n", " 2 0.000 0.000 0.000 0.000 selectors.py:275(_key_from_fd)\n", " 1 0.000 0.000 0.000 0.000 poll.py:31(register)\n", " 1 0.000 0.000 0.000 0.000 pathlib.py:583(name)\n", " 1 0.000 0.000 0.000 0.000 queues.py:309(_get)\n", " 1 0.000 0.000 0.000 0.000 unix_events.py:81(_process_self_data)\n", " 1 0.000 0.000 0.000 0.000 util.py:1005(__init__)\n", " 2 0.000 0.000 0.000 0.000 {built-in method posix.getpid}\n", " 1 0.000 0.000 0.000 0.000 configparser.py:649(has_section)\n", " 2 0.000 0.000 0.000 0.000 iostream.py:255(closed)\n", " 1 0.000 0.000 0.000 0.000 {method 'isalpha' of 'str' objects}\n", " 1 0.000 0.000 0.000 0.000 queues.py:177(empty)\n", " 1 0.000 0.000 0.000 0.000 codecs.py:186(__init__)\n", " 1 0.000 0.000 0.000 0.000 {method 'isascii' of 'str' objects}\n", " 1 0.000 0.000 0.000 0.000 {method 'done' of '_asyncio.Future' objects}\n", " 1 0.000 0.000 0.000 0.000 base_events.py:719(is_closed)\n", " 1 0.000 0.000 0.000 0.000 _base.py:643(__enter__)\n", " 1 0.000 0.000 0.000 0.000 zmqstream.py:659(_check_closed)\n", " 1 0.000 0.000 0.000 0.000 queues.py:59(_set_timeout)\n", " 1 0.000 0.000 0.000 0.000 configparser.py:338(before_set)\n", " 1 0.000 0.000 0.000 0.000 locks.py:224(clear)\n", "\n", "\n" ] } ], "source": [ "cProfile.run('debuggingbook_change_counter(ChangeCounter)', sort='cumulative')" ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "Yes, that's an awful lot of functions, but we can quickly narrow things down. The `cumtime` column is sorted by largest values first. We see that the `debuggingbook_change_counter()` method at the top takes up all the time – but this is not surprising, since it is the method we called in the first place. This calls a method `mine()` in the `ChangeCounter` class, which does all the work." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The next places are more interesting: almost all time is spent in a single method, named `modifications()`. This method determines the difference between two versions, which is an expensive operation; this is also supported by the observation that half of the time is spent in a `diff()` method." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "This profile thus already gets us a hint on how to improve performance: Rather than computing the diff between versions for _every_ version, we could do so _on demand_ (and possibly cache results so we don't have to compute them twice). Alas, this (slow) functionality is part of the \n", "underlying [PyDriller](https://pydriller.readthedocs.io/) Python package, so we cannot fix this within the `ChangeCounter` class. But we could file a bug with the developers, suggesting a patch to improve performance." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "### Sampling Execution Profiles\n", "\n", "Instrumenting code is _precise_, but it is also _slow_. An alternate way to measure performance is to _sample_ in regular intervals which functions are currently active – for instance, by examining the current function call stack. The more frequently a function is sampled as active, the more time is spent in that function." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "One profiler for Python that implements such sampling is [Scalene](https://github.com/plasma-umass/scalene) – a high-performance, high-precision CPU, GPU, and memory profiler for Python. We can invoke it on our example as follows:\n", "\n", "```sh\n", "$ scalene --html test.py > scalene-out.html\n", "```" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "where `test.py` is a script that again invokes\n", "\n", "```python\n", "debuggingbook_change_counter(ChangeCounter)\n", "```" ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The output of `scalene` is sent to a HTML file (here, `scalene-out.html`) which is organized by _lines_ – that is, for each line, we see how much it contributed to overall execution time. Opening the output `scalene-out.html` in a HTML browser, we see these lines:" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "![](PICS/scalene-out.png)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "As with `cProfile`, above, we identify the `mine()` method in the `ChangeCounter` class as the main performance hog – and in the `mine()` method, it is the iteration over all modifications that takes all the time. Adding the option `--profile-all` to `scalene` would extend the profile to all executed code, including the `pydriller` third-party library." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Besides relying on sampling rather that tracing (which is more efficient) and breaking down execution time by line, `scalene` also provides additional information on memory usage and more. If `cProfile` is not sufficient, then `scalene` will bring profiling to the next level." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Improving Performance" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Identifying a culprit is not always that easy. Notably, when the first set of obvious performance hogs is fixed, it becomes more and more difficult to squeeze out additional performance – and, as stated above, such optimization may be in conflict with readability and maintainability of your code. Here are some simple ways to improve performance:" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "* **Efficient algorithms**. For many tasks, the simplest algorithm is not always the best performing one. Consider alternatives that may be more efficient, and _measure_ whether they pay off.\n", "\n", "* **Efficient data types**. Remember that certain operations, such as looking up whether an element is contained, may take different amounts of time depending on the data structure. In Python, a query like `x in xs` takes (mostly) constant time if `xs` is a set, but linear time if `xs` is a list; these differences become significant as the size of `xs` grows.\n", "\n", "* **Efficient modules**. In Python, most frequently used modules (or at least parts of) are implemented in C, which is way more efficient than plain Python. Rely on existing modules whenever possible. Or implement your own, _after_ having measured that this may pay off." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "These are all things you can already use during programming – and also set up your code such that exchanging, say, one data type by another will still be possible later. This is best achieved by hiding implementation details (such as the used data types) behind an abstract interface used by your clients." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "But beyond these points, remember the famous words by [Donald E. Knuth](https://en.wikipedia.org/wiki/Donald_Knuth):" ] }, { "cell_type": "code", "execution_count": 10, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.569738Z", "iopub.status.busy": "2025-01-20T09:41:00.569582Z", "iopub.status.idle": "2025-01-20T09:41:00.571778Z", "shell.execute_reply": "2025-01-20T09:41:00.571495Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from bookutils import quiz" ] }, { "cell_type": "code", "execution_count": 11, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.573039Z", "iopub.status.busy": "2025-01-20T09:41:00.572940Z", "iopub.status.idle": "2025-01-20T09:41:00.577772Z", "shell.execute_reply": "2025-01-20T09:41:00.577543Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/html": [ "\n", " \n", " \n", " \n", "
\n", "

Quiz

\n", "

\n", "

Donald E. Knuth said: \"Premature optimization...\"
\n", "

\n", "

\n", "

\n", " \n", " \n", "
\n", " \n", " \n", "
\n", " \n", " \n", "
\n", " \n", " \n", "
\n", " \n", "
\n", "

\n", " \n", " \n", "
\n", " " ], "text/plain": [ "" ] }, "execution_count": 11, "metadata": {}, "output_type": "execute_result" } ], "source": [ "quiz('Donald E. Knuth said: \"Premature optimization...\"',\n", " [\n", " \"... is the root of all evil\",\n", " \"... requires lots of experience\",\n", " \"... should be left to assembly programmers\",\n", " \"... is the reason why TeX is so fast\",\n", " ], 'len(\"METAFONT\") - len(\"TeX\") - len(\"CWEB\")')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "This quote should always remind us that after a good design, you should always _first_ measure and _then_ optimize." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Building a Profiler\n", "\n", "Having discussed profilers from a _user_ perspective, let us now dive into how they are actually implemented. It turns out we can use most of our existing infrastructure to implement a simple tracing profiler with only a few lines of code." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The program we will apply our profiler on is – surprise! – our ongoing example, `remove_html_markup()`. Our aim is to understand how much time is spent _in each line of the code_ (such that we have a new feature on top of Python `cProfile`)." ] }, { "cell_type": "code", "execution_count": 12, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.579136Z", "iopub.status.busy": "2025-01-20T09:41:00.579051Z", "iopub.status.idle": "2025-01-20T09:41:00.580666Z", "shell.execute_reply": "2025-01-20T09:41:00.580457Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from Intro_Debugging import remove_html_markup" ] }, { "cell_type": "code", "execution_count": 13, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.581784Z", "iopub.status.busy": "2025-01-20T09:41:00.581702Z", "iopub.status.idle": "2025-01-20T09:41:00.583429Z", "shell.execute_reply": "2025-01-20T09:41:00.583131Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "# ignore\n", "from typing import Any, Optional, Type, Dict, Tuple, List" ] }, { "cell_type": "code", "execution_count": 14, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.584556Z", "iopub.status.busy": "2025-01-20T09:41:00.584475Z", "iopub.status.idle": "2025-01-20T09:41:00.585949Z", "shell.execute_reply": "2025-01-20T09:41:00.585741Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "# ignore\n", "from bookutils import print_content" ] }, { "cell_type": "code", "execution_count": 15, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.587258Z", "iopub.status.busy": "2025-01-20T09:41:00.587160Z", "iopub.status.idle": "2025-01-20T09:41:00.588632Z", "shell.execute_reply": "2025-01-20T09:41:00.588425Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "# ignore\n", "import inspect" ] }, { "cell_type": "code", "execution_count": 16, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.589816Z", "iopub.status.busy": "2025-01-20T09:41:00.589743Z", "iopub.status.idle": "2025-01-20T09:41:00.668650Z", "shell.execute_reply": "2025-01-20T09:41:00.668403Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "238 \u001b[34mdef\u001b[39;49;00m \u001b[32mremove_html_markup\u001b[39;49;00m(s): \u001b[37m# type: ignore\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "239 tag = \u001b[34mFalse\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "240 quote = \u001b[34mFalse\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "241 out = \u001b[33m\"\u001b[39;49;00m\u001b[33m\"\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "242 \u001b[37m\u001b[39;49;00m\n", "243 \u001b[34mfor\u001b[39;49;00m c \u001b[35min\u001b[39;49;00m s:\u001b[37m\u001b[39;49;00m\n", "244 \u001b[34massert\u001b[39;49;00m tag \u001b[35mor\u001b[39;49;00m \u001b[35mnot\u001b[39;49;00m quote\u001b[37m\u001b[39;49;00m\n", "245 \u001b[37m\u001b[39;49;00m\n", "246 \u001b[34mif\u001b[39;49;00m c == \u001b[33m'\u001b[39;49;00m\u001b[33m<\u001b[39;49;00m\u001b[33m'\u001b[39;49;00m \u001b[35mand\u001b[39;49;00m \u001b[35mnot\u001b[39;49;00m quote:\u001b[37m\u001b[39;49;00m\n", "247 tag = \u001b[34mTrue\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "248 \u001b[34melif\u001b[39;49;00m c == \u001b[33m'\u001b[39;49;00m\u001b[33m>\u001b[39;49;00m\u001b[33m'\u001b[39;49;00m \u001b[35mand\u001b[39;49;00m \u001b[35mnot\u001b[39;49;00m quote:\u001b[37m\u001b[39;49;00m\n", "249 tag = \u001b[34mFalse\u001b[39;49;00m\u001b[37m\u001b[39;49;00m\n", "250 \u001b[34melif\u001b[39;49;00m (c == \u001b[33m'\u001b[39;49;00m\u001b[33m\"\u001b[39;49;00m\u001b[33m'\u001b[39;49;00m \u001b[35mor\u001b[39;49;00m c == \u001b[33m\"\u001b[39;49;00m\u001b[33m'\u001b[39;49;00m\u001b[33m\"\u001b[39;49;00m) \u001b[35mand\u001b[39;49;00m tag:\u001b[37m\u001b[39;49;00m\n", "251 quote = \u001b[35mnot\u001b[39;49;00m quote\u001b[37m\u001b[39;49;00m\n", "252 \u001b[34melif\u001b[39;49;00m \u001b[35mnot\u001b[39;49;00m tag:\u001b[37m\u001b[39;49;00m\n", "253 out = out + c\u001b[37m\u001b[39;49;00m\n", "254 \u001b[37m\u001b[39;49;00m\n", "255 \u001b[34mreturn\u001b[39;49;00m out\u001b[37m\u001b[39;49;00m" ] } ], "source": [ "print_content(inspect.getsource(remove_html_markup), '.py',\n", " start_line_number=238)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "We introduce a class `PerformanceTracer` that tracks, for each line in the code:\n", "\n", "* how _often_ it was executed (`hits`), and\n", "* _how much time_ was spent during its execution (`time`).\n", "\n", "To this end, we make use of our `Timer` class, which measures time, and the `Tracer` class from [the chapter on tracing](Tracer.ipynb), which allows us to track every line of the program as it is being executed." ] }, { "cell_type": "code", "execution_count": 17, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.670044Z", "iopub.status.busy": "2025-01-20T09:41:00.669947Z", "iopub.status.idle": "2025-01-20T09:41:00.671598Z", "shell.execute_reply": "2025-01-20T09:41:00.671388Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from Tracer import Tracer" ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "In `PerformanceTracker`, the attributes `hits` and `time` are mappings indexed by unique locations – that is, pairs of function name and line number." ] }, { "cell_type": "code", "execution_count": 18, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.672766Z", "iopub.status.busy": "2025-01-20T09:41:00.672674Z", "iopub.status.idle": "2025-01-20T09:41:00.674177Z", "shell.execute_reply": "2025-01-20T09:41:00.673940Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "Location = Tuple[str, int]" ] }, { "cell_type": "code", "execution_count": 19, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.675321Z", "iopub.status.busy": "2025-01-20T09:41:00.675236Z", "iopub.status.idle": "2025-01-20T09:41:00.677217Z", "shell.execute_reply": "2025-01-20T09:41:00.676983Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class PerformanceTracer(Tracer):\n", " \"\"\"Trace time and #hits for individual program lines\"\"\"\n", "\n", " def __init__(self) -> None:\n", " \"\"\"Constructor.\"\"\"\n", " super().__init__()\n", " self.reset_timer()\n", " self.hits: Dict[Location, int] = {}\n", " self.time: Dict[Location, float] = {}\n", "\n", " def reset_timer(self) -> None:\n", " self.timer = Timer.Timer()" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "As common in this book, we want to use `PerformanceTracer` in a `with`-block around the function call(s) to be tracked:\n", "\n", "```python\n", "with PerformanceTracer() as perf_tracer:\n", " function(...)\n", "```" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "When entering the `with` block (`__enter__()`), we reset all timers. Also, coming from the `__enter__()` method of the superclass `Tracer`, we enable tracing through the `traceit()` method." ] }, { "cell_type": "code", "execution_count": 20, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.678463Z", "iopub.status.busy": "2025-01-20T09:41:00.678385Z", "iopub.status.idle": "2025-01-20T09:41:00.679891Z", "shell.execute_reply": "2025-01-20T09:41:00.679677Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from types import FrameType" ] }, { "cell_type": "code", "execution_count": 21, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.681034Z", "iopub.status.busy": "2025-01-20T09:41:00.680937Z", "iopub.status.idle": "2025-01-20T09:41:00.682731Z", "shell.execute_reply": "2025-01-20T09:41:00.682404Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class PerformanceTracer(PerformanceTracer):\n", " def __enter__(self) -> Any:\n", " \"\"\"Enter a `with` block.\"\"\"\n", " super().__enter__()\n", " self.reset_timer()\n", " return self" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The `traceit()` method extracts the current location. It increases the corresponding `hits` value by 1, and adds the elapsed time to the corresponding `time`." ] }, { "cell_type": "code", "execution_count": 22, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.684539Z", "iopub.status.busy": "2025-01-20T09:41:00.684418Z", "iopub.status.idle": "2025-01-20T09:41:00.686668Z", "shell.execute_reply": "2025-01-20T09:41:00.686438Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class PerformanceTracer(PerformanceTracer):\n", " def traceit(self, frame: FrameType, event: str, arg: Any) -> None:\n", " \"\"\"Tracing function; called for every line.\"\"\"\n", " t = self.timer.elapsed_time()\n", " location = (frame.f_code.co_name, frame.f_lineno)\n", "\n", " self.hits.setdefault(location, 0)\n", " self.time.setdefault(location, 0.0)\n", " self.hits[location] += 1\n", " self.time[location] += t\n", "\n", " self.reset_timer()" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "This is it already. We can now determine where most time is spent in `remove_html_markup()`. We invoke it 10,000 times such that we can average over runs:" ] }, { "cell_type": "code", "execution_count": 23, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:00.687937Z", "iopub.status.busy": "2025-01-20T09:41:00.687834Z", "iopub.status.idle": "2025-01-20T09:41:01.487676Z", "shell.execute_reply": "2025-01-20T09:41:01.487377Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "with PerformanceTracer() as perf_tracer:\n", " for i in range(10000):\n", " s = remove_html_markup('foo')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Here are the hits. For every line executed, we see how often it was executed. The most executed line is the `for` loop with 110,000 hits – once for each of the 10 characters in `foo`, once for the final check, and all of this 10,000 times." ] }, { "cell_type": "code", "execution_count": 24, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.489345Z", "iopub.status.busy": "2025-01-20T09:41:01.489253Z", "iopub.status.idle": "2025-01-20T09:41:01.491800Z", "shell.execute_reply": "2025-01-20T09:41:01.491574Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "data": { "text/plain": [ "{('__init__', 17): 1,\n", " ('__init__', 19): 1,\n", " ('clock', 8): 1,\n", " ('clock', 12): 2,\n", " ('__init__', 20): 2,\n", " ('remove_html_markup', 238): 10000,\n", " ('remove_html_markup', 239): 10000,\n", " ('remove_html_markup', 240): 10000,\n", " ('remove_html_markup', 241): 10000,\n", " ('remove_html_markup', 243): 110000,\n", " ('remove_html_markup', 244): 100000,\n", " ('remove_html_markup', 246): 100000,\n", " ('remove_html_markup', 247): 20000,\n", " ('remove_html_markup', 248): 80000,\n", " ('remove_html_markup', 250): 60000,\n", " ('remove_html_markup', 252): 60000,\n", " ('remove_html_markup', 249): 20000,\n", " ('remove_html_markup', 253): 30000,\n", " ('remove_html_markup', 255): 20000}" ] }, "execution_count": 24, "metadata": {}, "output_type": "execute_result" } ], "source": [ "perf_tracer.hits" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The `time` attribute collects how much time was spent in each line. Within the loop, again, the `for` statement takes the most time. The other lines show some variability, though." ] }, { "cell_type": "code", "execution_count": 25, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.492945Z", "iopub.status.busy": "2025-01-20T09:41:01.492867Z", "iopub.status.idle": "2025-01-20T09:41:01.495229Z", "shell.execute_reply": "2025-01-20T09:41:01.495001Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "data": { "text/plain": [ "{('__init__', 17): 0.00020849995780736208,\n", " ('__init__', 19): 1.374981366097927e-06,\n", " ('clock', 8): 1.2080417945981026e-06,\n", " ('clock', 12): 1.5009427443146706e-06,\n", " ('__init__', 20): 1.5830155462026596e-06,\n", " ('remove_html_markup', 238): 0.012197923264466226,\n", " ('remove_html_markup', 239): 0.013060983153991401,\n", " ('remove_html_markup', 240): 0.012579386122524738,\n", " ('remove_html_markup', 241): 0.011003078776411712,\n", " ('remove_html_markup', 243): 0.07900447177235037,\n", " ('remove_html_markup', 244): 0.07023449544794858,\n", " ('remove_html_markup', 246): 0.06870396924205124,\n", " ('remove_html_markup', 247): 0.014365122187882662,\n", " ('remove_html_markup', 248): 0.05404824938159436,\n", " ('remove_html_markup', 250): 0.04095112928189337,\n", " ('remove_html_markup', 252): 0.04195001139305532,\n", " ('remove_html_markup', 249): 0.013921678997576237,\n", " ('remove_html_markup', 253): 0.020369785837829113,\n", " ('remove_html_markup', 255): 0.013756285421550274}" ] }, "execution_count": 25, "metadata": {}, "output_type": "execute_result" } ], "source": [ "perf_tracer.time" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "For a full profiler, these numbers would now be sorted and printed in a table, much like `cProfile` does. However, we will borrow some material from previous chapters and annotate our code accordingly." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Visualizing Performance Metrics\n", "\n", "In the [chapter on statistical debugging](StatisticalDebugger.ipynb), we have encountered the `CoverageCollector` class, which collects line and function coverage during execution, using a `collect()` method that is invoked for every line. We will repurpose this class to collect arbitrary _metrics_ on the lines executed, notably time taken." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "### Collecting Time Spent" ] }, { "cell_type": "code", "execution_count": 26, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.496536Z", "iopub.status.busy": "2025-01-20T09:41:01.496453Z", "iopub.status.idle": "2025-01-20T09:41:01.498024Z", "shell.execute_reply": "2025-01-20T09:41:01.497811Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "from StatisticalDebugger import CoverageCollector, SpectrumDebugger" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The `MetricCollector` class is an abstract superclass that provides an interface to access a particular metric." ] }, { "cell_type": "code", "execution_count": 27, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.499236Z", "iopub.status.busy": "2025-01-20T09:41:01.499165Z", "iopub.status.idle": "2025-01-20T09:41:01.501160Z", "shell.execute_reply": "2025-01-20T09:41:01.500951Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "class MetricCollector(CoverageCollector):\n", " \"\"\"Abstract superclass for collecting line-specific metrics\"\"\"\n", "\n", " def metric(self, event: Any) -> Optional[float]:\n", " \"\"\"Return a metric for an event, or none.\"\"\"\n", " return None\n", "\n", " def all_metrics(self, func: str) -> List[float]:\n", " \"\"\"Return all metric for a function `func`.\"\"\"\n", " return []" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Given these metrics, we can also compute sums and maxima for a single function." ] }, { "cell_type": "code", "execution_count": 28, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.502278Z", "iopub.status.busy": "2025-01-20T09:41:01.502202Z", "iopub.status.idle": "2025-01-20T09:41:01.504093Z", "shell.execute_reply": "2025-01-20T09:41:01.503851Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class MetricCollector(MetricCollector):\n", " def total(self, func: str) -> float:\n", " return sum(self.all_metrics(func))\n", "\n", " def maximum(self, func: str) -> float:\n", " return max(self.all_metrics(func))" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Let us instantiate this superclass into `TimeCollector` – a subclass that measures time. This is modeled after our `PerformanceTracer` class, above; notably, the `time` attribute serves the same role." ] }, { "cell_type": "code", "execution_count": 29, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.505257Z", "iopub.status.busy": "2025-01-20T09:41:01.505179Z", "iopub.status.idle": "2025-01-20T09:41:01.507805Z", "shell.execute_reply": "2025-01-20T09:41:01.507606Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class TimeCollector(MetricCollector):\n", " \"\"\"Collect time executed for each line\"\"\"\n", "\n", " def __init__(self) -> None:\n", " \"\"\"Constructor\"\"\"\n", " super().__init__()\n", " self.reset_timer()\n", " self.time: Dict[Location, float] = {}\n", " self.add_items_to_ignore([Timer.Timer, Timer.clock])\n", "\n", " def collect(self, frame: FrameType, event: str, arg: Any) -> None:\n", " \"\"\"Invoked for every line executed. Accumulate time spent.\"\"\"\n", " t = self.timer.elapsed_time()\n", " super().collect(frame, event, arg)\n", " location = (frame.f_code.co_name, frame.f_lineno)\n", "\n", " self.time.setdefault(location, 0.0)\n", " self.time[location] += t\n", "\n", " self.reset_timer()\n", "\n", " def reset_timer(self) -> None:\n", " self.timer = Timer.Timer()\n", "\n", " def __enter__(self) -> Any:\n", " super().__enter__()\n", " self.reset_timer()\n", " return self" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The `metric()` and `all_metrics()` methods accumulate the metric (time taken) for an individual function:" ] }, { "cell_type": "code", "execution_count": 30, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.509392Z", "iopub.status.busy": "2025-01-20T09:41:01.509317Z", "iopub.status.idle": "2025-01-20T09:41:01.511421Z", "shell.execute_reply": "2025-01-20T09:41:01.511197Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "class TimeCollector(TimeCollector):\n", " def metric(self, location: Any) -> Optional[float]:\n", " if location in self.time:\n", " return self.time[location]\n", " else:\n", " return None\n", "\n", " def all_metrics(self, func: str) -> List[float]:\n", " return [time\n", " for (func_name, lineno), time in self.time.items()\n", " if func_name == func]" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Here's how to use `TimeCollector()` – again, in a `with` block:" ] }, { "cell_type": "code", "execution_count": 31, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.512582Z", "iopub.status.busy": "2025-01-20T09:41:01.512509Z", "iopub.status.idle": "2025-01-20T09:41:01.530580Z", "shell.execute_reply": "2025-01-20T09:41:01.530367Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "with TimeCollector() as collector:\n", " for i in range(100):\n", " s = remove_html_markup('foo')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The `time` attribute holds the time spent in each line:" ] }, { "cell_type": "code", "execution_count": 32, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.531788Z", "iopub.status.busy": "2025-01-20T09:41:01.531710Z", "iopub.status.idle": "2025-01-20T09:41:01.533528Z", "shell.execute_reply": "2025-01-20T09:41:01.533307Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "('remove_html_markup', 238) 0.0003748020390048623\n", "('remove_html_markup', 239) 0.0002687927335500717\n", "('remove_html_markup', 240) 0.00025362137239426374\n", "('remove_html_markup', 241) 0.00021975429262965918\n", "('remove_html_markup', 243) 0.0016262800199910998\n", "('remove_html_markup', 244) 0.0014232781250029802\n", "('remove_html_markup', 246) 0.0014147617621347308\n", "('remove_html_markup', 247) 0.0002851528115570545\n", "('remove_html_markup', 248) 0.0011260181199759245\n", "('remove_html_markup', 250) 0.0008431547321379185\n", "('remove_html_markup', 252) 0.0008588926866650581\n", "('remove_html_markup', 249) 0.000286611495539546\n", "('remove_html_markup', 253) 0.0004212367348372936\n", "('remove_html_markup', 255) 0.00027999025769531727\n" ] } ], "source": [ "for location, time_spent in collector.time.items():\n", " print(location, time_spent)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "And we can also create a total for an entire function:" ] }, { "cell_type": "code", "execution_count": 33, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.534678Z", "iopub.status.busy": "2025-01-20T09:41:01.534604Z", "iopub.status.idle": "2025-01-20T09:41:01.536657Z", "shell.execute_reply": "2025-01-20T09:41:01.536454Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "0.00968234718311578" ] }, "execution_count": 33, "metadata": {}, "output_type": "execute_result" } ], "source": [ "collector.total('remove_html_markup')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "### Visualizing Time Spent\n", "\n", "Let us now go and visualize these numbers in a simple form. The idea is to assign each line a _color_ whose saturation indicates the time spent in that line relative to the time spent in the function overall – the higher the fraction, the darker the line. We create a `MetricDebugger` class built as a specialization of `SpectrumDebugger`, in which `suspiciousness()` and `color()` are repurposed to show these metrics." ] }, { "cell_type": "code", "execution_count": 34, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.537781Z", "iopub.status.busy": "2025-01-20T09:41:01.537710Z", "iopub.status.idle": "2025-01-20T09:41:01.541144Z", "shell.execute_reply": "2025-01-20T09:41:01.540938Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class MetricDebugger(SpectrumDebugger):\n", " \"\"\"Visualize a metric\"\"\"\n", "\n", " def metric(self, location: Location) -> float:\n", " sum = 0.0\n", " for outcome in self.collectors:\n", " for collector in self.collectors[outcome]:\n", " assert isinstance(collector, MetricCollector)\n", " m = collector.metric(location)\n", " if m is not None:\n", " sum += m # type: ignore\n", "\n", " return sum\n", "\n", " def total(self, func_name: str) -> float:\n", " total = 0.0\n", " for outcome in self.collectors:\n", " for collector in self.collectors[outcome]:\n", " assert isinstance(collector, MetricCollector)\n", " total += sum(collector.all_metrics(func_name))\n", "\n", " return total\n", "\n", " def maximum(self, func_name: str) -> float:\n", " maximum = 0.0\n", " for outcome in self.collectors:\n", " for collector in self.collectors[outcome]:\n", " assert isinstance(collector, MetricCollector)\n", " maximum = max(maximum, \n", " max(collector.all_metrics(func_name)))\n", "\n", " return maximum\n", "\n", " def suspiciousness(self, location: Location) -> float:\n", " func_name, _ = location\n", " return self.metric(location) / self.total(func_name)\n", "\n", " def color(self, location: Location) -> str:\n", " func_name, _ = location\n", " hue = 240 # blue\n", " saturation = 100 # fully saturated\n", " darkness = self.metric(location) / self.maximum(func_name)\n", " lightness = 100 - darkness * 25\n", " return f\"hsl({hue}, {saturation}%, {lightness}%)\"\n", "\n", " def tooltip(self, location: Location) -> str:\n", " return f\"{super().tooltip(location)} {self.metric(location)}\"" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "We can now introduce `PerformanceDebugger` as a subclass of `MetricDebugger`, using an arbitrary `MetricCollector` (such as `TimeCollector`) to obtain the metric we want to visualize." ] }, { "cell_type": "code", "execution_count": 35, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.542528Z", "iopub.status.busy": "2025-01-20T09:41:01.542435Z", "iopub.status.idle": "2025-01-20T09:41:01.544689Z", "shell.execute_reply": "2025-01-20T09:41:01.544379Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "class PerformanceDebugger(MetricDebugger):\n", " \"\"\"Collect and visualize a metric\"\"\"\n", "\n", " def __init__(self, collector_class: Type, log: bool = False):\n", " assert issubclass(collector_class, MetricCollector)\n", " super().__init__(collector_class, log=log)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "With `PerformanceDebugger`, we inherit all the capabilities of `SpectrumDebugger`, such as showing the (relative) percentage of time spent in a table. We see that the `for` condition and the following `assert` take most of the time, followed by the first condition." ] }, { "cell_type": "code", "execution_count": 36, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.546252Z", "iopub.status.busy": "2025-01-20T09:41:01.546107Z", "iopub.status.idle": "2025-01-20T09:41:01.566869Z", "shell.execute_reply": "2025-01-20T09:41:01.566600Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "with PerformanceDebugger(TimeCollector) as debugger:\n", " for i in range(100):\n", " s = remove_html_markup('foo')" ] }, { "cell_type": "code", "execution_count": 37, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.568147Z", "iopub.status.busy": "2025-01-20T09:41:01.568058Z", "iopub.status.idle": "2025-01-20T09:41:01.570210Z", "shell.execute_reply": "2025-01-20T09:41:01.570000Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ " 238 3% def remove_html_markup(s): # type: ignore\n", " 239 2% tag = False\n", " 240 2% quote = False\n", " 241 2% out = \"\"\n", " 242 0%\n", " 243 16% for c in s:\n", " 244 14% assert tag or not quote\n", " 245 0%\n", " 246 15% if c == '<' and not quote:\n", " 247 3% tag = True\n", " 248 11% elif c == '>' and not quote:\n", " 249 2% tag = False\n", " 250 10% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 8% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 2% return out\n", "\n" ] } ], "source": [ "print(debugger)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "However, we can also visualize these percentages, using shades of blue to indicate those lines most time spent in:" ] }, { "cell_type": "code", "execution_count": 38, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.571309Z", "iopub.status.busy": "2025-01-20T09:41:01.571236Z", "iopub.status.idle": "2025-01-20T09:41:01.573993Z", "shell.execute_reply": "2025-01-20T09:41:01.573762Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "data": { "text/html": [ "
 238 def remove_html_markup(s):  # type: ignore
\n", "
 239     tag = False
\n", "
 240     quote = False
\n", "
 241     out = ""
\n", "
 242  
\n", "
 243     for c in s:
\n", "
 244         assert tag or not quote
\n", "
 245  
\n", "
 246         if c == '<' and not quote:
\n", "
 247             tag = True
\n", "
 248         elif c == '>' and not quote:
\n", "
 249             tag = False
\n", "
 250         elif (c == '"' or c == "'") and tag:
\n", "
 251             quote = not quote
\n", "
 252         elif not tag:
\n", "
 253             out = out + c
\n", "
 254  
\n", "
 255     return out
\n" ], "text/markdown": [ "| `remove_html_markup` | `s='foo'` | \n", "| ---------------------- | ---- | \n", "| remove_html_markup:238 | X | \n", "| remove_html_markup:239 | X | \n", "| remove_html_markup:240 | X | \n", "| remove_html_markup:241 | X | \n", "| remove_html_markup:243 | X | \n", "| remove_html_markup:244 | X | \n", "| remove_html_markup:246 | X | \n", "| remove_html_markup:247 | X | \n", "| remove_html_markup:248 | X | \n", "| remove_html_markup:249 | X | \n", "| remove_html_markup:250 | X | \n", "| remove_html_markup:252 | X | \n", "| remove_html_markup:253 | X | \n", "| remove_html_markup:255 | X | \n" ], "text/plain": [ " 238 3% def remove_html_markup(s): # type: ignore\n", " 239 2% tag = False\n", " 240 2% quote = False\n", " 241 2% out = \"\"\n", " 242 0%\n", " 243 16% for c in s:\n", " 244 14% assert tag or not quote\n", " 245 0%\n", " 246 15% if c == '<' and not quote:\n", " 247 3% tag = True\n", " 248 11% elif c == '>' and not quote:\n", " 249 2% tag = False\n", " 250 10% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 8% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 2% return out" ] }, "execution_count": 38, "metadata": {}, "output_type": "execute_result" } ], "source": [ "debugger" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "### Other Metrics\n", "\n", "Our framework is flexible enough to collect (and visualize) arbitrary metrics. This `HitCollector` class, for instance, collects how often a line is being executed." ] }, { "cell_type": "code", "execution_count": 39, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.575167Z", "iopub.status.busy": "2025-01-20T09:41:01.575090Z", "iopub.status.idle": "2025-01-20T09:41:01.577814Z", "shell.execute_reply": "2025-01-20T09:41:01.577610Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "class HitCollector(MetricCollector):\n", " \"\"\"Collect how often a line is executed\"\"\"\n", "\n", " def __init__(self) -> None:\n", " super().__init__()\n", " self.hits: Dict[Location, int] = {}\n", "\n", " def collect(self, frame: FrameType, event: str, arg: Any) -> None:\n", " super().collect(frame, event, arg)\n", " location = (frame.f_code.co_name, frame.f_lineno)\n", "\n", " self.hits.setdefault(location, 0)\n", " self.hits[location] += 1\n", "\n", " def metric(self, location: Location) -> Optional[int]:\n", " if location in self.hits:\n", " return self.hits[location]\n", " else:\n", " return None\n", "\n", " def all_metrics(self, func: str) -> List[float]:\n", " return [hits\n", " for (func_name, lineno), hits in self.hits.items()\n", " if func_name == func]" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "We can plug in this class into `PerformanceDebugger` to obtain a distribution of lines executed:" ] }, { "cell_type": "code", "execution_count": 40, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.579090Z", "iopub.status.busy": "2025-01-20T09:41:01.579015Z", "iopub.status.idle": "2025-01-20T09:41:01.594076Z", "shell.execute_reply": "2025-01-20T09:41:01.593727Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "with PerformanceDebugger(HitCollector) as debugger:\n", " for i in range(100):\n", " s = remove_html_markup('foo')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "In total, during this call to `remove_html_markup()`, there are 6,400 lines executed:" ] }, { "cell_type": "code", "execution_count": 41, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.595615Z", "iopub.status.busy": "2025-01-20T09:41:01.595519Z", "iopub.status.idle": "2025-01-20T09:41:01.598097Z", "shell.execute_reply": "2025-01-20T09:41:01.597873Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "6400.0" ] }, "execution_count": 41, "metadata": {}, "output_type": "execute_result" } ], "source": [ "debugger.total('remove_html_markup')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Again, we can visualize the distribution as a table and using colors. We can see how the shade gets lighter in the lower part of the loop as individual conditions have been met." ] }, { "cell_type": "code", "execution_count": 42, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.599477Z", "iopub.status.busy": "2025-01-20T09:41:01.599367Z", "iopub.status.idle": "2025-01-20T09:41:01.601377Z", "shell.execute_reply": "2025-01-20T09:41:01.601148Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ " 238 1% def remove_html_markup(s): # type: ignore\n", " 239 1% tag = False\n", " 240 1% quote = False\n", " 241 1% out = \"\"\n", " 242 0%\n", " 243 17% for c in s:\n", " 244 15% assert tag or not quote\n", " 245 0%\n", " 246 15% if c == '<' and not quote:\n", " 247 3% tag = True\n", " 248 12% elif c == '>' and not quote:\n", " 249 3% tag = False\n", " 250 9% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 9% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 3% return out\n", "\n" ] } ], "source": [ "print(debugger)" ] }, { "cell_type": "code", "execution_count": 43, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.602607Z", "iopub.status.busy": "2025-01-20T09:41:01.602511Z", "iopub.status.idle": "2025-01-20T09:41:01.605191Z", "shell.execute_reply": "2025-01-20T09:41:01.604927Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "data": { "text/html": [ "
 238 def remove_html_markup(s):  # type: ignore
\n", "
 239     tag = False
\n", "
 240     quote = False
\n", "
 241     out = ""
\n", "
 242  
\n", "
 243     for c in s:
\n", "
 244         assert tag or not quote
\n", "
 245  
\n", "
 246         if c == '<' and not quote:
\n", "
 247             tag = True
\n", "
 248         elif c == '>' and not quote:
\n", "
 249             tag = False
\n", "
 250         elif (c == '"' or c == "'") and tag:
\n", "
 251             quote = not quote
\n", "
 252         elif not tag:
\n", "
 253             out = out + c
\n", "
 254  
\n", "
 255     return out
\n" ], "text/markdown": [ "| `remove_html_markup` | `s='foo'` | \n", "| ---------------------- | ---- | \n", "| remove_html_markup:238 | X | \n", "| remove_html_markup:239 | X | \n", "| remove_html_markup:240 | X | \n", "| remove_html_markup:241 | X | \n", "| remove_html_markup:243 | X | \n", "| remove_html_markup:244 | X | \n", "| remove_html_markup:246 | X | \n", "| remove_html_markup:247 | X | \n", "| remove_html_markup:248 | X | \n", "| remove_html_markup:249 | X | \n", "| remove_html_markup:250 | X | \n", "| remove_html_markup:252 | X | \n", "| remove_html_markup:253 | X | \n", "| remove_html_markup:255 | X | \n" ], "text/plain": [ " 238 1% def remove_html_markup(s): # type: ignore\n", " 239 1% tag = False\n", " 240 1% quote = False\n", " 241 1% out = \"\"\n", " 242 0%\n", " 243 17% for c in s:\n", " 244 15% assert tag or not quote\n", " 245 0%\n", " 246 15% if c == '<' and not quote:\n", " 247 3% tag = True\n", " 248 12% elif c == '>' and not quote:\n", " 249 3% tag = False\n", " 250 9% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 9% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 3% return out" ] }, "execution_count": 43, "metadata": {}, "output_type": "execute_result" } ], "source": [ "debugger" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Integrating with Delta Debugging\n", "\n", "Besides identifying causes for performance issues in the code, one may also search for causes in the _input_, using [Delta Debugging](DeltaDebugger.ipynb). This can be useful if one does not immediately want to embark into investigating the code, but maybe first determine external influences that are related to performance issues." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Here is a variant of `remove_html_markup()` that introduces a (rather obvious) performance issue." ] }, { "cell_type": "code", "execution_count": 44, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.606468Z", "iopub.status.busy": "2025-01-20T09:41:01.606367Z", "iopub.status.idle": "2025-01-20T09:41:01.607832Z", "shell.execute_reply": "2025-01-20T09:41:01.607626Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import time" ] }, { "cell_type": "code", "execution_count": 45, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.608891Z", "iopub.status.busy": "2025-01-20T09:41:01.608815Z", "iopub.status.idle": "2025-01-20T09:41:01.610992Z", "shell.execute_reply": "2025-01-20T09:41:01.610783Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "def remove_html_markup_ampersand(s: str) -> str:\n", " tag = False\n", " quote = False\n", " out = \"\"\n", "\n", " for c in s:\n", " assert tag or not quote\n", "\n", " if c == '&':\n", " time.sleep(0.1) # <-- the obvious performance issue\n", "\n", " if c == '<' and not quote:\n", " tag = True\n", " elif c == '>' and not quote:\n", " tag = False\n", " elif (c == '\"' or c == \"'\") and tag:\n", " quote = not quote\n", " elif not tag:\n", " out = out + c\n", "\n", " return out" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "We can easily trigger this issue by measuring time taken:" ] }, { "cell_type": "code", "execution_count": 46, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.612085Z", "iopub.status.busy": "2025-01-20T09:41:01.612013Z", "iopub.status.idle": "2025-01-20T09:41:01.931246Z", "shell.execute_reply": "2025-01-20T09:41:01.930702Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "0.31450774997938424" ] }, "execution_count": 46, "metadata": {}, "output_type": "execute_result" } ], "source": [ "with Timer.Timer() as t:\n", " remove_html_markup_ampersand('&&&')\n", "t.elapsed_time()" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "Let us set up a test that checks whether the performance issue is present." ] }, { "cell_type": "code", "execution_count": 47, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.933712Z", "iopub.status.busy": "2025-01-20T09:41:01.933521Z", "iopub.status.idle": "2025-01-20T09:41:01.937687Z", "shell.execute_reply": "2025-01-20T09:41:01.936670Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "def remove_html_test(s: str) -> None:\n", " with Timer.Timer() as t:\n", " remove_html_markup_ampersand(s)\n", " assert t.elapsed_time() < 0.1" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "We can now apply delta debugging to determine a minimum input that causes the failure:" ] }, { "cell_type": "code", "execution_count": 48, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.940875Z", "iopub.status.busy": "2025-01-20T09:41:01.940674Z", "iopub.status.idle": "2025-01-20T09:41:01.944155Z", "shell.execute_reply": "2025-01-20T09:41:01.943222Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "s_fail = 'foo&'" ] }, { "cell_type": "code", "execution_count": 49, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:01.946552Z", "iopub.status.busy": "2025-01-20T09:41:01.946407Z", "iopub.status.idle": "2025-01-20T09:41:02.074744Z", "shell.execute_reply": "2025-01-20T09:41:02.074346Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [], "source": [ "with DeltaDebugger.DeltaDebugger() as dd:\n", " remove_html_test(s_fail)" ] }, { "cell_type": "code", "execution_count": 50, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.076413Z", "iopub.status.busy": "2025-01-20T09:41:02.076287Z", "iopub.status.idle": "2025-01-20T09:41:02.598988Z", "shell.execute_reply": "2025-01-20T09:41:02.598288Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "{'s': '&'}" ] }, "execution_count": 50, "metadata": {}, "output_type": "execute_result" } ], "source": [ "dd.min_args()" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "For performance issues, however, a minimal input is often not enough to highlight the failure cause. This is because short inputs tend to take less processing time than longer inputs, which increases the risks of a spurious diagnosis. A better alternative is to compute a _maximum_ input where the issue does not occur:" ] }, { "cell_type": "code", "execution_count": 51, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.603786Z", "iopub.status.busy": "2025-01-20T09:41:02.603160Z", "iopub.status.idle": "2025-01-20T09:41:02.814976Z", "shell.execute_reply": "2025-01-20T09:41:02.814127Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "s_pass = dd.max_args()" ] }, { "cell_type": "code", "execution_count": 52, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.819912Z", "iopub.status.busy": "2025-01-20T09:41:02.819382Z", "iopub.status.idle": "2025-01-20T09:41:02.824845Z", "shell.execute_reply": "2025-01-20T09:41:02.824339Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "{'s': 'fooamp;'}" ] }, "execution_count": 52, "metadata": {}, "output_type": "execute_result" } ], "source": [ "s_pass" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "We see that the culprit character (the `&`) is removed. This tells us the failure-inducing difference – or, more precisely, the cause for the performance issue." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Synopsis" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "This chapter provides a class `PerformanceDebugger` that allows measuring and visualizing the time taken per line in a function." ] }, { "cell_type": "code", "execution_count": 53, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.829147Z", "iopub.status.busy": "2025-01-20T09:41:02.828574Z", "iopub.status.idle": "2025-01-20T09:41:02.854845Z", "shell.execute_reply": "2025-01-20T09:41:02.854516Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "with PerformanceDebugger(TimeCollector) as debugger:\n", " for i in range(100):\n", " s = remove_html_markup('foo')" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "The distribution of executed time within each function can be obtained by printing out the debugger:" ] }, { "cell_type": "code", "execution_count": 54, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.856450Z", "iopub.status.busy": "2025-01-20T09:41:02.856325Z", "iopub.status.idle": "2025-01-20T09:41:02.858564Z", "shell.execute_reply": "2025-01-20T09:41:02.858305Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ " 238 5% def remove_html_markup(s): # type: ignore\n", " 239 2% tag = False\n", " 240 2% quote = False\n", " 241 2% out = \"\"\n", " 242 0%\n", " 243 16% for c in s:\n", " 244 14% assert tag or not quote\n", " 245 0%\n", " 246 14% if c == '<' and not quote:\n", " 247 2% tag = True\n", " 248 11% elif c == '>' and not quote:\n", " 249 2% tag = False\n", " 250 8% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 8% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 2% return out\n", "\n" ] } ], "source": [ "print(debugger)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The sum of all percentages in a function should always be 100%." ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "fragment" } }, "source": [ "These percentages can also be visualized, where darker shades represent higher percentage values:" ] }, { "cell_type": "code", "execution_count": 55, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.859976Z", "iopub.status.busy": "2025-01-20T09:41:02.859874Z", "iopub.status.idle": "2025-01-20T09:41:02.862806Z", "shell.execute_reply": "2025-01-20T09:41:02.862525Z" }, "slideshow": { "slide_type": "subslide" } }, "outputs": [ { "data": { "text/html": [ "
 238 def remove_html_markup(s):  # type: ignore
\n", "
 239     tag = False
\n", "
 240     quote = False
\n", "
 241     out = ""
\n", "
 242  
\n", "
 243     for c in s:
\n", "
 244         assert tag or not quote
\n", "
 245  
\n", "
 246         if c == '<' and not quote:
\n", "
 247             tag = True
\n", "
 248         elif c == '>' and not quote:
\n", "
 249             tag = False
\n", "
 250         elif (c == '"' or c == "'") and tag:
\n", "
 251             quote = not quote
\n", "
 252         elif not tag:
\n", "
 253             out = out + c
\n", "
 254  
\n", "
 255     return out
\n" ], "text/markdown": [ "| `remove_html_markup` | `s='foo'` | \n", "| ---------------------- | ---- | \n", "| remove_html_markup:238 | X | \n", "| remove_html_markup:239 | X | \n", "| remove_html_markup:240 | X | \n", "| remove_html_markup:241 | X | \n", "| remove_html_markup:243 | X | \n", "| remove_html_markup:244 | X | \n", "| remove_html_markup:246 | X | \n", "| remove_html_markup:247 | X | \n", "| remove_html_markup:248 | X | \n", "| remove_html_markup:249 | X | \n", "| remove_html_markup:250 | X | \n", "| remove_html_markup:252 | X | \n", "| remove_html_markup:253 | X | \n", "| remove_html_markup:255 | X | \n" ], "text/plain": [ " 238 5% def remove_html_markup(s): # type: ignore\n", " 239 2% tag = False\n", " 240 2% quote = False\n", " 241 2% out = \"\"\n", " 242 0%\n", " 243 16% for c in s:\n", " 244 14% assert tag or not quote\n", " 245 0%\n", " 246 14% if c == '<' and not quote:\n", " 247 2% tag = True\n", " 248 11% elif c == '>' and not quote:\n", " 249 2% tag = False\n", " 250 8% elif (c == '\"' or c == \"'\") and tag:\n", " 251 0% quote = not quote\n", " 252 8% elif not tag:\n", " 253 4% out = out + c\n", " 254 0%\n", " 255 2% return out" ] }, "execution_count": 55, "metadata": {}, "output_type": "execute_result" } ], "source": [ "debugger" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "The abstract `MetricCollector` class allows subclassing to build more collectors, such as `HitCollector`." ] }, { "cell_type": "code", "execution_count": 56, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.864407Z", "iopub.status.busy": "2025-01-20T09:41:02.864293Z", "iopub.status.idle": "2025-01-20T09:41:02.865930Z", "shell.execute_reply": "2025-01-20T09:41:02.865643Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "# ignore\n", "from ClassDiagram import display_class_hierarchy" ] }, { "cell_type": "code", "execution_count": 57, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:02.867333Z", "iopub.status.busy": "2025-01-20T09:41:02.867207Z", "iopub.status.idle": "2025-01-20T09:41:04.169284Z", "shell.execute_reply": "2025-01-20T09:41:04.168859Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "image/svg+xml": [ "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "PerformanceDebugger\n", "\n", "\n", "PerformanceDebugger\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "MetricDebugger\n", "\n", "\n", "MetricDebugger\n", "\n", "\n", "\n", "color()\n", "\n", "\n", "\n", "maximum()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "suspiciousness()\n", "\n", "\n", "\n", "tooltip()\n", "\n", "\n", "\n", "total()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "PerformanceDebugger->MetricDebugger\n", "\n", "\n", "\n", "\n", "\n", "SpectrumDebugger\n", "\n", "\n", "SpectrumDebugger\n", "\n", "\n", "\n", "\n", "\n", "MetricDebugger->SpectrumDebugger\n", "\n", "\n", "\n", "\n", "\n", "DifferenceDebugger\n", "\n", "\n", "DifferenceDebugger\n", "\n", "\n", "\n", "FAIL\n", "\n", "\n", "\n", "PASS\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "SpectrumDebugger->DifferenceDebugger\n", "\n", "\n", "\n", "\n", "\n", "StatisticalDebugger\n", "\n", "\n", "StatisticalDebugger\n", "\n", "\n", "\n", "\n", "\n", "DifferenceDebugger->StatisticalDebugger\n", "\n", "\n", "\n", "\n", "\n", "TimeCollector\n", "\n", "\n", "TimeCollector\n", "\n", "\n", "\n", "__enter__()\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "collect()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "reset_timer()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "MetricCollector\n", "\n", "\n", "MetricCollector\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "maximum()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "total()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "TimeCollector->MetricCollector\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector\n", "\n", "\n", "CoverageCollector\n", "\n", "\n", "\n", "\n", "\n", "MetricCollector->CoverageCollector\n", "\n", "\n", "\n", "\n", "\n", "Collector\n", "\n", "\n", "Collector\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector->Collector\n", "\n", "\n", "\n", "\n", "\n", "StackInspector\n", "\n", "\n", "StackInspector\n", "\n", "\n", "\n", "_generated_function_cache\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector->StackInspector\n", "\n", "\n", "\n", "\n", "\n", "Tracer\n", "\n", "\n", "Tracer\n", "\n", "\n", "\n", "\n", "\n", "Collector->Tracer\n", "\n", "\n", "\n", "\n", "\n", "Tracer->StackInspector\n", "\n", "\n", "\n", "\n", "\n", "HitCollector\n", "\n", "\n", "HitCollector\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "collect()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "HitCollector->MetricCollector\n", "\n", "\n", "\n", "\n", "\n", "Legend\n", "Legend\n", "• \n", "public_method()\n", "• \n", "private_method()\n", "• \n", "overloaded_method()\n", "Hover over names to see doc\n", "\n", "\n", "\n" ], "text/html": [ "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "PerformanceDebugger\n", "\n", "\n", "PerformanceDebugger\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "MetricDebugger\n", "\n", "\n", "MetricDebugger\n", "\n", "\n", "\n", "color()\n", "\n", "\n", "\n", "maximum()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "suspiciousness()\n", "\n", "\n", "\n", "tooltip()\n", "\n", "\n", "\n", "total()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "PerformanceDebugger->MetricDebugger\n", "\n", "\n", "\n", "\n", "\n", "SpectrumDebugger\n", "\n", "\n", "SpectrumDebugger\n", "\n", "\n", "\n", "\n", "\n", "MetricDebugger->SpectrumDebugger\n", "\n", "\n", "\n", "\n", "\n", "DifferenceDebugger\n", "\n", "\n", "DifferenceDebugger\n", "\n", "\n", "\n", "FAIL\n", "\n", "\n", "\n", "PASS\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "SpectrumDebugger->DifferenceDebugger\n", "\n", "\n", "\n", "\n", "\n", "StatisticalDebugger\n", "\n", "\n", "StatisticalDebugger\n", "\n", "\n", "\n", "\n", "\n", "DifferenceDebugger->StatisticalDebugger\n", "\n", "\n", "\n", "\n", "\n", "TimeCollector\n", "\n", "\n", "TimeCollector\n", "\n", "\n", "\n", "__enter__()\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "collect()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "reset_timer()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "MetricCollector\n", "\n", "\n", "MetricCollector\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "maximum()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "total()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "TimeCollector->MetricCollector\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector\n", "\n", "\n", "CoverageCollector\n", "\n", "\n", "\n", "\n", "\n", "MetricCollector->CoverageCollector\n", "\n", "\n", "\n", "\n", "\n", "Collector\n", "\n", "\n", "Collector\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector->Collector\n", "\n", "\n", "\n", "\n", "\n", "StackInspector\n", "\n", "\n", "StackInspector\n", "\n", "\n", "\n", "_generated_function_cache\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "CoverageCollector->StackInspector\n", "\n", "\n", "\n", "\n", "\n", "Tracer\n", "\n", "\n", "Tracer\n", "\n", "\n", "\n", "\n", "\n", "Collector->Tracer\n", "\n", "\n", "\n", "\n", "\n", "Tracer->StackInspector\n", "\n", "\n", "\n", "\n", "\n", "HitCollector\n", "\n", "\n", "HitCollector\n", "\n", "\n", "\n", "__init__()\n", "\n", "\n", "\n", "all_metrics()\n", "\n", "\n", "\n", "collect()\n", "\n", "\n", "\n", "metric()\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "\n", "HitCollector->MetricCollector\n", "\n", "\n", "\n", "\n", "\n", "Legend\n", "Legend\n", "• \n", "public_method()\n", "• \n", "private_method()\n", "• \n", "overloaded_method()\n", "Hover over names to see doc\n", "\n", "\n", "\n" ], "text/plain": [ "" ] }, "execution_count": 57, "metadata": {}, "output_type": "execute_result" } ], "source": [ "# ignore\n", "display_class_hierarchy([PerformanceDebugger, TimeCollector, HitCollector],\n", " public_methods=[\n", " PerformanceDebugger.__init__,\n", " ],\n", " project='debuggingbook')" ] }, { "cell_type": "markdown", "metadata": { "button": false, "new_sheet": true, "run_control": { "read_only": false }, "slideshow": { "slide_type": "slide" } }, "source": [ "## Lessons Learned\n", "\n", "* To measure performance,\n", " * instrument the code such that the time taken per function (or line) is collected; or\n", " * sample the execution that at regular intervals, the active call stack is collected.\n", "* To make code performant, focus on efficient algorithms, efficient data types, and sufficient abstraction such that you can replace them by alternatives.\n", "* Beyond efficient algorithms and data types, do _not_ optimize before measuring." ] }, { "cell_type": "markdown", "metadata": { "button": false, "new_sheet": false, "run_control": { "read_only": false }, "slideshow": { "slide_type": "slide" } }, "source": [ "## Next Steps\n", "\n", "This chapter concludes the part on abstracting failures. The next part will focus on\n", "\n", "* [repairing code automatically](Repairer.ipynb)" ] }, { "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Background\n", "\n", "[Scalene](https://github.com/plasma-umass/scalene) is a high-performance, high-precision CPU, GPU, and memory profiler for Python. In contrast to the standard Python `cProfile` profiler, it uses _sampling_ instead of instrumentation or relying on Python's tracing facilities; and it also supports line-by-line profiling. Scalene might be the tool of choice if you want to go beyond basic profiling.\n", "\n", "The Wikipedia articles on [profiling](https://en.wikipedia.org/wiki/Profiling_(computer_programming)) and [performance analysis tools](https://en.wikipedia.org/wiki/List_of_performance_analysis_tools) provide several additional resources on profiling tools and how to apply them in practice." ] }, { "cell_type": "markdown", "metadata": { "button": false, "new_sheet": true, "run_control": { "read_only": false }, "slideshow": { "slide_type": "slide" } }, "source": [ "## Exercises" ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "button": false, "new_sheet": false, "run_control": { "read_only": false }, "slideshow": { "slide_type": "subslide" } }, "source": [ "### Exercise 1: Profiling Memory Usage\n", "\n", "The Python [`tracemalloc` module](https://docs.python.org/3/library/tracemalloc.html) allows tracking memory usage during execution. Between `tracemalloc.start()` and `tracemalloc.end()`, use `tracemalloc.get_traced_memory()` to obtain how much memory is currently being consumed:" ] }, { "cell_type": "code", "execution_count": 58, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:04.171045Z", "iopub.status.busy": "2025-01-20T09:41:04.170916Z", "iopub.status.idle": "2025-01-20T09:41:04.174722Z", "shell.execute_reply": "2025-01-20T09:41:04.174208Z" }, "slideshow": { "slide_type": "skip" } }, "outputs": [], "source": [ "import tracemalloc" ] }, { "cell_type": "code", "execution_count": 59, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:04.176284Z", "iopub.status.busy": "2025-01-20T09:41:04.176139Z", "iopub.status.idle": "2025-01-20T09:41:04.178510Z", "shell.execute_reply": "2025-01-20T09:41:04.178031Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "tracemalloc.start()" ] }, { "cell_type": "code", "execution_count": 60, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:04.180871Z", "iopub.status.busy": "2025-01-20T09:41:04.180593Z", "iopub.status.idle": "2025-01-20T09:41:04.185625Z", "shell.execute_reply": "2025-01-20T09:41:04.185084Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [ { "data": { "text/plain": [ "23083" ] }, "execution_count": 60, "metadata": {}, "output_type": "execute_result" } ], "source": [ "current_size, peak_size = tracemalloc.get_traced_memory()\n", "current_size" ] }, { "cell_type": "code", "execution_count": 61, "metadata": { "execution": { "iopub.execute_input": "2025-01-20T09:41:04.188020Z", "iopub.status.busy": "2025-01-20T09:41:04.187734Z", "iopub.status.idle": "2025-01-20T09:41:04.190253Z", "shell.execute_reply": "2025-01-20T09:41:04.189943Z" }, "slideshow": { "slide_type": "fragment" } }, "outputs": [], "source": [ "tracemalloc.stop()" ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "subslide" } }, "source": [ "Create a subclass of `MetricCollector` named `MemoryCollector`. Make it measure the memory consumption before and after each line executed (0 if negative), and visualize the impact of individual lines on memory. Create an appropriate test program that (temporarily) consumes larger amounts of memory." ] }, { "attachments": {}, "cell_type": "markdown", "metadata": { "slideshow": { "slide_type": "slide" } }, "source": [ "## Exercise 2: Statistical Performance Debugging\n", "\n", "In a similar way as we integrated a binary \"performance test\" with delta debugging, we can also integrate such a test with other techniques. Combining a performance test with [Statistical Debugging](StatisticalDebugger.ipynb), for instance, will highlight those lines whose execution correlates with low performance. But then, the performance test need not be binary, as with functional pass/fail tests – you can also _weight_ individual lines by _how much_ they impact performance. Create a variant of `StatisticalDebugger` that reflects the impact of individual lines on an arbitrary (summarized) performance metric." ] } ], "metadata": { "ipub": { "bibliography": "fuzzingbook.bib", "toc": true }, "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.12.8" }, "toc": { "base_numbering": 1, "nav_menu": {}, "number_sections": true, "sideBar": true, "skip_h1_title": true, "title_cell": "", "title_sidebar": "Contents", "toc_cell": false, "toc_position": {}, "toc_section_display": true, "toc_window_display": true }, "toc-autonumbering": false }, "nbformat": 4, "nbformat_minor": 4 }