Debugging Performance Issues

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.

from bookutils import YouTubeVideo
YouTubeVideo("0tMeB9G0uUI")

Prerequisites

import bookutils

Synopsis

To use the code provided in this chapter, write

>>> from debuggingbook.PerformanceDebugger import <identifier>

and then make use of the following features.

This chapter provides a class PerformanceDebugger that allows to measure and visualize the time taken per line in a function.

>>> with PerformanceDebugger(TimeCollector) as debugger:
>>>     for i in range(100):
>>>         s = remove_html_markup('<b>foo</b>')

The distribution of executed time within each function can be obtained by printing out the debugger:

>>> print(debugger)
 238   2% def remove_html_markup(s):
 239   1%     tag = False
 240   1%     quote = False
 241   1%     out = ""
 242   0%
 243  16%     for c in s:
 244  15%         assert tag or not quote
 245   0%
 246  15%         if c == '<' and not quote:
 247   2%             tag = True
 248  12%         elif c == '>' and not quote:
 249   3%             tag = False
 250   8%         elif (c == '"' or c == "'") and tag:
 251   0%             quote = not quote
 252   9%         elif not tag:
 253   4%             out = out + c
 254   0%
 255   3%     return out

The sum of all percentages in a function should always be 100%.

These percentages can also be visualized, where darker shades represent higher percentage values:

>>> debugger
 238 def remove_html_markup(s):  # type: ignore
 239     tag = False
 240     quote = False
 241     out = ""
 242  
 243     for c in s:
 244         assert tag or not quote
 245  
 246         if c == '<' and not quote:
 247             tag = True
 248         elif c == '>' and not quote:
 249             tag = False
 250         elif (c == '"' or c == "'") and tag:
 251             quote = not quote
 252         elif not tag:
 253             out = out + c
 254  
 255     return out

The abstract MetricCollector class allows subclassing to build more collectors, such as HitCollector.

%3 PerformanceDebugger PerformanceDebugger __init__() MetricDebugger MetricDebugger color() maximum() metric() suspiciousness() tooltip() total() PerformanceDebugger->MetricDebugger SpectrumDebugger SpectrumDebugger __repr__() __str__() _repr_html_() code() percentage() suspiciousness() tooltip() MetricDebugger->SpectrumDebugger DifferenceDebugger DifferenceDebugger FAIL PASS __enter__() __exit__() all_fail_events() all_pass_events() collect_fail() collect_pass() fail_collectors() only_fail_events() only_pass_events() pass_collectors() SpectrumDebugger->DifferenceDebugger StatisticalDebugger StatisticalDebugger __init__() __repr__() _repr_markdown_() add_collector() all_events() collect() color() coverage() covered_functions() event_str() event_table() event_table_text() function() tooltip() DifferenceDebugger->StatisticalDebugger TimeCollector TimeCollector __enter__() __init__() all_metrics() collect() metric() reset_timer() MetricCollector MetricCollector all_metrics() maximum() metric() total() TimeCollector->MetricCollector CoverageCollector CoverageCollector __init__() collect() coverage() covered_functions() events() MetricCollector->CoverageCollector Collector Collector __exit__() __init__() __repr__() add_items_to_ignore() args() argstring() collect() coverage() covered_functions() events() exception() function() id() traceit() CoverageCollector->Collector StackInspector StackInspector _generated_function_cache caller_frame() caller_function() caller_globals() caller_locals() caller_location() create_function() is_internal_error() our_frame() search_frame() search_func() unknown() CoverageCollector->StackInspector Tracer Tracer __enter__() __exit__() __init__() _traceit() changed_vars() log() print_debugger_status() traceit() Collector->Tracer Tracer->StackInspector HitCollector HitCollector __init__() all_metrics() collect() metric() HitCollector->MetricCollector Legend Legend •  public_method() •  private_method() •  overloaded_method() Hover over names to see doc

Measuring Performance

The solution to debugging performance issues fits in two simple rules:

  1. Measure performance
  2. Break down how individual parts of your code contribute to performance.

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.

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

  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

  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 profiler works this way.

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.

Tracing Execution Profiles

