Code profiling
Better Code, Better Science: Chapter 10, Part 3
This is a possible section from the open-source living textbook Better Code, Better Science, which is being released in sections on Substack. The entire book can be accessed here and the Github repository is here. This material is released under CC-BY-NC-ND.
Complexity analysis tells us about the worst case performance of our code, but there are many reasons for slow code even when complexity is low. Profiling is the activity of empirically analyzing the performance of our code in order to identify specific parts of the code that might cause poor performance. It’s often the case that slow performance arises from specific portions of the code, which we refer to as bottlenecks. These bottlenecks can be difficult to intuit, which is why it’s important to empirically analyze performance in order to identify the location of those bottlenecks, which can then help us focus our efforts. However, it’s also important to keep complexity in mind when we analyze code; in particular, we should always profile the code using realistic input sizes, so that we will see any complexity-related slowdowns if they exist.
There are a couple of important points to know when profiling code. First, it’s important to remember that profiling has overhead and can sometimes distort results. In particular, when code involves many repetitions of a very fast operation, the overhead due to profiling the operation can add up, making it seem worse than it is. The profiler can also compete with your code for memory and CPU time, potentially distorting results (e.g. for processes involving lots of memory). Second, it’s important to keep in mind the distinction between CPU time, which refers to the time actually spent by the CPU doing processing, and wall time, which includes CPU time as well as time due to other sources such as input/output. If the wall time is much greater than the CPU time, then this suggests that optimizing the computations may not have much impact on the overall execution time. Also note that sometimes the CPU time can actually be greater than the wall time if multiple cores are used for the computation, since the time spent by each core is added together.
Note
Tip
Always profile before you optimize, as our intuitions about software performance are very often wrong.
10.3.1 Function profiling
Function profiling looks at the execution time taken by each function. Let’s say that we have two different implementations of a function, in this case using functions to find duplicates in an array of numbers, where one is efficient and one is inefficient:
def find_duplicates_inefficient(data: list) -> list:
duplicates = []
seen = []
for item in data:
if item in seen:
if item not in duplicates:
duplicates.append(item)
else:
seen.append(item)
return duplicates
def find_duplicates_efficient(data: list) -> list:
duplicates = set()
seen = set()
for item in data:
if item in seen:
duplicates.add(item)
else:
seen.add(item)
return list(duplicates)These functions look remarkably similar, so it wouldn’t be obvious that one is much slower than the other unless we know the details of Python data structures. We can use the cProfile package to profile these two functions (with some additional printing statements removed):
import cProfile
import pstats
import io
import \textit{NumPy} as np
def compare_duplicate_finding(data_size: int = 10000) -> None:
data = list(range(data_size)) + list(range(data_size // 2))
np.random.shuffle(data)
profiler = cProfile.Profile()
profiler.enable()
result = find_duplicates_inefficient(data)
profiler.disable()
s = io.StringIO()
ps = pstats.Stats(profiler, stream=s).sort_stats("cumulative")
ps.print_stats(10)
# Profile efficient version with set
profiler = cProfile.Profile()
profiler.enable()
result = find_duplicates_efficient(data)
profiler.disable()
s = io.StringIO()
ps = pstats.Stats(profiler, stream=s).sort_stats("cumulative")
ps.print_stats(10)The output shows the relative timing of each of the functions:
Profiling duplicate finding with list (data_size=10000):
(Using 'if item in seen_list' is O(n) each time)
---------------------------------------------------------------------
15002 function calls in 0.310 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.308 0.308 0.310 0.310 profiling_example.py:72(find_duplicates_inefficient)
15000 0.001 0.000 0.001 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
Profiling duplicate finding with set (data_size=10000):
(Using 'if item in seen_set' is O(1) each time)
---------------------------------------------------------------------
15002 function calls in 0.002 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.001 0.001 0.002 0.002 profiling_example.py:92(find_duplicates_efficient)
15000 0.001 0.000 0.001 0.000 {method 'add' of 'set' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}Here we can see that there is a huge difference in the time taken by the two functions (0.31 seconds versus 0.002 seconds). This is due to the fact that membership (in) operations on sets are O(1) whereas membership operations on lists are O(N). Once they are put into a loop this becomes O(N) versus O(N2), which can make a huge difference as the number of inputs increases.
I also learned something quite interesting in the process of writing this example. I worked with my coding agent to generate code for examples of problems where there might be a subtle issue that could cause a bottleneck. In several cases, the agent generated code that was meant to demonstrate major performance bottlenecks, but the bottlenecks didn’t actually occur. The reason was that those particular issues were once problematic, but the latest version of the CPython interpreter (the standard implementation of Python) is now optimized to eliminate the bottlenecks! This highlights the importance of verifying claims made by coding agents rather than blindly trusting them. It also shows how optimization is a moving target, since code that was inefficient in a previous Python version can become optimal in a later version.
10.3.2 Line profiling
In the previous examples, we saw that there were functions that took a long time (such as find_duplicates_inefficient()) but we couldn’t tell why. Line profiling digs even more deeply to measure the time taken to execute each line in the code. We can do this with the same code as above, simply by adding a @profile decorator to each of the functions:
@profile
def find_duplicates_inefficient(data):
...We can then run line profiling using the kernprof tool that is part of the line_profiler module (in this case using the command kernprof -lv line_profiling_example.py), which gives the following output:
Total time: 0.31827 s
File: line_profiling_example.py
Function: find_duplicates_inefficient at line 34
Line # Hits Time Per Hit % Time Line Contents
==============================================================
34 @profile
35 def find_duplicates_inefficient(data):
36 1 0.0 0.0 0.0 duplicates = []
37 1 0.0 0.0 0.0 seen = []
38
39 15001 3715.0 0.2 1.2 for item in data:
40 15000 262284.0 17.5 82.4 if item in seen:
41 5000 48610.0 9.7 15.3 if item not in duplicates:
42 5000 1246.0 0.2 0.4 duplicates.append(item)
43 else:
44 10000 2413.0 0.2 0.8 seen.append(item)
45
46 1 2.0 2.0 0.0 return duplicates
Total time: 0.010041 s
File: line_profiling_example.py
Function: find_duplicates_efficient at line 49
Line # Hits Time Per Hit % Time Line Contents
==============================================================
49 @profile
50 def find_duplicates_efficient(data):
51 1 2.0 2.0 0.0 duplicates = set()
52 1 0.0 0.0 0.0 seen = set()
53
54 15001 3930.0 0.3 39.1 for item in data:
55 15000 2831.0 0.2 28.2 if item in seen:
56 5000 968.0 0.2 9.6 duplicates.add(item)
57 else:
58 10000 2290.0 0.2 22.8 seen.add(item)
59
60 1 20.0 20.0 0.2 return list(duplicates)This confirms that the slowdown comes specifically from the lines in which in is used with a list rather than a set. Specifically, the “per hit” metric shows that line 40 in the inefficient version takes 17.5 units of time, versus 0.2 for the equivalent line (55) in the efficient version. Even if we didn’t know about the optimization of membership testing for Python sets, this would make it clear that those two lines are the place to look to learn more about the slowdown. Note that the @profile decorator is not a built-in Python function, but instead is injected by kernprof when it runs; this, the decorator would need to be removed to avoid a NameError when it was run using the Python interpreter.
The results above also highlight the overhead that occurs with line profiling; while the efficient function took 0.002 seconds to complete in the function profiling example, it took 0.01 seconds in the line profiling example.
10.3.3 Memory profiling
Memory usage is another potential issue that we can investigate using profiling. This becomes a particularly important issue when we start thinking about implementation of many jobs at once on a high-performance computing system, as I will discuss in the next chapter; these systems often require that one specifies not only how many CPU cores one requires for the job, but also how much memory.
As an example we can look at the use of the .copy() method in NumPy. It’s generally good practice to copy a variable before making changes to it, since otherwise the changes may affect the original copied variable (since assignment will refer to the same memory location rather than creating a new object). Here let’s see the memory implications of overusage of the .copy() operation. We will compare two functions, each of which computes the sum of squares for an array of random numbers; we use the @profile decorator from the memory_profiler package to perform memory profiling:
from memory_profiler import profile
@profile
def process_with_copies(n_rows: int = 2000000) -> np.ndarray:
data = np.random.randn(n_rows, 5)
data_copy1 = data.copy()
data_normalized = (data_copy1 - data_copy1.mean()) / data_copy1.std()
data_copy2 = data_normalized.copy()
data_squared = data_copy2 ** 2
data_copy3 = data_squared.copy()
result = data_copy3.sum(axis=1)
return result
@profile
def process_without_copies(n_rows: int = 2000000) -> np.ndarray:
data = np.random.randn(n_rows, 5)
mean = data.mean()
std = data.std()
data_normalized = (data - mean) / std
data_normalized **= 2
result = data_normalized.sum(axis=1)
return resultThe process_without_copies() function doesn’t copy the dataset at all; rather, it only saves transformations on the original data, or performs operations in place (such as **= 2). Running these two functions we see substantial differences in the memory used during execution:
UNNECESSARY COPIES EXAMPLE (BAD VERSION)
=============================================================
Filename: src/bettercode/profiling/unnecessary_copies_bad.py
Line # Mem usage Increment Occurrences Line Contents
=============================================================
22 66.2 MiB 66.2 MiB 1 @profile
23 def process_with_copies(n_rows=2000000):
24 144.7 MiB 78.4 MiB 1 data = np.random.randn(n_rows, 5)
25
26 221.0 MiB 76.3 MiB 1 data_copy1 = data.copy()
27 373.8 MiB 152.8 MiB 1 data_normalized = (data_copy1 - data_copy1.mean()) / data_copy1.std()
28
29 373.8 MiB 0.0 MiB 1 data_copy2 = data_normalized.copy()
30 450.1 MiB 76.3 MiB 1 data_squared = data_copy2 ** 2
31
32 526.4 MiB 76.3 MiB 1 data_copy3 = data_squared.copy()
33 541.7 MiB 15.3 MiB 1 result = data_copy3.sum(axis=1)
34
35 541.7 MiB 0.0 MiB 1 return result
UNNECESSARY COPIES EXAMPLE (GOOD VERSION)
=============================================================
Filename: src/bettercode/profiling/unnecessary_copies_good.py
Line # Mem usage Increment Occurrences Line Contents
=============================================================
22 66.3 MiB 66.3 MiB 1 @profile
23 def process_without_copies(n_rows=2000000):
24 144.7 MiB 78.4 MiB 1 data = np.random.randn(n_rows, 5)
25
26 144.7 MiB 0.0 MiB 1 mean = data.mean()
27 221.0 MiB 76.3 MiB 1 std = data.std()
28 221.2 MiB 0.2 MiB 1 data_normalized = (data - mean) / std
29 221.2 MiB 0.0 MiB 1 data_normalized **= 2
30
31 236.5 MiB 15.3 MiB 1 result = data_normalized.sum(axis=1)
32
33 236.5 MiB 0.0 MiB 1 return resultYou can see that each creation of a copy resulted in a substantial growth in memory usage, leading to more than double the total memory usage. While this might not matter for small datasets, it could have a major impact for large datasets.
There is a caveat to this kind of memory profiling, which is that it is less exact than compute profiling due to its interaction with the Python memory management system, and due to the fact that it samples memory usage at specific points. Python has a garbage collector that removes objects from memory, and sometimes it will do so in the middle of execution, leading to seemingly strange results. For example, on line 29 of the “bad” version above, you can see that a copy was created but there was zero increment, which could reflect the fact that Python performed a garbage collection operation just before creation, or that the operation occurred so quickly that the memory profiler’s sample missed it.
10.3.3.1 Memory profiling in pandas
pandas data frames can exhibit some surprising memory usage features, and memory profiling can often be useful to optimize pandas workflows. pandas has a built-in memory profiling function for data frames, called pandas.memory_usage(). Here we will use this to see an example of a surprising memory usage feature. We first create functions to generate a data frame with a number of string variables, and to analyze the memory footprint of the data frame. Note that it’s important to use deep=True when using the memory analyzer, since otherwise it will only report the size of the pointers in memory and not the size of the actual data that are being pointed to:
def create_sample_data(n_rows: int = 100000) -> pd.DataFrame:
data = {
'subject_id': range(n_rows),
'condition': np.random.choice(
['Control', 'Treatment_A', 'Treatment_B'],
n_rows),
'gender': np.random.choice(
['Male', 'Female'], n_rows),
'site': np.random.choice(
['Site_Boston', 'Site_London',
'Site_Tokyo', 'Site_Sydney'],
n_rows),
'diagnosis': np.random.choice(
['Healthy', 'Patient'], n_rows)
}
return pd.DataFrame(data)
def analyze_memory(df: pd.DataFrame) -> int:
print("\nMemory usage per column:")
memory_usage = df.memory_usage(deep=True)
for col, mem in memory_usage.items():
print(f" {col:15s}: {mem / 1024**2:8.2f} MB")
total_memory = memory_usage.sum()
print(f"\nTotal memory usage: {total_memory / 1024**2:.2f} MB")
print("=" * 80)
return total_memory
df = create_sample_data(n_rows=100000)
# Analyze with default string columns
string_memory = analyze_memory(df)Memory usage per column:
Index : 0.00 MB
subject_id : 0.76 MB
condition : 5.59 MB
gender : 5.15 MB
site : 5.70 MB
diagnosis : 5.34 MB
Total memory usage: 22.55 MBNow we convert the string columns to Categorical data types, which are represented in a much more compact way by pandas:
categorical_cols = ['condition', 'gender', 'site', 'diagnosis']
df_categorical = df.copy()
for col in categorical_cols:
df_categorical[col] = df_categorical[col].astype('category')
categorical_memory = analyze_memory(df_categorical)Memory usage per column:
Index : 0.00 MB
subject_id : 0.76 MB
condition : 0.10 MB
gender : 0.10 MB
site : 0.10 MB
diagnosis : 0.10 MB
Total memory usage: 1.15 MBThis simple change led to almost 95% in reduction in the memory footprint of the data frame, due to the fact that pandas uses a compact representation for categorical data types. This particular optimization works well in cases where there is a small number of unique categorical items that are repeated many times each. This provides an example of how memory profiling, combined with knowledge of how the relevant packages work with the data, can sometimes lead to massive improvements in memory footprint.
In the next post I will discuss common sources of slow code execution.