diff --git a/_posts/2024-03-26-python-profiling.md b/_posts/2024-03-26-python-profiling.md new file mode 100644 index 0000000..83cd4c6 --- /dev/null +++ b/_posts/2024-03-26-python-profiling.md @@ -0,0 +1,100 @@ +--- +layout: post +title: How to Find Python Performance Problems +categories: + - How-To Guides + - Python +tags: + - Software Engineering + - Software Performance + - Python +image: + path: /assets/img/posts/python_profiling/sorting.profile.svg + alt: A flame graph showing the performance of different parts of a Python program. +--- + +When a Python program is running too slowly, use a profiler to measure which parts of the code are hurting performance the most. + +## Measure Code Performance with `cProfile` + +Start by writing a [decorator](https://realpython.com/primer-on-python-decorators/) which will add profiling metrics to the decorated function: +```python +# Credit: https://stackoverflow.com/a/5376616/14765128 +import cProfile # Python's built-in profiling tool + +def profile(output_file_path): + def inner(func): + def wrapper(*args, **kwargs): + prof = cProfile.Profile() + retval = prof.runcall(func, *args, **kwargs) + prof.dump_stats(output_file_path) + return retval + return wrapper + return inner +``` + +Then apply that decorator to the function which is running slowly. +```python +@profile("path/to/output.profile") +def my_slow_function(): + ... +``` + +Now, when you execute `my_slow_function` a performance profile will be saved to `"path/to/output.profile"`. + +## Generate a Flame Graph of Profiling Metrics + +Download the [flameprof](https://github.com/baverman/flameprof) tool +```bash +wget https://raw.githubusercontent.com/baverman/flameprof/master/flameprof.py -o flameprof.py +``` + +Create a flame graph. +```bash +python flameprof.py "path/to/output.profile" --width 1800 > "output.profile.svg" +``` + + + +## Review the Flame Graph to Identify Performance Bottlenecks + +Here's a sample [flame graph](https://www.brendangregg.com/flamegraphs.html) for a function which generates a list of 250 random integers, then sorts the list twice -- first with [bubble sort](https://github.com/TheAlgorithms/Python/blob/master/sorts/bubble_sort.py), then again with [merge sort](https://github.com/TheAlgorithms/Python/blob/master/sorts/merge_sort.py). + +![A flame graph showing that bubble sort takes longer to run than merge sort](/assets/img/posts/python_profiling/sorting.profile.svg){: width="600" } +_A flame graph showing that bubble sort is slower than merge sort. [[Source Code]](/assets/code/python_profiling_sorting.py)_ + +**The top half of the flame graph helps you find which line(s) of code in your function are the slowest.** It roughly shows the function call stack over time. Longer bars indicate more time spent in the function call. Taller peaks indicate a deeper function call stack. A split peak indicates that the function called multiple other functions. + +In the example above, you can clearly see that `bubble_sort_iterative` took longer than `merge_sort`. You can also see that `merge_sort` called other functions while `bubble_sort_iterative` did not. + +**The bottom half of the flame graph helps you find which functions contribute the most to the total runtime, even if they were invoked from different places.** Longer bars indicate more time spent in the function call. Deeper valleys indicate that the function was called deeper in the call stack. A split valley indicates that the function was called from multiple places. In the example above, you can see that `merge_sort` was called from two places -- `sort_a_random_list` and `merge_sort` itself -- while `merge` was only ever called from `merge_sort`. You can also see that more time was spent executing code in `merge` than in `merge_sort`. + +You can also see even more detailed information by hovering over any bar in the flame graph. For example, hovering over the blue bar for `merge_sort` shows the following tooltip: +``` +/jhale.dev/posts/python-profiling/sample.py:41:merge_sort 11.37% (305 1 0.0002682973988063135 0.0008462241322068796) +``` + +The first section shows where the function is located in your code `/path:line-number:function_name`. In this case, the `merge_sort` function was found on line 41 of a file called `sample.py` + +The percent indicates what percent of the total profiled runtime was spent in that function. In this case, recursive calls to `merge_sort` accounted for 11.37% of the total recorded runtime. + +The parentheses show `(calls_total calls_primitive duration_excluding_subcalls duration_total)`. In this case, the `merge_sort` function was called 305 times, but only one of those calls was "primitive" (i.e. non-recursive). Excluding calls to sub-functions, `merge_sort` completed its work in 0.000268... seconds, compared to a total runtime of 0.000846... seconds when including calls to sub-functions (including recursive calls). + +## Conclusion + +Now you have a new tool for tracking down performance issues in your Python applications! + +Use the comments below to share your experiences with improving the performance of Python programs! diff --git a/assets/code/python_profiling_sorting.py b/assets/code/python_profiling_sorting.py new file mode 100644 index 0000000..fb8b184 --- /dev/null +++ b/assets/code/python_profiling_sorting.py @@ -0,0 +1,60 @@ +# Companion file to https://jhale.dev/posts/python-profiling/ + +import cProfile # Python's built-in profiling tool + +def profile(output_file_path): + # Credit: https://stackoverflow.com/a/5376616/14765128 + def inner(func): + def wrapper(*args, **kwargs): + prof = cProfile.Profile() + retval = prof.runcall(func, *args, **kwargs) + prof.dump_stats(output_file_path) + return retval + return wrapper + return inner + + +###################### +# Demonstration Code: + +from random import randint + +@profile("sorting.profile") +def sort_a_random_list(): + ints = [randint(0, 1000) for _ in range(250)] + sorted_ints_bubble = bubble_sort_iterative([i for i in ints]) + sorted_ints_merged = merge_sort([i for i in ints]) + + +def bubble_sort_iterative(collection: list) -> list: + # https://github.com/TheAlgorithms/Python/blob/master/sorts/bubble_sort.py + length = len(collection) + for i in reversed(range(length)): + swapped = False + for j in range(i): + if collection[j] > collection[j + 1]: + swapped = True + collection[j], collection[j + 1] = collection[j + 1], collection[j] + if not swapped: + break # Stop iteration if the collection is sorted. + return collection + + +def merge_sort(collection: list) -> list: + # https://github.com/TheAlgorithms/Python/blob/master/sorts/merge_sort.py + def merge(left: list, right: list) -> list: + result = [] + while left and right: + result.append(left.pop(0) if left[0] <= right[0] else right.pop(0)) + result.extend(left) + result.extend(right) + return result + + if len(collection) <= 1: + return collection + mid_index = len(collection) // 2 + return merge(merge_sort(collection[:mid_index]), merge_sort(collection[mid_index:])) + + +if __name__ == "__main__": + sort_a_random_list() \ No newline at end of file diff --git a/assets/img/posts/python_profiling/sorting.profile.svg b/assets/img/posts/python_profiling/sorting.profile.svg new file mode 100644 index 0000000..005842c --- /dev/null +++ b/assets/img/posts/python_profiling/sorting.profile.svg @@ -0,0 +1,480 @@ + + + + + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 99.99% (1 1 2.1675e-05 0.007443303) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 15.43% (1 1 0.000108981 0.0011484610000000001) + + <listcomp> + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 13.96% (250 250 0.000131715 0.00103948) + + randint + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:290:randrange 12.19% (250 250 0.000275276 0.000907765) + + randrange + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:237:_randbelow_with_getrandbits 8.50% (250 250 0.000418002 0.0006324890000000001) + + _randbelow_with_getrandbits + + + ~:0:<method 'bit_length' of 'int' objects> 2.24% (250 250 0.00016644 0.00016644) + + <method 'bit_length' of 'int' objects> + + + ~:0:<method 'getrandbits' of '_random.Random' objects> 0.65% (256 256 4.8047e-05 4.8047e-05) + + <method 'getrandbits' of '_random.Random' objects> + + + /jhale.dev/posts/python-profiling/sample.py:23:<listcomp> 0.12% (1 1 9.284000000000001e-06 9.284000000000001e-06) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:24:<listcomp> 0.14% (1 1 1.0298e-05 1.0298e-05) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:27:bubble_sort_iterative 63.83% (1 1 0.004751223000000001 0.004751778) + + bubble_sort_iterative + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 20.17% (1 1 8.152000000000001e-06 0.0015018070000000002) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 11.37% (305 1 0.0002682973988063135 0.0008462241322068796) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 4.40% (118 0 0.00010380994223699696 0.0003274220274769278) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 3.22% (59 59 0.00016565853392311086 0.00023963464929254683) + + merge + + + ~:0:<method 'append' of 'list' objects> 0.34% (396 396 2.543328521769674e-05 2.543328521769674e-05) + + <method 'append' of 'list' objects> + + + ~:0:<method 'extend' of 'list' objects> 0.13% (118 118 9.647934342260665e-06 9.647934342260665e-06) + + <method 'extend' of 'list' objects> + + + ~:0:<method 'pop' of 'list' objects> 0.52% (396 396 3.889489580947857e-05 3.889489580947857e-05) + + <method 'pop' of 'list' objects> + + + ~:0:<built-in method builtins.len> 0.15% (177 177 1.0870056631091483e-05 1.0870056631091483e-05) + + <built-in method builtins.len> + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 8.32% (153 153 0.00042814544333498347 0.0006193371432793258) + + merge + + + ~:0:<method 'append' of 'list' objects> 0.88% (1024 1024 6.573247340248689e-05 6.573247340248689e-05) + + <method 'append' of 'list' objects> + + + ~:0:<method 'extend' of 'list' objects> 0.33% (305 305 2.4935142358263586e-05 2.4935142358263586e-05) + + <method 'extend' of 'list' objects> + + + ~:0:<method 'pop' of 'list' objects> 1.35% (1024 1024 0.00010052408418359183 0.00010052408418359183) + + <method 'pop' of 'list' objects> + + + ~:0:<built-in method builtins.len> 0.38% (459 459 2.8093724513795e-05 2.8093724513795e-05) + + <built-in method builtins.len> + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:237:_randbelow_with_getrandbits 5.62% (250 250 0.000418002 0.0006324890000000001) + + _randbelow_with_getrandbits + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:290:randrange 5.62% (250 250 0.000418002 0.0006324890000000001) + + randrange + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 3.70% (250 250 0.000275276 0.000907765) + + randint + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.77% (250 250 0.000131715 0.00103948) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:290:randrange 3.70% (250 250 0.000275276 0.000907765) + + randrange + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 3.70% (250 250 0.000275276 0.000907765) + + randint + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.77% (250 250 0.000131715 0.00103948) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 1.77% (250 250 0.000131715 0.00103948) + + randint + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.77% (250 250 0.000131715 0.00103948) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.29% (1 1 2.1675e-05 0.007443303) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.46% (1 1 0.000108981 0.0011484610000000001) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:23:<listcomp> 0.12% (1 1 9.284000000000001e-06 9.284000000000001e-06) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.12% (1 1 9.284000000000001e-06 9.284000000000001e-06) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:24:<listcomp> 0.14% (1 1 1.0298e-05 1.0298e-05) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.14% (1 1 1.0298e-05 1.0298e-05) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:27:bubble_sort_iterative 63.82% (1 1 0.004751223000000001 0.004751778) + + bubble_sort_iterative + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 63.82% (1 1 0.004751223000000001 0.004751778) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.99% (1 499 0.00044577500000000003 0.0015018070000000002) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 9.38% (249 249 0.0006983530000000001 0.001010208) + + merge + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 9.38% (249 249 0.0006983530000000001 0.001010208) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + ~:0:<built-in method builtins.len> 0.62% (749 749 4.6379000000000004e-05 4.6379000000000004e-05) + + <built-in method builtins.len> + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 0.62% (748 748 4.5824e-05 4.5824e-05) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + ~:0:<method 'append' of 'list' objects> 1.44% (1671 1671 0.000107217 0.000107217) + + <method 'append' of 'list' objects> + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 1.44% (1671 1671 0.000107217 0.000107217) + + merge + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 9.38% (249 249 0.0006983530000000001 0.001010208) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + ~:0:<method 'bit_length' of 'int' objects> 2.24% (250 250 0.00016644 0.00016644) + + <method 'bit_length' of 'int' objects> + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:237:_randbelow_with_getrandbits 2.24% (250 250 0.00016644 0.00016644) + + _randbelow_with_getrandbits + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:290:randrange 5.62% (250 250 0.000418002 0.0006324890000000001) + + randrange + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 3.70% (250 250 0.000275276 0.000907765) + + randint + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.77% (250 250 0.000131715 0.00103948) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + ~:0:<method 'extend' of 'list' objects> 0.55% (498 498 4.0672e-05 4.0672e-05) + + <method 'extend' of 'list' objects> + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 0.55% (498 498 4.0672e-05 4.0672e-05) + + merge + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 9.38% (249 249 0.0006983530000000001 0.001010208) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + ~:0:<method 'getrandbits' of '_random.Random' objects> 0.65% (256 256 4.8047e-05 4.8047e-05) + + <method 'getrandbits' of '_random.Random' objects> + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:237:_randbelow_with_getrandbits 0.65% (256 256 4.8047e-05 4.8047e-05) + + _randbelow_with_getrandbits + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:290:randrange 5.62% (250 250 0.000418002 0.0006324890000000001) + + randrange + + + /jhale.dev/posts/.pyenv/versions/3.9.18/lib/python3.9/random.py:334:randint 3.70% (250 250 0.000275276 0.000907765) + + randint + + + /jhale.dev/posts/python-profiling/sample.py:22:<listcomp> 1.77% (250 250 0.000131715 0.00103948) + + <listcomp> + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 1.46% (1 1 0.000108981 0.0011484610000000001) + + sort_a_random_list + + + ~:0:<method 'pop' of 'list' objects> 2.20% (1671 1671 0.000163966 0.000163966) + + <method 'pop' of 'list' objects> + + + /jhale.dev/posts/python-profiling/sample.py:43:merge 2.20% (1671 1671 0.000163966 0.000163966) + + merge + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 9.38% (249 249 0.0006983530000000001 0.001010208) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + + /jhale.dev/posts/python-profiling/sample.py:20:sort_a_random_list 0.11% (1 1 8.152000000000001e-06 0.0015018070000000002) + + sort_a_random_list + + + /jhale.dev/posts/python-profiling/sample.py:41:merge_sort 5.88% (498 2 0.00043762300000000005 0.001380286) + + merge_sort + + +