Let us illustrate profiling in a simple example. The ChangeCounter class (which we will encounter in the chapter on mining version histories reads in a version history from a git repository. Yet, it takes more than a minute to read in the debugging book change history:

from ChangeCounter import ChangeCounter, debuggingbook_change_counter  # minor dependency
import Timer
with Timer.Timer() as t:
    change_counter = debuggingbook_change_counter(ChangeCounter)
t.elapsed_time()
155.81421788999796

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:

  • How often it was called (ncalls column)
  • How much time was spent in the given function, excluding time spent in calls to sub-functions (tottime column)
  • The fraction of tottime / ncalls (first percall column)
  • How much time was spent in the given function, including time spent in calls to sub-functions (cumtime column)
  • The fraction of cumtime / percall (second percall column)

Let us have a look at the profile we obtain:

import cProfile
cProfile.run('debuggingbook_change_counter(ChangeCounter)', sort='cumulative')
         10390598 function calls (10310890 primitive calls) in 154.961 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  154.961  154.961 {built-in method builtins.exec}
        1    0.000    0.000  154.961  154.961 <string>:1(<module>)
        1    0.000    0.000  154.961  154.961 ChangeCounter.ipynb:165(debuggingbook_change_counter)
        1    0.000    0.000  154.961  154.961 ChangeCounter.ipynb:51(__init__)
        1    1.514    1.514  154.960  154.960 ChangeCounter.ipynb:88(mine)
      735    0.026    0.000  153.058    0.208 ChangeCounter.ipynb:99(mine_commit)
      735    0.177    0.000  152.834    0.208 commit.py:657(modified_files)
      735    0.055    0.000  152.656    0.208 commit.py:673(_get_modifications)
      702    0.231    0.000   85.005    0.121 diff.py:71(diff)
      702    7.490    0.011   69.998    0.100 diff.py:412(_index_from_patch_format)
      735    0.088    0.000   67.576    0.092 commit.py:707(_parse_diff)
    13694    0.506    0.000   66.389    0.005 commit.py:736(_get_decoded_sc_str)
   560217   46.625    0.000   46.625    0.000 {method 'decode' of 'bytes' objects}
      702    0.111    0.000   45.590    0.065 cmd.py:59(handle_process_output)
     7053   44.739    0.006   44.739    0.006 {method 'acquire' of '_thread.lock' objects}
     1408    0.015    0.000   44.542    0.032 threading.py:1024(join)
     1408    0.013    0.000   44.525    0.032 threading.py:1062(_wait_for_tstate_lock)
    43931    0.123    0.000   19.649    0.000 cmd.py:435(read)
    87840   19.516    0.000   19.517    0.000 {method 'read' of '_io.BufferedReader' objects}
    37028    0.030    0.000   19.495    0.001 base.py:137(read)
     6847    0.121    0.000   15.880    0.002 diff.py:258(__init__)
     6168    0.100    0.000   15.642    0.003 base.py:332(submodules)
     6168    0.044    0.000   15.542    0.003 util.py:919(list_items)
13920/13917    0.032    0.000   15.484    0.001 {method 'extend' of 'list' objects}
    18504    0.179    0.000   15.452    0.001 base.py:1174(iter_items)
      711    0.312    0.000   14.817    0.021 cmd.py:946(_call_process)
      703    0.065    0.000   14.773    0.021 cmd.py:545(<lambda>)
      711    0.213    0.000   14.477    0.020 cmd.py:583(execute)
      711    0.239    0.000   13.988    0.020 subprocess.py:608(__init__)
      711    0.211    0.000   13.710    0.019 subprocess.py:1228(_execute_child)
      711   10.642    0.015   10.642    0.015 {built-in method _posixsubprocess.fork_exec}
    68603    0.364    0.000    5.781    0.000 cmd.py:1060(__get_object_header)
    31575    0.082    0.000    5.451    0.000 util.py:248(__getattr__)
    18504    0.036    0.000    5.134    0.000 base.py:472(commit)
   112795    4.554    0.000    4.555    0.000 {method 'readline' of '_io.BufferedReader' objects}
    18504    0.021    0.000    4.444    0.000 symbolic.py:192(_get_commit)
    18504    0.038    0.000    4.423    0.000 symbolic.py:183(_get_object)
43176/12336    0.053    0.000    4.415    0.000 tree.py:287(__getitem__)
43176/12336    0.187    0.000    4.386    0.000 tree.py:210(join)
    43931    0.161    0.000    4.358    0.000 db.py:40(stream)
    43931    0.179    0.000    4.039    0.000 cmd.py:1085(stream_object_data)
    24672    0.071    0.000    3.897    0.000 tree.py:190(_set_cache_)
    24672    0.041    0.000    3.482    0.000 symbolic.py:125(dereference_recursive)
    49345    0.106    0.000    3.441    0.000 symbolic.py:176(_get_ref_info)
    49345    0.636    0.000    3.335    0.000 symbolic.py:137(_get_ref_info_helper)
     6168    0.064    0.000    2.875    0.000 base.py:171(_config_parser)
    24672    0.122    0.000    2.796    0.000 base.py:54(new_from_sha)
      711    2.512    0.004    2.512    0.004 {built-in method posix.read}
    24672    0.098    0.000    2.383    0.000 db.py:36(info)
    24672    0.043    0.000    2.203    0.000 cmd.py:1065(get_object_header)
    56997    1.998    0.000    2.080    0.000 {built-in method io.open}
     6168    0.055    0.000    2.046    0.000 fun.py:175(rev_parse)
     6168    0.046    0.000    1.982    0.000 fun.py:106(name_to_object)
     6903    0.048    0.000    1.458    0.000 commit.py:139(_set_cache_)
49390/43191    0.084    0.000    1.381    0.000 config.py:79(assure_data_present)
     6168    0.114    0.000    1.322    0.000 util.py:56(__init__)
    12356    0.022    0.000    1.262    0.000 base.py:108(data_stream)
     6182    0.064    0.000    1.211    0.000 config.py:255(__init__)
     6182    0.085    0.000    1.143    0.000 configparser.py:600(__init__)
49390/43208    0.102    0.000    1.025    0.000 config.py:507(read)
      702    0.930    0.001    0.930    0.001 {method 'join' of 'bytes' objects}
     6182    0.168    0.000    0.892    0.000 configparser.py:1296(__init__)
    24672    0.587    0.000    0.853    0.000 fun.py:41(tree_entries_from_data)
     6847    0.006    0.000    0.666    0.000 commit.py:726(_get_decoded_str)
     1408    0.029    0.000    0.535    0.000 threading.py:828(start)
     6182    0.248    0.000    0.531    0.000 config.py:356(_read)
     6182    0.528    0.000    0.528    0.000 {built-in method builtins.dir}
    49369    0.328    0.000    0.429    0.000 {method 'read' of '_io.TextIOWrapper' objects}
      736    0.004    0.000    0.388    0.001 repository.py:201(traverse_commits)
     6903    0.116    0.000    0.388    0.000 commit.py:445(_deserialize)
     6847    0.077    0.000    0.370    0.000 commit.py:153(__init__)
     1408    0.125    0.000    0.328    0.000 threading.py:757(__init__)
   853478    0.320    0.000    0.320    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
    68603    0.301    0.000    0.301    0.000 {method 'flush' of '_io.BufferedWriter' objects}
    12575    0.033    0.000    0.293    0.000 pathlib.py:998(__new__)
    68492    0.188    0.000    0.293    0.000 posixpath.py:75(join)
     1408    0.009    0.000    0.291    0.000 threading.py:533(wait)
     7582    0.005    0.000    0.287    0.000 commit.py:564(committer_date)
     7582    0.007    0.000    0.282    0.000 commit.py:152(committed_datetime)
     1408    0.024    0.000    0.278    0.000 threading.py:263(wait)
      711    0.048    0.000    0.268    0.000 os.py:701(copy)
    12577    0.029    0.000    0.254    0.000 pathlib.py:651(_from_parts)
    68603    0.176    0.000    0.248    0.000 cmd.py:1013(_parse_object_header)
    24685    0.054    0.000    0.244    0.000 configparser.py:765(get)
      739    0.018    0.000    0.238    0.000 repository.py:236(_iter_commits)
   209712    0.123    0.000    0.233    0.000 compat.py:27(safe_decode)
    12577    0.051    0.000    0.220    0.000 pathlib.py:631(_parse_args)
     1408    0.214    0.000    0.214    0.000 {built-in method _thread.start_new_thread}
    68603    0.109    0.000    0.211    0.000 cmd.py:1035(_prepare_ref)
    24672    0.092    0.000    0.191    0.000 util.py:44(get_object_type_by_name)
   384407    0.177    0.000    0.177    0.000 {built-in method builtins.getattr}
     6185    0.015    0.000    0.175    0.000 config.py:454(_has_includes)
    13806    0.041    0.000    0.174    0.000 util.py:221(parse_actor_and_date)
   252550    0.103    0.000    0.173    0.000 cmd.py:384(__getattr__)
    68603    0.035    0.000    0.172    0.000 cmd.py:1048(_get_persistent_cmd)
    94030    0.093    0.000    0.169    0.000 base.py:132(__init__)
     6182    0.018    0.000    0.159    0.000 config.py:457(_included_paths)
    12577    0.081    0.000    0.155    0.000 pathlib.py:51(parse_parts)
     6182    0.091    0.000    0.150    0.000 configparser.py:1219(__init__)
   943901    0.150    0.000    0.150    0.000 {built-in method builtins.isinstance}
    68732    0.150    0.000    0.150    0.000 {method 'write' of '_io.BufferedWriter' objects}
   140067    0.075    0.000    0.136    0.000 os.py:794(fsencode)
    82442    0.122    0.000    0.133    0.000 base.py:29(__init__)
    61870    0.055    0.000    0.126    0.000 os.py:664(__getitem__)
     1408    0.015    0.000    0.125    0.000 _weakrefset.py:81(add)
    12350    0.023    0.000    0.123    0.000 configparser.py:644(sections)
      736    0.000    0.000    0.122    0.000 git.py:106(get_list_commits)
    24685    0.076    0.000    0.120    0.000 configparser.py:1131(_unify_values)
      736    0.001    0.000    0.115    0.000 commit.py:248(_iter_from_process_or_stream)
    25407    0.038    0.000    0.111    0.000 tree.py:181(__init__)
     2123    0.110    0.000    0.110    0.000 {method 'add' of 'set' objects}
     7582    0.025    0.000    0.108    0.000 util.py:124(from_timestamp)
    32343    0.048    0.000    0.105    0.000 commit.py:71(__init__)
      711    0.025    0.000    0.104    0.000 os.py:607(get_exec_path)
    49369    0.065    0.000    0.102    0.000 codecs.py:318(decode)
    12350    0.100    0.000    0.100    0.000 {method 'keys' of 'collections.OrderedDict' objects}
    12336    0.019    0.000    0.097    0.000 base.py:304(index)
   270669    0.084    0.000    0.084    0.000 {method 'encode' of 'str' objects}
    40033    0.084    0.000    0.084    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
    62568    0.019    0.000    0.083    0.000 _collections_abc.py:719(__iter__)
    49369    0.056    0.000    0.082    0.000 codecs.py:308(__init__)
    43188    0.056    0.000    0.079    0.000 util.py:127(join_path)
    12336    0.023    0.000    0.078    0.000 base.py:96(__init__)
   120205    0.077    0.000    0.077    0.000 {built-in method binascii.a2b_hex}
   112685    0.076    0.000    0.076    0.000 {method 'split' of 'str' objects}
    49345    0.064    0.000    0.075    0.000 symbolic.py:26(_git_dir)
    13694    0.011    0.000    0.070    0.000 diff.py:399(_pick_best_path)
    24685    0.044    0.000    0.064    0.000 __init__.py:877(__getitem__)
    62568    0.038    0.000    0.064    0.000 os.py:687(__iter__)
    24673    0.037    0.000    0.063    0.000 <frozen importlib._bootstrap>:997(_handle_fromlist)
    13694    0.039    0.000    0.059    0.000 diff.py:31(decode_path)
      711    0.059    0.000    0.059    0.000 warnings.py:449(__enter__)
    43407    0.058    0.000    0.059    0.000 config.py:155(__setitem__)
   389847    0.058    0.000    0.058    0.000 {built-in method builtins.len}
    18505    0.022    0.000    0.058    0.000 base.py:311(head)
      703    0.015    0.000    0.057    0.000 util.py:326(finalize_process)
    82442    0.057    0.000    0.057    0.000 {method 'split' of 'bytes' objects}
     1409    0.012    0.000    0.056    0.000 threading.py:498(__init__)
    12336    0.022    0.000    0.055    0.000 base.py:98(__init__)
    12336    0.014    0.000    0.055    0.000 base.py:136(_index_path)
    43931    0.030    0.000    0.054    0.000 base.py:128(__new__)
     6847    0.004    0.000    0.054    0.000 ChangeCounter.ipynb:109(include)
   363587    0.053    0.000    0.053    0.000 {method 'append' of 'list' objects}
    13509    0.010    0.000    0.052    0.000 subprocess.py:1284(<genexpr>)
    69290    0.033    0.000    0.052    0.000 posixpath.py:41(_get_sep)
   123714    0.025    0.000    0.052    0.000 os.py:746(decode)
    61752    0.041    0.000    0.052    0.000 config.py:168(__getitem__)
    12573    0.050    0.000    0.050    0.000 util.py:29(mode_str_to_int)
     6847    0.015    0.000    0.050    0.000 ChangeCounter.ipynb:173(filter)
     1405    0.015    0.000    0.048    0.000 cmd.py:387(wait)
    72914    0.048    0.000    0.048    0.000 {built-in method binascii.b2a_hex}
    13806    0.019    0.000    0.048    0.000 util.py:561(_from_string)
    87348    0.047    0.000    0.047    0.000 {built-in method __new__ of type object at 0x1092b2ea8}
    48024    0.047    0.000    0.047    0.000 {built-in method sys.intern}
     6847    0.026    0.000    0.046    0.000 commit.py:907(_from_change_to_modification_type)
    61870    0.023    0.000    0.046    0.000 os.py:742(encode)
     1412    0.021    0.000    0.045    0.000 subprocess.py:1434(wait)
   126003    0.045    0.000    0.045    0.000 {method 'startswith' of 'str' objects}
   155149    0.042    0.000    0.042    0.000 {method 'endswith' of 'str' objects}
     7582    0.031    0.000    0.041    0.000 {built-in method fromtimestamp}
    12348    0.013    0.000    0.041    0.000 util.py:160(join_path_native)
    85733    0.041    0.000    0.041    0.000 {built-in method builtins.hasattr}
    12336    0.030    0.000    0.039    0.000 symbolic.py:410(to_full_path)
   222182    0.037    0.000    0.037    0.000 {built-in method posix.fspath}
    49369    0.037    0.000    0.037    0.000 {built-in method _codecs.utf_8_decode}
    24672    0.022    0.000    0.037    0.000 base.py:35(__new__)
    18506    0.026    0.000    0.036    0.000 head.py:25(__init__)
    24673    0.026    0.000    0.036    0.000 <frozen importlib._bootstrap>:416(parent)
     3531    0.034    0.000    0.034    0.000 {built-in method _thread.allocate_lock}
    16972    0.012    0.000    0.033    0.000 commit.py:227(new_path)
      719    0.011    0.000    0.032    0.000 cmd.py:345(__del__)
    12336    0.022    0.000    0.032    0.000 configparser.py:876(has_option)
    43931    0.031    0.000    0.031    0.000 cmd.py:424(__init__)
    68184    0.027    0.000    0.027    0.000 {method 'group' of '_sre.SRE_Match' objects}
    49369    0.026    0.000    0.026    0.000 codecs.py:259(__init__)
    13806    0.024    0.000    0.024    0.000 util.py:68(utctz_to_altz)
     2853    0.024    0.000    0.024    0.000 {built-in method posix.close}
    24866    0.024    0.000    0.024    0.000 config.py:158(add)
    34459    0.023    0.000    0.023    0.000 {method 'groups' of '_sre.SRE_Match' objects}
      710    0.002    0.000    0.022    0.000 subprocess.py:1421(_try_wait)
     1416    0.021    0.000    0.022    0.000 threading.py:215(__init__)
    17846    0.013    0.000    0.022    0.000 base.py:84(__ne__)
     7582    0.022    0.000    0.022    0.000 util.py:104(__init__)
    16534    0.013    0.000    0.021    0.000 pathlib.py:691(__str__)
      718    0.020    0.000    0.020    0.000 {built-in method posix.waitpid}
        2    0.000    0.000    0.020    0.010 {built-in method builtins.next}
        2    0.000    0.000    0.020    0.010 repository.py:166(_prep_repo)
     7582    0.016    0.000    0.020    0.000 {method 'astimezone' of 'datetime.datetime' objects}
    43931    0.020    0.000    0.020    0.000 cmd.py:511(__del__)
   131005    0.019    0.000    0.019    0.000 {method 'strip' of 'str' objects}
    24685    0.019    0.000    0.019    0.000 __init__.py:867(__init__)
       13    0.001    0.000    0.019    0.001 base.py:88(__init__)
       12    0.000    0.000    0.018    0.002 util.py:63(wrapper)
    74259    0.018    0.000    0.018    0.000 {method 'rstrip' of 'str' objects}
    65061    0.018    0.000    0.018    0.000 {method 'startswith' of 'bytes' objects}
       12    0.000    0.000    0.018    0.002 base.py:1049(module)
       15    0.000    0.000    0.018    0.001 cmd.py:1094(clear_cache)
      735    0.004    0.000    0.018    0.000 conf.py:257(is_commit_filtered)
     2785    0.015    0.000    0.018    0.000 __init__.py:1544(isEnabledFor)
      430    0.002    0.000    0.017    0.000 ChangeCounter.ipynb:118(update_stats)
    24672    0.017    0.000    0.017    0.000 base.py:38(__init__)
    12865    0.012    0.000    0.016    0.000 diff.py:370(a_path)
      736    0.003    0.000    0.016    0.000 __init__.py:1298(info)
        1    0.000    0.000    0.016    0.016 contextlib.py:85(__exit__)
        2    0.000    0.000    0.015    0.008 git.py:73(clear)
 6330/711    0.009    0.000    0.015    0.000 cmd.py:915(__unpack_args)
    30918    0.015    0.000    0.015    0.000 {built-in method builtins.setattr}
     4444    0.013    0.000    0.014    0.000 conf.py:45(get)
     6847    0.011    0.000    0.014    0.000 commit.py:526(committer)
    12336    0.011    0.000    0.013    0.000 util.py:18(sm_name)
        6    0.000    0.000    0.012    0.002 base.py:1067(module_exists)
      711    0.004    0.000    0.012    0.000 subprocess.py:1174(_get_handles)
    24685    0.011    0.000    0.011    0.000 base.py:271(common_dir)
    12573    0.011    0.000    0.011    0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
     2141    0.011    0.000    0.011    0.000 {built-in method posix.pipe}
    61881    0.011    0.000    0.011    0.000 {function _OMD.__getitem__ at 0x7fe76c92eea0}
     1404    0.011    0.000    0.011    0.000 threading.py:727(_newname)
     6168    0.008    0.000    0.010    0.000 util.py:851(__new__)
      711    0.009    0.000    0.010    0.000 _collections_abc.py:672(keys)
    24673    0.010    0.000    0.010    0.000 {method 'rpartition' of 'str' objects}
    18506    0.010    0.000    0.010    0.000 symbolic.py:48(__init__)
    22746    0.010    0.000    0.010    0.000 util.py:111(utcoffset)
    13185    0.006    0.000    0.010    0.000 diff.py:374(b_path)
      430    0.010    0.000    0.010    0.000 ChangeCounter.ipynb:134(update_size)
     1413    0.009    0.000    0.009    0.000 {method 'append' of 'collections.deque' objects}
     2816    0.008    0.000    0.009    0.000 threading.py:1230(current_thread)
     5527    0.006    0.000    0.009    0.000 diff.py:393(renamed_file)
    34866    0.008    0.000    0.008    0.000 {method 'readline' of '_io.BytesIO' objects}
     4311    0.004    0.000    0.008    0.000 base.py:102(hexsha)
      702    0.008    0.000    0.008    0.000 {method 'finditer' of '_sre.SRE_Pattern' objects}
      711    0.005    0.000    0.008    0.000 cmd.py:903(transform_kwargs)
    61888    0.008    0.000    0.008    0.000 config.py:352(optionxform)
     6409    0.005    0.000    0.008    0.000 pathlib.py:674(_format_parsed_parts)
    12577    0.008    0.000    0.008    0.000 pathlib.py:282(splitroot)
    13806    0.007    0.000    0.007    0.000 util.py:542(__init__)
      711    0.003    0.000    0.007    0.000 warnings.py:143(simplefilter)
    37300    0.007    0.000    0.007    0.000 {method 'lower' of 'str' objects}
     2049    0.002    0.000    0.007    0.000 __init__.py:1286(debug)
    49344    0.006    0.000    0.006    0.000 {built-in method builtins.ord}
     6065    0.002    0.000    0.006    0.000 config.py:318(__del__)
    50/26    0.000    0.000    0.006    0.000 fun.py:70(find_submodule_git_dir)
        1    0.000    0.000    0.006    0.006 base.py:504(iter_commits)
        1    0.000    0.000    0.006    0.006 commit.py:186(iter_items)
     1408    0.005    0.000    0.006    0.000 _weakrefset.py:38(_remove)
     1404    0.003    0.000    0.006    0.000 threading.py:1147(setDaemon)
    24672    0.006    0.000    0.006    0.000 base.py:52(type)
      735    0.003    0.000    0.006    0.000 posixpath.py:154(dirname)
    12577    0.006    0.000    0.006    0.000 pathlib.py:1008(_init)
      735    0.003    0.000    0.006    0.000 commit.py:506(hash)
     6168    0.004    0.000    0.005    0.000 base.py:78(__eq__)
      711    0.005    0.000    0.005    0.000 cmd.py:341(__init__)
     1408    0.005    0.000    0.005    0.000 threading.py:1120(daemon)
     6168    0.005    0.000    0.005    0.000 util.py:854(__init__)
     6182    0.003    0.000    0.005    0.000 configparser.py:1338(__iter__)
     6847    0.004    0.000    0.005    0.000 commit.py:591(msg)
     6168    0.005    0.000    0.005    0.000 fun.py:164(to_commit)
      711    0.005    0.000    0.005    0.000 warnings.py:428(__init__)
    24672    0.005    0.000    0.005    0.000 base.py:42(binsha)
    24672    0.004    0.000    0.004    0.000 base.py:60(size)
     6066    0.003    0.000    0.004    0.000 config.py:330(release)
        1    0.000    0.000    0.004    0.004 contextlib.py:79(__enter__)
     1423    0.004    0.000    0.004    0.000 {built-in method builtins.sorted}
      430    0.003    0.000    0.004    0.000 ChangeCounter.ipynb:142(update_changes)
        1    0.000    0.000    0.004    0.004 git.py:38(__init__)
     7582    0.004    0.000    0.004    0.000 developer.py:24(__init__)
     1405    0.003    0.000    0.004    0.000 encoding.py:1(force_bytes)
        1    0.000    0.000    0.004    0.004 git.py:82(_open_repository)
      711    0.003    0.000    0.004    0.000 subprocess.py:872(poll)
      711    0.001    0.000    0.004    0.000 warnings.py:159(_add_filter)
    30910    0.004    0.000    0.004    0.000 {built-in method builtins.callable}
    24685    0.003    0.000    0.003    0.000 configparser.py:362(before_get)
      768    0.002    0.000    0.003    0.000 commit.py:600(parents)
    30328    0.003    0.000    0.003    0.000 util.py:117(dst)
     1408    0.003    0.000    0.003    0.000 threading.py:1136(daemon)
       13    0.000    0.000    0.003    0.000 base.py:217(__del__)
     6180    0.003    0.000    0.003    0.000 base.py:265(working_tree_dir)
     1421    0.002    0.000    0.003    0.000 threading.py:239(__enter__)
       13    0.000    0.000    0.003    0.000 base.py:223(close)
     6180    0.003    0.000    0.003    0.000 base.py:278(bare)
       13    0.000    0.000    0.003    0.000 base.py:436(config_reader)
     2785    0.003    0.000    0.003    0.000 __init__.py:1530(getEffectiveLevel)
     6541    0.003    0.000    0.003    0.000 {method 'join' of 'str' objects}
     1404    0.001    0.000    0.003    0.000 base.py:94(__str__)
     6246    0.003    0.000    0.003    0.000 {method 'pop' of 'list' objects}
     6182    0.002    0.000    0.003    0.000 config.py:299(_acquire_lock)
      711    0.003    0.000    0.003    0.000 warnings.py:468(__exit__)
      711    0.001    0.000    0.002    0.000 subprocess.py:1368(_handle_exitstatus)
     1408    0.002    0.000    0.002    0.000 threading.py:966(_stop)
    12798    0.002    0.000    0.002    0.000 {method 'endswith' of 'bytes' objects}
     6903    0.002    0.000    0.002    0.000 {method 'read' of '_io.BytesIO' objects}
       63    0.000    0.000    0.002    0.000 fun.py:29(is_git_dir)
     7666    0.002    0.000    0.002    0.000 {method 'strip' of 'bytes' objects}
     1413    0.001    0.000    0.002    0.000 threading.py:254(_is_owned)
      715    0.002    0.000    0.002    0.000 {method 'remove' of 'list' objects}
     6847    0.002    0.000    0.002    0.000 {method 'end' of '_sre.SRE_Match' objects}
        1    0.000    0.000    0.002    0.002 _base.py:610(__exit__)
    12577    0.002    0.000    0.002    0.000 {method 'reverse' of 'list' objects}
        1    0.000    0.000    0.002    0.002 thread.py:146(shutdown)
     6182    0.002    0.000    0.002    0.000 {built-in method builtins.iter}
    12348    0.002    0.000    0.002    0.000 util.py:155(to_native_path_linux)
     1408    0.001    0.000    0.002    0.000 threading.py:251(_acquire_restore)
     5527    0.002    0.000    0.002    0.000 diff.py:378(rename_from)
     5155    0.002    0.000    0.002    0.000 {method 'get' of 'dict' objects}
     6182    0.002    0.000    0.002    0.000 configparser.py:1179(converters)
      735    0.001    0.000    0.002    0.000 commit.py:515(author)
     1405    0.001    0.000    0.001    0.000 cmd.py:539(__getattr__)
        1    0.000    0.000    0.001    0.001 repository.py:230(<dictcomp>)
     6145    0.001    0.000    0.001    0.000 {method 'start' of '_sre.SRE_Match' objects}
        4    0.000    0.000    0.001    0.000 thread.py:114(submit)
      711    0.001    0.000    0.001    0.000 subprocess.py:778(__del__)
      182    0.001    0.000    0.001    0.000 {built-in method posix.stat}
     1421    0.001    0.000    0.001    0.000 threading.py:242(__exit__)
     1408    0.001    0.000    0.001    0.000 threading.py:248(_release_save)
        3    0.000    0.000    0.001    0.000 config.py:610(write)
      721    0.001    0.000    0.001    0.000 cmd.py:118(dashify)
     4224    0.001    0.000    0.001    0.000 threading.py:506(is_set)
      711    0.001    0.000    0.001    0.000 cmd.py:977(<dictcomp>)
        4    0.000    0.000    0.001    0.000 thread.py:127(_adjust_thread_count)
     2816    0.001    0.000    0.001    0.000 {built-in method _thread.get_ident}
     5527    0.001    0.000    0.001    0.000 diff.py:382(rename_to)
     2817    0.001    0.000    0.001    0.000 {method 'insert' of 'list' objects}
      128    0.000    0.000    0.001    0.000 genericpath.py:39(isdir)
      711    0.001    0.000    0.001    0.000 subprocess.py:203(_cleanup)
      2/1    0.000    0.000    0.001    0.001 config.py:92(flush_changes)
     2828    0.001    0.000    0.001    0.000 {method 'release' of '_thread.lock' objects}
       39    0.000    0.000    0.001    0.000 util.py:332(expand_path)
      131    0.001    0.000    0.001    0.000 posixpath.py:338(normpath)
     1422    0.001    0.000    0.001    0.000 {method 'close' of '_io.BufferedReader' objects}
     6069    0.001    0.000    0.001    0.000 config.py:655(read_only)
      711    0.001    0.000    0.001    0.000 _collections_abc.py:698(__init__)
        8    0.001    0.000    0.001    0.000 {method 'close' of '_io.BufferedWriter' objects}
     1422    0.001    0.000    0.001    0.000 subprocess.py:1386(_internal_poll)
      711    0.001    0.000    0.001    0.000 {method 'rfind' of 'bytes' objects}
        1    0.000    0.000    0.001    0.001 config.py:738(set_value)
      711    0.001    0.000    0.001    0.000 {built-in method posix.WIFSIGNALED}
      735    0.000    0.000    0.001    0.000 git.py:130(get_commit_from_gitpython)
      805    0.001    0.000    0.001    0.000 {method 'replace' of 'str' objects}
      711    0.001    0.000    0.001    0.000 cmd.py:984(<listcomp>)
        1    0.000    0.000    0.001    0.001 base.py:457(config_writer)
     1413    0.001    0.000    0.001    0.000 {method '__enter__' of '_thread.lock' objects}
     2845    0.001    0.000    0.001    0.000 {method 'items' of 'dict' objects}
     1408    0.001    0.000    0.001    0.000 {method 'discard' of 'set' objects}
       13    0.000    0.000    0.001    0.000 configparser.py:826(getboolean)
        4    0.000    0.000    0.001    0.000 util.py:762(_obtain_lock)
        4    0.000    0.000    0.001    0.000 util.py:740(_obtain_lock_or_raise)
        1    0.001    0.001    0.001    0.001 {built-in method posix.open}
       13    0.000    0.000    0.001    0.000 configparser.py:805(_get_conv)
        3    0.000    0.000    0.000    0.000 config.py:571(_write)
      711    0.000    0.000    0.000    0.000 cmd.py:978(<dictcomp>)
        1    0.000    0.000    0.000    0.000 repository.py:44(__init__)
      719    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}
       39    0.000    0.000    0.000    0.000 posixpath.py:376(abspath)
       13    0.000    0.000    0.000    0.000 configparser.py:802(_get)
        2    0.000    0.000    0.000    0.000 pathlib.py:1133(resolve)
       45    0.000    0.000    0.000    0.000 config.py:574(write_section)
     2133    0.000    0.000    0.000    0.000 {built-in method _warnings._filters_mutated}
        5    0.000    0.000    0.000    0.000 _base.py:196(as_completed)
      735    0.000    0.000    0.000    0.000 commit.py:480(__init__)
     1413    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.lock' objects}
       13    0.000    0.000    0.000    0.000 db.py:31(__init__)
        2    0.000    0.000    0.000    0.000 pathlib.py:303(resolve)
        2    0.000    0.000    0.000    0.000 pathlib.py:307(_resolve)
       13    0.000    0.000    0.000    0.000 cmd.py:519(__init__)
        8    0.000    0.000    0.000    0.000 pathlib.py:439(readlink)
        8    0.000    0.000    0.000    0.000 {built-in method posix.readlink}
       41    0.000    0.000    0.000    0.000 genericpath.py:27(isfile)
       13    0.000    0.000    0.000    0.000 loose.py:77(__init__)
      711    0.000    0.000    0.000    0.000 {built-in method posix.WIFEXITED}
        5    0.000    0.000    0.000    0.000 _base.py:174(_yield_finished_futures)
      711    0.000    0.000    0.000    0.000 {method 'items' of 'collections.OrderedDict' objects}
        1    0.000    0.000    0.000    0.000 repository.py:246(_split_in_chunks)
      711    0.000    0.000    0.000    0.000 {method 'pop' of 'dict' objects}
      711    0.000    0.000    0.000    0.000 {built-in method posix.WEXITSTATUS}
       13    0.000    0.000    0.000    0.000 genericpath.py:16(exists)
        5    0.000    0.000    0.000    0.000 queue.py:115(put)
       14    0.000    0.000    0.000    0.000 base.py:418(_get_config_path)
       13    0.000    0.000    0.000    0.000 mman.py:410(collect)
     1408    0.000    0.000    0.000    0.000 {method 'locked' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 git.py:88(_discover_main_branch)
      702    0.000    0.000    0.000    0.000 diff.py:63(_process_diff_args)
        1    0.000    0.000    0.000    0.000 base.py:713(active_branch)
      430    0.000    0.000    0.000    0.000 ChangeCounter.ipynb:152(update_elems)
       13    0.000    0.000    0.000    0.000 re.py:179(search)
       24    0.000    0.000    0.000    0.000 _bootlocale.py:23(getpreferredencoding)
       13    0.000    0.000    0.000    0.000 base.py:108(__init__)
        1    0.000    0.000    0.000    0.000 thread.py:91(__init__)
       13    0.000    0.000    0.000    0.000 _collections_abc.py:664(__contains__)
        1    0.000    0.000    0.000    0.000 symbolic.py:266(_get_reference)
       45    0.000    0.000    0.000    0.000 config.py:192(items_all)
        7    0.000    0.000    0.000    0.000 subprocess.py:1602(terminate)
        4    0.000    0.000    0.000    0.000 _base.py:405(result)
       45    0.000    0.000    0.000    0.000 config.py:194(<listcomp>)
       63    0.000    0.000    0.000    0.000 posixpath.py:64(isabs)
       39    0.000    0.000    0.000    0.000 posixpath.py:232(expanduser)
        4    0.000    0.000    0.000    0.000 weakref.py:356(remove)
       13    0.000    0.000    0.000    0.000 re.py:286(_compile)
       85    0.000    0.000    0.000    0.000 config.py:733(_value_to_string)
       12    0.000    0.000    0.000    0.000 cmd.py:887(transform_kwarg)
       13    0.000    0.000    0.000    0.000 mman.py:305(_collect_lru_region)
        4    0.000    0.000    0.000    0.000 _base.py:312(__init__)
        2    0.000    0.000    0.000    0.000 util.py:767(_release_lock)
        1    0.000    0.000    0.000    0.000 util.py:103(rmfile)
        5    0.000    0.000    0.000    0.000 queue.py:206(_put)
      129    0.000    0.000    0.000    0.000 config.py:185(getall)
       12    0.000    0.000    0.000    0.000 base.py:174(abspath)
        5    0.000    0.000    0.000    0.000 threading.py:334(notify)
        1    0.000    0.000    0.000    0.000 queue.py:27(__init__)
       39    0.000    0.000    0.000    0.000 posixpath.py:285(expandvars)
        1    0.000    0.000    0.000    0.000 {built-in method posix.remove}
        8    0.000    0.000    0.000    0.000 {method '__enter__' of '_thread.RLock' objects}
        3    0.000    0.000    0.000    0.000 config.py:188(items)
        3    0.000    0.000    0.000    0.000 config.py:190(<listcomp>)
       37    0.000    0.000    0.000    0.000 cmd.py:306(is_cygwin)
        7    0.000    0.000    0.000    0.000 subprocess.py:1596(send_signal)
       24    0.000    0.000    0.000    0.000 {built-in method _locale.nl_langinfo}
       13    0.000    0.000    0.000    0.000 configparser.py:1151(_convert_to_boolean)
        1    0.000    0.000    0.000    0.000 conf.py:24(__init__)
       12    0.000    0.000    0.000    0.000 base.py:243(__ne__)
        7    0.000    0.000    0.000    0.000 {built-in method posix.kill}
       13    0.000    0.000    0.000    0.000 base.py:67(__init__)
        1    0.000    0.000    0.000    0.000 conf.py:77(sanity_check_filters)
        1    0.000    0.000    0.000    0.000 symbolic.py:650(from_path)
       85    0.000    0.000    0.000    0.000 encoding.py:11(force_text)
        1    0.000    0.000    0.000    0.000 configparser.py:890(set)
        4    0.000    0.000    0.000    0.000 weakref.py:406(__setitem__)
      115    0.000    0.000    0.000    0.000 {built-in method _stat.S_ISDIR}
       28    0.000    0.000    0.000    0.000 {method 'find' of 'bytes' objects}
        4    0.000    0.000    0.000    0.000 threading.py:74(RLock)
        1    0.000    0.000    0.000    0.000 _base.py:152(_create_and_install_waiters)
        4    0.000    0.000    0.000    0.000 _base.py:382(__get_result)
       37    0.000    0.000    0.000    0.000 util.py:292(is_cygwin_git)
        7    0.000    0.000    0.000    0.000 conf.py:36(set_value)
       12    0.000    0.000    0.000    0.000 base.py:238(__eq__)
       28    0.000    0.000    0.000    0.000 {method 'rstrip' of 'bytes' objects}
        1    0.000    0.000    0.000    0.000 _base.py:74(__init__)
        4    0.000    0.000    0.000    0.000 {method 'remove' of 'set' objects}
        1    0.000    0.000    0.000    0.000 conf.py:287(_check_timezones)
        1    0.000    0.000    0.000    0.000 _base.py:141(__init__)
        1    0.000    0.000    0.000    0.000 util.py:728(__del__)
        1    0.000    0.000    0.000    0.000 conf.py:191(build_args)
       24    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
        1    0.000    0.000    0.000    0.000 _base.py:58(__init__)
        1    0.000    0.000    0.000    0.000 {built-in method math.ceil}
        1    0.000    0.000    0.000    0.000 git.py:316(__del__)
        1    0.000    0.000    0.000    0.000 conf.py:65(_check_only_one_from_commit)
        1    0.000    0.000    0.000    0.000 conf.py:293(_replace_timezone)
       13    0.000    0.000    0.000    0.000 {method 'values' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 thread.py:45(__init__)
        2    0.000    0.000    0.000    0.000 repository.py:144(_is_remote)
       27    0.000    0.000    0.000    0.000 {built-in method _stat.S_ISREG}
        1    0.000    0.000    0.000    0.000 contextlib.py:157(helper)
        1    0.000    0.000    0.000    0.000 queue.py:199(_init)
       13    0.000    0.000    0.000    0.000 {built-in method builtins.issubclass}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'datetime.datetime' objects}
        1    0.000    0.000    0.000    0.000 _base.py:144(__enter__)
        1    0.000    0.000    0.000    0.000 reference.py:35(__init__)
       12    0.000    0.000    0.000    0.000 cmd.py:906(<lambda>)
        3    0.000    0.000    0.000    0.000 config.py:647(_assure_writable)
        8    0.000    0.000    0.000    0.000 util.py:735(_has_lock)
        8    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 contextlib.py:59(__init__)
        1    0.000    0.000    0.000    0.000 _base.py:148(__exit__)
        2    0.000    0.000    0.000    0.000 util.py:731(_lock_file_path)
        3    0.000    0.000    0.000    0.000 git.py:62(repo)
        1    0.000    0.000    0.000    0.000 conf.py:71(_check_only_one_to_commit)
        2    0.000    0.000    0.000    0.000 conf.py:181(only_one_filter)
        4    0.000    0.000    0.000    0.000 {method 'release' of '_thread.RLock' objects}
        2    0.000    0.000    0.000    0.000 pathlib.py:1434(expanduser)
        5    0.000    0.000    0.000    0.000 _base.py:221(<genexpr>)
        1    0.000    0.000    0.000    0.000 reference.py:86(name)
        1    0.000    0.000    0.000    0.000 conf.py:54(_sanity_check_repos)
        1    0.000    0.000    0.000    0.000 conf.py:165(get_ending_commit)
        1    0.000    0.000    0.000    0.000 __init__.py:230(utcoffset)
        4    0.000    0.000    0.000    0.000 {method 'lstrip' of 'str' objects}
        4    0.000    0.000    0.000    0.000 {method 'acquire' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 pathlib.py:777(name)
        1    0.000    0.000    0.000    0.000 configparser.py:663(has_section)
        1    0.000    0.000    0.000    0.000 util.py:724(__init__)
        1    0.000    0.000    0.000    0.000 conf.py:114(_check_correct_filters_order)
        1    0.000    0.000    0.000    0.000 conf.py:142(get_starting_commit)
        4    0.000    0.000    0.000    0.000 {method 'remove' of 'collections.deque' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 pathlib.py:919(is_absolute)
        1    0.000    0.000    0.000    0.000 _base.py:607(__enter__)
        1    0.000    0.000    0.000    0.000 configparser.py:365(before_set)
        2    0.000    0.000    0.000    0.000 conf.py:189(<listcomp>)

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 it the method we called in the first place. This calls a method mine() in the ChangeCounter class, which does all the work.

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.

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 underlying PyDriller 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.

Sampling Execution Profiles

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.

One profiler for Python that implements such sampling is Scalene – a high-performance, high-precision CPU, GPU, and memory profiler for Python. We can invoke it on our example as follows:

$ scalene --html test.py > scalene-out.html

where test.py is a script that again invokes

debuggingbook_change_counter(ChangeCounter)

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 browswer, we see these lines:

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.

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.

Improving Performance

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:

  • 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.

  • 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.

  • 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.

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.

But beyond these points, remember the famous words by Donald J. Knuth:

from bookutils import quiz

Quiz

Donald J. Knuth said: "Premature optimization..."





This quote should always remind us that after a good design, you should always first measure and then optimize.

Building a Profiler

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.

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).

from Intro_Debugging import remove_html_markup
print_content(inspect.getsource(remove_html_markup), '.py',
              start_line_number=238)
238  def remove_html_markup(s):  # type: ignore
239      tag = False
240      quote = False
241      out = ""
242  
243      for c in s:
244          assert tag or not quote
245  
246          if c == '<' and not quote:
247              tag = True
248          elif c == '>' and not quote:
249              tag = False
250          elif (c == '"' or c == "'") and tag:
251              quote = not quote
252          elif not tag:
253              out = out + c
254  
255      return out

We introduce a class PerformanceTracer that tracks, for each line in the code:

  • how often it was executed (hits), and
  • how much time was spent during its execution (time).

To this end, we make use of our Timer class, which measures time, and the Tracer class from the chapter on tracing, which allows us to track every line of the program as it is being executed.

from Tracer import Tracer

In PerfomanceTracker, the attributes hits and time are mappings indexed by unique locations – that is, pairs of function name and line number.

Location = Tuple[str, int]
class PerformanceTracer(Tracer):
    """Trace time and #hits for individual program lines"""

    def __init__(self) -> None:
        """Constructor."""
        super().__init__()
        self.reset_timer()
        self.hits: Dict[Location, int] = {}
        self.time: Dict[Location, float] = {}

    def reset_timer(self) -> None:
        self.timer = Timer.Timer()

As common in this book, we want to use PerformanceTracer in a with-block around the function call(s) to be tracked:

with PerformanceTracer() as perf_tracer:
    function(...)

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.

from types import FrameType
class PerformanceTracer(PerformanceTracer):
    def __enter__(self) -> Any:
        """Enter a `with` block."""
        super().__enter__()
        self.reset_timer()
        return self

The traceit() method extracts the current location. It increases the corresponding hits value by 1, and adds the elapsed time to the corresponding time.

class PerformanceTracer(PerformanceTracer):
    def traceit(self, frame: FrameType, event: str, arg: Any) -> None:
        """Tracing function; called for every line."""
        t = self.timer.elapsed_time()
        location = (frame.f_code.co_name, frame.f_lineno)

        self.hits.setdefault(location, 0)
        self.time.setdefault(location, 0.0)
        self.hits[location] += 1
        self.time[location] += t

        self.reset_timer()

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:

with PerformanceTracer() as perf_tracer:
    for i in range(10000):
        s = remove_html_markup('<b>foo</b>')

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 <b>foo</b>, once for the final check, and all of this 10,000 times.

perf_tracer.hits
{('__init__', 17): 1,
 ('__init__', 19): 1,
 ('clock', 8): 1,
 ('clock', 12): 2,
 ('__init__', 20): 2,
 ('remove_html_markup', 238): 10000,
 ('remove_html_markup', 239): 10000,
 ('remove_html_markup', 240): 10000,
 ('remove_html_markup', 241): 10000,
 ('remove_html_markup', 243): 110000,
 ('remove_html_markup', 244): 100000,
 ('remove_html_markup', 246): 100000,
 ('remove_html_markup', 247): 20000,
 ('remove_html_markup', 248): 80000,
 ('remove_html_markup', 250): 60000,
 ('remove_html_markup', 252): 60000,
 ('remove_html_markup', 249): 20000,
 ('remove_html_markup', 253): 30000,
 ('remove_html_markup', 255): 20000}

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.

perf_tracer.time
{('__init__', 17): 0.0001059240021277219,
 ('__init__', 19): 2.73999830824323e-06,
 ('clock', 8): 2.0500010577961802e-06,
 ('clock', 12): 5.755999154644087e-06,
 ('__init__', 20): 3.058001311728731e-06,
 ('remove_html_markup', 238): 0.023277391002920922,
 ('remove_html_markup', 239): 0.02008059803483775,
 ('remove_html_markup', 240): 0.019305240031826543,
 ('remove_html_markup', 241): 0.018249372093123384,
 ('remove_html_markup', 243): 0.1731851907206874,
 ('remove_html_markup', 244): 0.15601146045446512,
 ('remove_html_markup', 246): 0.15702730580596835,
 ('remove_html_markup', 247): 0.03183129778699367,
 ('remove_html_markup', 248): 0.12509353636050946,
 ('remove_html_markup', 250): 0.0944255334798072,
 ('remove_html_markup', 252): 0.09768310593790375,
 ('remove_html_markup', 249): 0.031472253907850245,
 ('remove_html_markup', 253): 0.04686223630778841,
 ('remove_html_markup', 255): 0.03130254888674244}

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.

Visualizing Performance Metrics

In the chapter on statistical debugging, 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.

Collecting Time Spent

from StatisticalDebugger import CoverageCollector, SpectrumDebugger

The MetricCollector class is an abstract superclass that provides an interface to access a particular metric.

class MetricCollector(CoverageCollector):
    """Abstract superclass for collecting line-specific metrics"""

    def metric(self, event: Any) -> Optional[float]:
        """Return a metric for an event, or none."""
        return None

    def all_metrics(self, func: str) -> List[float]:
        """Return all metric for a function `func`."""
        return []

Given these metrics, we can also compute sums and maxima for a single function.

class MetricCollector(MetricCollector):
    def total(self, func: str) -> float:
        return sum(self.all_metrics(func))

    def maximum(self, func: str) -> float:
        return max(self.all_metrics(func))

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.

class TimeCollector(MetricCollector):
    """Collect time executed for each line"""

    def __init__(self) -> None:
        """Constructor"""
        super().__init__()
        self.reset_timer()
        self.time: Dict[Location, float] = {}
        self.add_items_to_ignore([Timer.Timer, Timer.clock])

    def collect(self, frame: FrameType, event: str, arg: Any) -> None:
        """Invoked for every line executed. Accumulate time spent."""
        t = self.timer.elapsed_time()
        super().collect(frame, event, arg)
        location = (frame.f_code.co_name, frame.f_lineno)

        self.time.setdefault(location, 0.0)
        self.time[location] += t

        self.reset_timer()

    def reset_timer(self) -> None:
        self.timer = Timer.Timer()

    def __enter__(self) -> Any:
        super().__enter__()
        self.reset_timer()
        return self

The metric() and all_metrics() methods accumulate the metric (time taken) for an individual function:

class TimeCollector(TimeCollector):
    def metric(self, location: Any) -> Optional[float]:
        if location in self.time:
            return self.time[location]
        else:
            return None

    def all_metrics(self, func: str) -> List[float]:
        return [time
                for (func_name, lineno), time in self.time.items()
                if func_name == func]

Here's how to use TimeCollector() – again, in a with block:

with TimeCollector() as collector:
    for i in range(100):
        s = remove_html_markup('<b>foo</b>')

The time attribute holds the time spent in each line:

for location, time_spent in collector.time.items():
    print(location, time_spent)
('remove_html_markup', 238) 0.0004949449939886108
('remove_html_markup', 239) 0.0003431719960644841
('remove_html_markup', 240) 0.00036031701529282145
('remove_html_markup', 241) 0.0003080779824813362
('remove_html_markup', 243) 0.0034793319646269083
('remove_html_markup', 244) 0.0030123600372462533
('remove_html_markup', 246) 0.003005930033395998
('remove_html_markup', 247) 0.0005973920015094336
('remove_html_markup', 248) 0.002322773994819727
('remove_html_markup', 250) 0.0017448210528527852
('remove_html_markup', 252) 0.0018759159720502794
('remove_html_markup', 249) 0.0005653560001519509
('remove_html_markup', 253) 0.0008377570593438577
('remove_html_markup', 255) 0.0006236640219867695

And we can also create a total for an entire function:

collector.total('remove_html_markup')
0.019571814125811215

Visualizing Time Spent

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.

class MetricDebugger(SpectrumDebugger):
    """Visualize a metric"""

    def metric(self, location: Location) -> float:
        sum = 0.0
        for outcome in self.collectors:
            for collector in self.collectors[outcome]:
                assert isinstance(collector, MetricCollector)
                m = collector.metric(location)
                if m is not None:
                    sum += m

        return sum

    def total(self, func_name: str) -> float:
        total = 0.0
        for outcome in self.collectors:
            for collector in self.collectors[outcome]:
                assert isinstance(collector, MetricCollector)
                total += sum(collector.all_metrics(func_name))

        return total

    def maximum(self, func_name: str) -> float:
        maximum = 0.0
        for outcome in self.collectors:
            for collector in self.collectors[outcome]:
                assert isinstance(collector, MetricCollector)
                maximum = max(maximum, 
                              max(collector.all_metrics(func_name)))

        return maximum

    def suspiciousness(self, location: Location) -> float:
        func_name, _ = location
        return self.metric(location) / self.total(func_name)

    def color(self, location: Location) -> str:
        func_name, _ = location
        hue = 240  # blue
        saturation = 100  # fully saturated
        darkness = self.metric(location) / self.maximum(func_name)
        lightness = 100 - darkness * 25
        return f"hsl({hue}, {saturation}%, {lightness}%)"

    def tooltip(self, location: Location) -> str:
        return f"{super().tooltip(location)} {self.metric(location)}"

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.

class PerformanceDebugger(MetricDebugger):
    """Collect and visualize a metric"""

    def __init__(self, collector_class: Type, log: bool = False):
        assert issubclass(collector_class, MetricCollector)
        super().__init__(collector_class, log=log)

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.

with PerformanceDebugger(TimeCollector) as debugger:
    for i in range(100):
        s = remove_html_markup('<b>foo</b>')
print(debugger)
 238   2% def remove_html_markup(s):  # type: ignore
 239   2%     tag = False
 240   2%     quote = False
 241   1%     out = ""
 242   0%
 243  16%     for c in s:
 244  15%         assert tag or not quote
 245   0%
 246  15%         if c == '<' and not quote:
 247   3%             tag = True
 248  12%         elif c == '>' and not quote:
 249   3%             tag = False
 250   9%         elif (c == '"' or c == "'") and tag:
 251   0%             quote = not quote
 252   9%         elif not tag:
 253   4%             out = out + c
 254   0%
 255   2%     return out

However, we can also visualize these percentages, using shades of blue to indicate those lines most time spent in:

debugger
 238 def remove_html_markup(s):  # type: ignore
 239     tag = False
 240     quote = False
 241     out = ""
 242  
 243     for c in s:
 244         assert tag or not quote
 245  
 246         if c == '<' and not quote:
 247             tag = True
 248         elif c == '>' and not quote:
 249             tag = False
 250         elif (c == '"' or c == "'") and tag:
 251             quote = not quote
 252         elif not tag:
 253             out = out + c
 254  
 255     return out

Other Metrics

Our framework is flexible enough to collect (and visualize) arbitrary metrics. This HitCollector class, for instance, collects how often a line is being executed.

class HitCollector(MetricCollector):
    """Collect how often a line is executed"""

    def __init__(self) -> None:
        super().__init__()
        self.hits: Dict[Location, int] = {}

    def collect(self, frame: FrameType, event: str, arg: Any) -> None:
        super().collect(frame, event, arg)
        location = (frame.f_code.co_name, frame.f_lineno)

        self.hits.setdefault(location, 0)
        self.hits[location] += 1

    def metric(self, location: Location) -> Optional[int]:
        if location in self.hits:
            return self.hits[location]
        else:
            return None

    def all_metrics(self, func: str) -> List[float]:
        return [hits
                for (func_name, lineno), hits in self.hits.items()
                if func_name == func]

We can plug in this class into PerformanceDebugger to obtain a distribution of lines executed:

with PerformanceDebugger(HitCollector) as debugger:
    for i in range(100):
        s = remove_html_markup('<b>foo</b>')

In total, during this call to remove_html_markup(), there are 6,400 lines executed:

debugger.total('remove_html_markup')
6400.0

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.

print(debugger)
 238   1% def remove_html_markup(s):  # type: ignore
 239   1%     tag = False
 240   1%     quote = False
 241   1%     out = ""
 242   0%
 243  17%     for c in s:
 244  15%         assert tag or not quote
 245   0%
 246  15%         if c == '<' and not quote:
 247   3%             tag = True
 248  12%         elif c == '>' and not quote:
 249   3%             tag = False
 250   9%         elif (c == '"' or c == "'") and tag:
 251   0%             quote = not quote
 252   9%         elif not tag:
 253   4%             out = out + c
 254   0%
 255   3%     return out
debugger
 238 def remove_html_markup(s):  # type: ignore
 239     tag = False
 240     quote = False
 241     out = ""
 242  
 243     for c in s:
 244         assert tag or not quote
 245  
 246         if c == '<' and not quote:
 247             tag = True
 248         elif c == '>' and not quote:
 249             tag = False
 250         elif (c == '"' or c == "'") and tag:
 251             quote = not quote
 252         elif not tag:
 253             out = out + c
 254  
 255     return out

Integrating with Delta Debugging

Besides identifying causes for performance issues in the code, one may also search for causes in the input, using Delta Debugging. 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.

Here is a variant of remove_html_markup() that introduces a (rather obvious) performance issue.

import time
def remove_html_markup_ampersand(s: str) -> str:
    tag = False
    quote = False
    out = ""

    for c in s:
        assert tag or not quote

        if c == '&':
            time.sleep(0.1)  # <-- the obvious performance issue

        if c == '<' and not quote:
            tag = True
        elif c == '>' and not quote:
            tag = False
        elif (c == '"' or c == "'") and tag:
            quote = not quote
        elif not tag:
            out = out + c

    return out

We can easily trigger this issue by measuring time taken:

with Timer.Timer() as t:
    remove_html_markup_ampersand('&&&')
t.elapsed_time()
0.3070877220015973

Let us set up a test that checks whether the performance issue is present.

def remove_html_test(s: str) -> None:
    with Timer.Timer() as t:
        remove_html_markup_ampersand(s)
    assert t.elapsed_time() < 0.1

We can now apply delta debugging to determine a minimum input that causes the failure:

s_fail = '<b>foo&amp;</b>'
with DeltaDebugger.DeltaDebugger() as dd:
    remove_html_test(s_fail)
dd.min_args()
{'s': '&'}

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:

s_pass = dd.max_args()
s_pass
{'s': '<b>fooamp;</b>'}

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.

Lessons Learned

  • To measure performance,
    • instrument the code such that the time taken per function (or line) is collected; or
    • sample the execution that at regular intervals, the active call stack is collected.
  • To make code performant, focus on efficient algorithms, efficient data types, and sufficient abstraction such that you can replace them by alternatives.
  • Beyond efficient algorithms and data types, do not optimize before measuring.

Next Steps

This chapter concludes the part on abstracting failures. The next part will focus on

Background

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.

The Wikipedia articles on profiling) and performance analysis tools provide several additional resources on profiling tools and how to apply them in practice.

Exercises

Exercise 1: Profiling Memory Usage

The Python tracemalloc module allows to track memory usage during execution. Between tracemalloc.start() and tracemalloc.end(), use tracemalloc.get_traced_memory() to obtain how much memory is currently being consumed:

import tracemalloc
tracemalloc.start()
current_size, peak_size = tracemalloc.get_traced_memory()
current_size
18723
tracemalloc.stop()

Create a subclass of MetricCollector named MemoryCollector. Have 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.

Exercise 2: Statistical Performance Debugging

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, 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.

Creative Commons License The content of this project is licensed under the Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License. The source code that is part of the content, as well as the source code used to format and display that content is licensed under the MIT License. Last change: 2021-05-12 17:03:19+02:00CiteImprint