Profiling - general concepts¶
Slow code usually has some "hot spots" where most of the runtime is spent and to improve your code you first have to figure out where such bottlenecks are located in your code.
This process is called profiling.
# IGNORE THIS CELL WHICH CUSTOMIZES LAYOUT AND STYLING OF THE NOTEBOOK !
%matplotlib inline
%config InlineBackend.figure_format = 'retina'
import warnings
import matplotlib.pyplot as plt
warnings.filterwarnings("ignore", category=FutureWarning)
warnings.filterwarnings = lambda *a, **kw: None
from IPython.core.display import HTML
HTML(open("../documents/custom.html", "r").read())
The first part of this chapter gives an overview of the general concepts of profiling. This includes:
In the second part we focus on Python tools for:
Slow code usually has some "hot spots" where most of the runtime is spent and to improve your code you first have to figure out where such bottlenecks are located in your code.
This process is called profiling.
The following function count_common takes two lists data_1 and data_2 and counts how many elements both have in common. This is a simple and slightly unrealistic example, but good enough to show and explain a few fundamental principles of profiling and optimization.
def count_common(data_1, data_2):
"""counts how many items data_1 and data_2 have in common"""
matches = 0
for value in data_1:
if value in data_2:
matches += 1
return matches
print(count_common([10, 20, 30], [20, 30, 40, 50]))
2
This looked good! We got the result immediately. But how fast is count_common for larger inputs?
To measure runtime we can use the time function from the time module from the Python standard library:
time.time() returns the time in second since the so called "epoch". On Windows and most Unix systems, the epoch is January 1, 1970, 00:00:00 (UTC), commonly referred to as Unix time.
We can use the difference of two calls of time.time() to measure the runtime spent between the two calls:
import time
started = time.time()
print("I sleep now for 1.23 seconds")
time.sleep(1.23)
print("Measured execution time is", time.time() - started)
I sleep now for 1.23 seconds Measured execution time is 1.230435848236084
We use this method now to measure and report the speed of our initial code:
import random
import time
input_size = [8000, 16000, 32000]
needed_time = []
def random_numbers(n):
"""generate a list with n random numbers"""
data = list(range(n*2))
random.shuffle(data)
return data[:n]
for i, n in enumerate(input_size):
# create two lists of length n of random numbers in range 0..n:
data_1 = random_numbers(n)
data_2 = random_numbers(n)
# time.time() returns the number of seconds (including figures
# after the decimal point) since 1st of January 1970
# (this date is also called the Unix epoch).
start_time = time.time()
count_common(data_1, data_2)
# Calling time.time() and subtracting the value of
# start_time we get the observed runtime for executing count_common.
end_time = time.time()
needed_time.append(end_time - start_time)
factor = needed_time[i] / needed_time[0]
print(
"n = {:5d} time: {:5.2f} seconds, increased by {:3.1f} times".format(
n, needed_time[i], factor
)
)
n = 8000 time: 0.56 seconds, increased by 1.0 times n = 16000 time: 2.32 seconds, increased by 4.1 times n = 32000 time: 9.61 seconds, increased by 17.2 times
We observe that every time we double the size $n$, the overall runtime approximately increases by a factor of four. This is the same as saying that the runtime is proportional to $n^2$.
Note: Timing measurement values in this chapter will vary, they depends on the computer used and also will change from run to run. More about this later. So do not expect to get exactly the same output here and in following examples.
A simple calculation estimates that
n = 240000 would result in about 10 minutes processing timen = 600000 would need about one hour to finish! This also means, that a program which works well on small data sets during development may have unacceptable runtime in real world situations.
import matplotlib.pyplot as plt
import numpy as np
n = np.arange(0, 800_000, 8_000)
t1 = n ** 2 / 6_000_000_000
plt.plot(n, t1)
plt.xlabel("n")
plt.ylabel("Run time [min]")
plt.xlim(0, None)
plt.ylim(0, None)
plt.xticks(np.arange(0, 800_001, 200_000), ['0', '200k', '400k', '600k', '800k']);
Question to the audience
When you look at the function `count_common`: where do you think most run-time will be spent? Is there any command or are there code lines which are suspicious to be slow?Instead of guessing which parts of our code are slow, tools called profilers provide means to understand how the overall runtime of a program is distributed over functions and/or individual lines of code.
At the time of writing this notebook, the Python package line_profiler is our preferred profiling tool. We will discuss other tools later.
To analyze code with line_profiler, we first have to install it using pip install line_profiler.
Within a notebook, we can use the line_profiler line magic, namely %lprun. To do so, after installing line_profiler we have to activate it:
%load_ext line_profiler
n = 4000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
To run %lprun, the functions which are to be profiled are listed using -f, and the last argument is how the function execution is called. Here, we profile the count_common function using the given data. We will explain how to use line_profiler in the command line later in the script.
%lprun -f count_common count_common(data_1, data_2)
The output shows us:
Hits counts how often the actual line was executedTime is the overall time spent executing this line in µsPer Hit is the average execution time of this line in µs% Time is the fraction of the overall time running the functionSo we see that most of the runtime (>95% on my computer) is spent in if value in data_2!
Question to the audience
Was your guess right?Lesson learned
It is difficult to guess where the slow part of a program is, and guesses are most often wrong! |
The appropriate and optimized data type for checking membership is set and not list.
Note
The Python type `set` implements an unordered collection of elements similar to mathematical sets. Python sets support operations like intersection, union, differences or checks, e.g., if a set is a subset of another set. The underlying implementation is very fast!.Sets (and dictionaries) in Python are implemented based on so-called hash tables which come from computer science. Hash tables guarantee that the membership lookup x in y has constant (maximal) runtime independent of the size of y!
As our program is independent of the order of the values in data we do no harm when we convert the data type to set:
def count_common_2(data_1, data_2):
matches = 0
# This is the modification. But this only works
# in case data_2 has no duplicate elements,
# which is valid for out test data:
data_2 = set(data_2)
for value in data_1:
if value in data_2:
matches += 1
return matches
n = 4000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
%lprun -f count_common_2 count_common_2(data_1, data_2)
Overall runtime (Total time in the output) reduced significantly by choosing the right data structure!
You also can notice that data conversion in Line 3 only adds insignificant extra runtime.
Further we see no "hot spots" of slow code anymore, the Per Hit values in Line 10 to 12 are similar.
We optimize our code further: To count the number of common elements we convert data_1 and data_2 to sets and compute the size of the intersection of both sets.
def count_common_3(data_1, data_2):
data_1 = set(data_1)
data_2 = set(data_2)
# compute set intersection which is the set of common elements:
common = data_1 & data_2
return len(common)
import random
n = 4000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
%lprun -f count_common_3 count_common_3(data_1, data_2)
The result is impressive. We further reduced runtime by a factor of about 10!
The reason for this is that we replaced a slow Python for loop by calling the set intersection of Python which is implemented in C.
In the beginning we estimated that the original implementation would need about 1h to run for n = 600000.
Let's profile our improved version:
import random
n = 60000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
%lprun -f count_common_3 count_common_3(data_1, data_2)
After we have performed code profiling and optimization, we reduced overall runtime for a large n from an hour to less than 0.1 sec.
Lesson learned
Optimizing Python code might require good knowledge of Python data structures.Use the line_profiler line magic %lprun to profile the following code. Try to understand where and why most time is spent. Can you improve run time?
import time
def fibionacci_numbers(n):
"""computes first n fibionacci numbers.
the fibionacci sequence starts with 0, 1
and following numbers are the sum of its
two preceding numbers:
0, 1, 1, 2, 3, 5, 8, 13, ...
"""
result = [0, 1]
while len(result) < n:
result.append(result[-1] + result[-2])
return result[:n]
def sumup_fibionacci_numbers(n):
"""sums the n first elements of the
fibonacci sequence.
"""
sum_ = 0
for i in range(n):
numbers = fibionacci_numbers(i + 1)
sum_ += numbers[i]
return sum_
started = time.time()
sumup_fibionacci_numbers(2000)
needed = time.time() - started
print(f"needed {needed:.1f} seconds")
needed 0.3 seconds
%load_ext line_profiler
The line_profiler extension is already loaded. To reload it, use: %reload_ext line_profiler
%lprun -f sumup_fibionacci_numbers sumup_fibionacci_numbers(2000)
As you can see we spend 99% of the time in calling fibionacci_numbers over and over again.
If you compare the reported runtime and compare to the timing from the original exercise you will also see the extra time caused by the profiler!
Optimization: We can compute the first $n$ fibionacci numbers once in the beginning and then add them up:
def fibionacci_numbers(n):
"""computes first n fibionacci numbers.
the fibionacci sequence starts with 0, 1
and following numbers are the sum of its
two preceding numbers:
0, 1, 1, 2, 3, 5, 8, 13, ...
"""
result = [0, 1]
while len(result) < n:
result.append(result[-1] + result[-2])
return result[:n]
def sumup_fibionacci_numbers_optimized(n):
"""sums the n first elements of the
fibonacci sequence.
"""
sum_ = 0
numbers = fibionacci_numbers(n)
for i in range(n):
sum_ += numbers[i]
return sum_
def sumup_fibionacci_numbers_optimized_further(n):
"""sums the n first elements of the
fibonacci sequence.
"""
numbers = fibionacci_numbers(n)
return sum(numbers)
%lprun -f sumup_fibionacci_numbers_optimized sumup_fibionacci_numbers_optimized(2000)
%lprun -f sumup_fibionacci_numbers_optimized_further sumup_fibionacci_numbers_optimized_further(2000)
Measuring code execution time accurately can be trickier than you might think. If you run the previous examples multiple times you will see that then numbers change from run to run.
The reason for this is that modern computers run many programs concurrently, this might be a system-upgrade in the background, downloading new emails or other work done permanently by your operating system. Even moving the mouse, scrolling a window or typing cause some (but little) load on your system!
To improve accuracy the common strategy is to measure multiple times and take the minimum or the average of the measured times.
It depends on the code whether you should choose the minimum or the average of measured runtimes.
But the situation can be even more tricky, e.g., if your program downloads data from the internet the first run might me much slower than subsequent runs since the internet might store data on its way from the server to your machine in local network caches. In this case you have to decide what you want to measure. Even taking the maximum run time could make sense here, or list the range of runtimes and the median value for reporting.
As time measurements are inaccurate especially small values should not be taken too seriously. In Python applications, we usually do not try to squeeze out a few microseconds but intend to reduce runtime by a significant factor, e.g., to gain 10 times speedup when starting the optimization and to reduce 20% of runtime when fine-tuning.
When you optimize your code, do not compare measurements taken on different computers. Operating systems, CPU models and other factors affect time measurements significantly. (This does not mean that you should not report the final speed of your code on different computers).
In real world programs, the location of the slow parts of a program can vary for different data set / problem sizes. Let's assume your program has the following structure:
intermediate_result = process_step_1(data)
final_result = process_step_2(intermediate_result)
Further let's assume that
dataprocess_step_1 can be described as $40 \times n^2$ microseconds process_step_2 as $0.00005 \times n^4$ microseconds. (These polynomial laws for the runtimes are not made up, more about this the following chapter.)
This is a plot showing how the total run time and the partial run times develop depending on $n$:
import matplotlib.pyplot as plt
import numpy as np
n = np.arange(0, 1500, 50)
t1 = 40 * n ** 2 / 1_000_000
t2 = 0.00005 * n ** 4 / 1_000_000
plt.plot(n, t1 + t2, label="total run time")
plt.plot(n, t1, "g:", label="process_step_1")
plt.plot(n, t2, "k:", label="process_step_2")
plt.xlabel("n")
plt.ylabel("Run time [us]")
plt.xlim(0, None)
plt.ylim(0, None)
plt.legend();
So when you profile your code for a data set size of 500, the profiler will show you that process_step_1 is the bottleneck. Optimizing process_step_1 will give you better results for this problem size, but when you run your program with larger data sets in the future you will realize that you need further optimizations.
So profiling also depends on typical use cases for your code and also on assumptions about future scenarios.
Advice
Profile your code for different realistic problem sizes $n$ so that you can be sure where the bottlenecks are.
time command line¶The command line command time determines how long a given command takes to run. Please note that his command is available in Linux and macOS but not in Windows.
Let's see an example. Since time is a command line program we have to write our Python file into a separate file.
The so called cell magic %%file will write the content of the cell into a file named myscript.py:
%%file myscript.py
import random
import time
def random_numbers(n):
"""generate a list with n random numbers"""
data = list(range(n))
random.shuffle(data)
return data
def count_common(data_1, data_2):
"""counts how many items data_1 and data_2 have in common"""
matches = 0
for value in data_1:
if value in data_2:
matches += 1
return matches
n = 8000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
start_time = time.time()
count_common(data_1, data_2)
end_time = time.time()
needed_time = end_time - start_time
print("n = {:5d} time: {:5.2f} seconds".format(n, needed_time))
Overwriting myscript.py
Let's call the time command. To execute a terminal command in a Jupyter Notebook cell, we need to prepend an exclamation mark ! to the beginning of the command:
%%bash
time python myscript.py
n = 8000 time: 0.35 seconds
real 0m0.400s user 0m0.374s sys 0m0.015s
real is the time from start to finish of the call. It is the time the user experiences from the moment you hit the Enter key until the moment the execution of the script is completed.user - amount of CPU time spent in user mode.sys - amount of CPU time spent in kernel mode in which protected instructions can be performed, e.g., I/O instructions.We cannot explain the differences of the values here, but unless you know what you are doing, use the real entry for time measurements.
Note
For macOS users: When you are using the default shell zsh instead of bash the output looks different (see below) and the real time is specified as total time.
!time python myscript.py
n = 8000 time: 0.34 seconds real 0m0.391s user 0m0.371s sys 0m0.012s
timeit¶Unlike the time module which saves the time before and after the execution of the code and subtract them, timeit.timeit() times a number of executions (1,000,000 by default) of the main statement and output the statistically measurement of code execution time. timeit can be used from the command line or imported as a Python module.
As it runs code so many time it is more suited to measure small execution times, e.g. for single Python commands or expressions.
The module function timeit.timeit(stmt, setup, timer, number) takes in four arguments:
stmt is the statement to be measured the time (default value 'pass')setup is the code that needs to be run before stmttimer is a timeit.Timer objectnumber is the number of executions to run the stmtThe return value is the total time of the number executions.
Let's use this to compare membership lookup for lists and sets:
import timeit
setup = """
import random
n = 5000
data_as_list = [random.randint(0, n) for _ in range(n)]
data_as_set = set(data_as_list)
"""
list_lookup = """
2500 in data_as_list
"""
set_lookup = """
2500 in data_as_set
"""
print(timeit.timeit(stmt=list_lookup, setup=setup, number=10_000))
print(timeit.timeit(stmt=set_lookup, setup=setup, number=10_000))
0.2259291250000004 0.0003628340000005892
You should not be surprised any more to see here that sets are much faster than lists for checking membership!
IPython magic commands or magic functions are the enhancements specific to and provided by IPython kernel. The two types of magic commands are:
% character and are similarly to command line calls%% character and can operate on multiple lines below their call.%time magic¶The cell magic %%time and the line magic %time display time required by IPython environment to execute a Python code snippet.
%time measure the run time of a single line of code, %%time the run time of a full code cell:
import random
n = 5000
data_1 = random_numbers(n)
data_2 = random_numbers(n)
%time count_common(data_1, data_2)
CPU times: user 208 ms, sys: 3.89 ms, total: 212 ms Wall time: 213 ms
2521
%%time
count_common(data_1, data_2)
count_common(data_1, data_2)
CPU times: user 418 ms, sys: 8.16 ms, total: 426 ms Wall time: 429 ms
2521
From the output, you can see CPU times which are the time the code spends in the user and kernel (sys) mode (we don't explain the details and differences here). Wall time is the amount of time that passes from the start of the execution to its end.
%timeit magic¶%timeit uses timeit.repeat(stmt, setup, timer, number, repeat) which executes code snippet for number times (loops) and repeat runs.
The output reports mean and standard deviation of time per loop.
Users can specify number with the option -n and repeat with -r.
Running %timeint -n N -r R FUNCTIONCALL works as follows:
timings = []
for _ in range(R):
start = time.time()
for _ in range(N):
FUNCTIONCALL
needed = (time.time() - start) / N
timings.append(needed)
m = mean(timings)
s = stddev(timings)
report(....)The inner loop to N is needed to get accurate measurements, the outer loop to R is needed for the final statistics.
Without specifying -n and -r the numbers are estimated based on the execution time for one or more function calls. This is done in a way so that overall timing does not run very long, but at the same time we can get reliable measurements and statistics.
The numbers are then also reported:
%%timeit
count_common(data_1, data_2)
212 ms ± 2.07 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
So in this case N was set to 1 and R to 7.
Same as a line magic:
%timeit count_common(data_1, data_2)
223 ms ± 8.38 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
And now with user specified parameters:
%timeit -n 10 -r 2 count_common(data_1, data_2)
214 ms ± 19.4 µs per loop (mean ± std. dev. of 2 runs, 10 loops each)
%lprun was introduce in the first section. Beyond the use within Jupyter notebooks you can also call the line profiler directly from the command line.
To make this work you have to decorate the functions you want to profile with the @profile decorator, we also write the content of the code cell to a file so that we can use line_profiler from the command line:
%%file line_profiler_demo.py
import random
def random_numbers(n):
"""generate a list with n random numbers"""
data = list(range(n))
random.shuffle(data)
return data
@profile
def count_common(data_1, data_2):
"""counts how many items data_1 and data_2 have in common"""
matches = 0
for value in data_1:
if value in data_2:
matches += 1
return matches
@profile
def generate_data(n=5000):
data_1 = random_numbers(n)
data_2 = random_numbers(n)
return data_1, data_2
@profile
def multiple_calls():
for i in range(5):
data_1, data_2 = generate_data()
count_common(data_1, data_2)
multiple_calls()
multiple_calls()
Overwriting line_profiler_demo.py
To profile this code in the commandline you have to run as below. The options -v shows the results on the screen output and the option-l use the line-by-line profiler instead of cProfile.
!kernprof -vl line_profiler_demo.py
Wrote profile results to line_profiler_demo.py.lprof
Timer unit: 1e-06 s
Total time: 1.39169 s
File: line_profiler_demo.py
Function: count_common at line 11
Line # Hits Time Per Hit % Time Line Contents
==============================================================
11 @profile
12 def count_common(data_1, data_2):
13 """counts how many items data_1 and data_2 have in common"""
14 10 4.0 0.4 0.0 matches = 0
15 50010 16835.0 0.3 1.2 for value in data_1:
16 50000 1358134.0 27.2 97.6 if value in data_2:
17 50000 16719.0 0.3 1.2 matches += 1
18 10 3.0 0.3 0.0 return matches
Total time: 0.192406 s
File: line_profiler_demo.py
Function: generate_data at line 21
Line # Hits Time Per Hit % Time Line Contents
==============================================================
21 @profile
22 def generate_data(n=5000):
23 10 96225.0 9622.5 50.0 data_1 = random_numbers(n)
24 10 96168.0 9616.8 50.0 data_2 = random_numbers(n)
25 10 13.0 1.3 0.0 return data_1, data_2
Total time: 1.61917 s
File: line_profiler_demo.py
Function: multiple_calls at line 28
Line # Hits Time Per Hit % Time Line Contents
==============================================================
28 @profile
29 def multiple_calls():
30 12 15.0 1.2 0.0 for i in range(5):
31 10 193338.0 19333.8 11.9 data_1, data_2 = generate_data()
32 10 1425821.0 142582.1 88.1 count_common(data_1, data_2)
Comments:
line_profiler works by calling time.time() before and after each line is executed and accumulating these measurements@profile does not require extra imports, as this is handled when you call kernprof. Thus, your code will not run when you run it as a regular Python script:
!python line_profiler_demo.py
Traceback (most recent call last):
File "/Users/uweschmitt/Projects/fast-python/scripts/section_2/line_profiler_demo.py", line 11, in <module>
@profile
NameError: name 'profile' is not defined
Trick
If you run the code above using the Python interpreter, you will get an error message that profile is not defined and program execution will halt. Adding and removing @profile during development can be cumbersome, but there is a trick, such that code runs in both situations:
%%file line_profiler_trick.py
# this makes code run with Python and line-profiler:
try:
profile
except NameError:
profile = lambda f: f
# now we demonstrate this
@profile
def test():
print("hi")
test()
Overwriting line_profiler_trick.py
!python line_profiler_trick.py
hi
!kernprof -vl line_profiler_trick.py
hi
Wrote profile results to line_profiler_trick.py.lprof
Timer unit: 1e-06 s
Total time: 2.7e-05 s
File: line_profiler_trick.py
Function: test at line 10
Line # Hits Time Per Hit % Time Line Contents
==============================================================
10 @profile
11 def test():
12 1 27.0 27.0 100.0 print("hi")
cProfile¶Python standard library provides two different implementations of the same profiling interface:
cProfile is a C extension with reasonable overhead and, therefore, suitable for profiling long-running programs.
profile is a pure Python module with the same interface as cProfile but has significant higher overhead in profiling. It is not recommended to be used unless you want to subclass from profile.Profile to modify / extend the profiler.
Both profilers measure times per function call and not per executed line.
We mention cProfile for the sake of completeness, the output of cProfile is regrettably difficult to read, this is why we introduce pyinstrument next.
pyinstrument¶As a statistical profiler, pyinstrument is faster than line_profiler and cProfile because, instead of tracing, it is sampling the process every 1ms and recording the call stack at that point and this results in lower overhead. The output shows measured times not per line but per function call.
We construct a more complex example with multiple nested function calls to demonstrate the use of pyinstrument:
%%file multiple_calls.py
import random
def random_numbers(n):
"""generate a list with n random numbers"""
data = list(range(n))
random.shuffle(data)
return data
def count_common(data_1, data_2):
"""counts how many items data_1 and data_2 have in common"""
matches = 0
for value in data_1:
if value in data_2:
matches += 1
return matches
def generate_data(n=5000):
data_1 = random_numbers(n)
data_2 = random_numbers(n)
return data_1, data_2
def multiple_calls():
for i in range(5):
data_1, data_2 = generate_data()
count_common(data_1, data_2)
def main():
multiple_calls()
multiple_calls()
main()
Overwriting multiple_calls.py
And now we run this code including profiling and printing a final report:
!pyinstrument multiple_calls.py
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:49:50 Samples: 84 /_//_/// /_\ / //_// / //_'/ // Duration: 1.440 CPU time: 1.415 / _/ v4.2.0 Program: multiple_calls.py 1.439 <module> <string>:1 [4 frames hidden] <string>, runpy 1.439 _run_code runpy.py:64 └─ 1.439 <module> multiple_calls.py:2 └─ 1.439 main multiple_calls.py:32 └─ 1.439 multiple_calls multiple_calls.py:26 ├─ 1.365 count_common multiple_calls.py:11 └─ 0.072 generate_data multiple_calls.py:20 └─ 0.072 random_numbers multiple_calls.py:4 └─ 0.072 shuffle random.py:348 [8 frames hidden] random, <built-in> To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-49-50 [options]
What we see here is a top down analysis of your program from the entry point function main down to the lowest level:
jupyter internals, our function main appears on the fourth level.count_common and only little time in generate_data. Both time values sum up to the run time of main.generate_data the run time is split (almost equally) to the run times of both list comprehensionsSome facts about pyinstrument:
pyinstrument can be used as a first step to profile complex programs to get an idea whereabout the slow spots are. Then, you can refine your analysis using the line_profiler.pyinstrument also has an HTML mode which opens a browser to show the report which is interactive and easy to be explored.The full documentation can be found at https://github.com/joerick/pyinstrument
Excessive memory consumption can cause so called swapping where your computer offloads unused memory temporarily to disk. This process slows down execution significantly. It can also crash your program. Profiling memory consumption will give you the needed information to figure out why your program uses excessive memory.
%mprun¶In a similar fashion to %lprun, %mprun performs line-by-line profiling. The module can be installed with the command:
$ pip install memory_profilerThen, load the module as an extension:
%load_ext memory_profiler
The code we used before is not suitable for memory profiling, so we introduce another example:
Our example uses the so called outer product $\otimes$ from linear algebra, which is a kind of multiplication of two vectors which returns a matrix. We use this to make Python use lots of memory:
For a vector $a$ of dimension $n$ and a vector $b$ of dimension $m$ the operation $a \otimes b$ results in a matrix of size $n \times m$.
Definition for the curious
The outer product $\otimes$ is defined as $$\otimes: \mathbb{R}^n \times \mathbb{R}^m \rightarrow \mathbb{R}^{n \times m}$$ $$(a \otimes b)_{i,j} = a_i b_j$$numpy offers a function outer to implement this.
%%file outer_product.py
import numpy as np
def outer_product(n):
a = np.random.random(size=(n,))
AA = np.outer(a, a)
print("shape of AA:", AA.shape)
b = np.outer(a, a) @ a
print("shape of b:", b.shape)
Overwriting outer_product.py
Calling the memory profiler is similar to %lprun: we specify the functions we want to profile with -f and the last argument on that line triggers code execution:
# profiling starts here
from outer_product import outer_product
%mprun -f outer_product outer_product(10_000)
shape of AA: (10000, 10000) shape of b: (10000,)
The output reports for each line the accumulated Mem usage over the lines, Increment the memory usage of that line, and Line Contents from the code.
A single Python float consumes 8 bytes (and not 4 bytes as in C). Thus AA allocates 10_000 * 10_000 * 8 bytes which is 10_000 * 10_000 * 8 / (1024 * 1024) = 762.9 MiB.
This is approximately the number reported by memory_profiler as Increment for line 8.
In line 11, we first create a matrix of 763MiB for np.outer(a, a), the following matrix multiplication by a reduces the memory down to the 10_000 * 8 bytes for b. The memore usage of ~78KiB for b is not reported by the profiler because it prints rounded MiB values!
We do not see the temporary memory usage to compute the outer product in line 11!!!
memory_profiler works and consequences¶The reason for the observed behavior is the way memory_profiler works: the profiler asks the operating system before and after executing each line about the used memory.
This has a few consequences:
line_profiler (the OS needs a while to determine and report memory usage).Point 3 also applies if a line calls a function which allocates and releases memory:
%%file outer_product_2.py
import numpy as np
def run(n):
a = np.random.random(size=(n,))
b = compute_b(a)
print("shape of b:", b.shape)
def compute_b(a):
AA = np.outer(a, a)
b = np.outer(a, a) @ a
return b
Overwriting outer_product_2.py
from outer_product_2 import compute_b, run
%mprun -f compute_b -f run run(10_000)
shape of b: (10000,)
compute_b, similarly to the previous example, the memory usage of Line 12 is reported correctly and that of Line 13 is not reported. run, the memory usage of the function compute_b in Line 7 is also not reported correctly.This affects the way one has to work with memory_profiler:
line_profiler you can "drill down" from a function to lower level functions to find a hot spot
because consumed run-time can not "hide" behind a function call.Comment: memory_profiler can also be used from the command line, see the documentation at https://github.com/pythonprofilers/memory_profiler#usage
%memit¶There is also a "single line version" of the memory profiler %memit which also able to detect temporary memory usage within a particular line of code:
a = np.random.random(size=(10_000,))
%memit np.outer(a, a) @ a
peak memory: 884.45 MiB, increment: 759.27 MiB
from outer_product_2 import run
%memit run(10_000)
shape of b: (10000,) peak memory: 1649.15 MiB, increment: 1524.05 MiB
scalene¶scalene is a high-performance CPU, GPU and memory profiler for Python.
The tool can be used with the following options:
scalene your_prog.py@profile decorator to profile specific functions.The web interface looks as follows for the training of a simple neural network:
time, line_profiler and pyinstrument from the command line to profile the code from Exercise block 1 as well as your solution. You can also use the code from the solutions folder. %%file fib_sum.py
import sys
try:
profile
except NameError:
profile = lambda f: f
@profile
def fibionacci_numbers(n):
"""computes first n fibionacci numbers.
the fibionacci sequence starts with 0, 1
and following numbers are the sum of its
two preceding numbers:
0, 1, 1, 2, 3, 5, 8, 13, ...
"""
result = [0, 1]
while len(result) < n:
result.append(result[-1] + result[-2])
return result[:n]
@profile
def sumup_fibionacci_numbers(n):
"""sums the n first elements of the
fibonacci sequence.
"""
sum_ = 0
for i in range(n):
numbers = fibionacci_numbers(n)
sum_ += numbers[i]
return sum_
@profile
def sumup_fibionacci_numbers_optimized(n):
"""sums the n first elements of the
fibonacci sequence.
"""
sum_ = 0
numbers = fibionacci_numbers(n)
for i in range(n):
sum_ += numbers[i]
return sum_
@profile
def sumup_fibionacci_numbers_optimized_further(n):
"""sums the n first elements of the
fibonacci sequence.
"""
numbers = fibionacci_numbers(n)
return sum(numbers)
if __name__ == "__main__":
variant = int(sys.argv[1])
n = int(sys.argv[2])
algo = [
sumup_fibionacci_numbers,
sumup_fibionacci_numbers_optimized,
sumup_fibionacci_numbers_optimized_further,
][variant]
for _ in range(n):
algo(2_000)
Overwriting fib_sum.py
!time python fib_sum.py 0 1
!time python fib_sum.py 1 500
!time python fib_sum.py 2 500
real 0m0.674s user 0m0.643s sys 0m0.021s real 0m0.293s user 0m0.270s sys 0m0.015s real 0m0.243s user 0m0.222s sys 0m0.013s
!kernprof -vl fib_sum.py 0 1
# check the "Total time", you will see the huge overhead compared to the previous timings!
Wrote profile results to fib_sum.py.lprof
Timer unit: 1e-06 s
Total time: 3.01428 s
File: fib_sum.py
Function: fibionacci_numbers at line 10
Line # Hits Time Per Hit % Time Line Contents
==============================================================
10 @profile
11 def fibionacci_numbers(n):
12 """computes first n fibionacci numbers.
13
14 the fibionacci sequence starts with 0, 1
15 and following numbers are the sum of its
16 two preceding numbers:
17
18 0, 1, 1, 2, 3, 5, 8, 13, ...
19 """
20 2000 908.0 0.5 0.0 result = [0, 1]
21 3998000 1331239.0 0.3 44.2 while len(result) < n:
22 3996000 1674348.0 0.4 55.5 result.append(result[-1] + result[-2])
23 2000 7787.0 3.9 0.3 return result[:n]
Total time: 4.90133 s
File: fib_sum.py
Function: sumup_fibionacci_numbers at line 26
Line # Hits Time Per Hit % Time Line Contents
==============================================================
26 @profile
27 def sumup_fibionacci_numbers(n):
28 """sums the n first elements of the
29 fibonacci sequence.
30 """
31 1 4.0 4.0 0.0 sum_ = 0
32 2001 684.0 0.3 0.0 for i in range(n):
33 2000 4899561.0 2449.8 100.0 numbers = fibionacci_numbers(n)
34 2000 1086.0 0.5 0.0 sum_ += numbers[i]
35 1 0.0 0.0 0.0 return sum_
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized at line 38
Line # Hits Time Per Hit % Time Line Contents
==============================================================
38 @profile
39 def sumup_fibionacci_numbers_optimized(n):
40 """sums the n first elements of the
41 fibonacci sequence.
42 """
43 sum_ = 0
44 numbers = fibionacci_numbers(n)
45 for i in range(n):
46 sum_ += numbers[i]
47 return sum_
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized_further at line 50
Line # Hits Time Per Hit % Time Line Contents
==============================================================
50 @profile
51 def sumup_fibionacci_numbers_optimized_further(n):
52 """sums the n first elements of the
53 fibonacci sequence.
54 """
55 numbers = fibionacci_numbers(n)
56 return sum(numbers)
!kernprof -vl fib_sum.py 1 500
Wrote profile results to fib_sum.py.lprof
Timer unit: 1e-06 s
Total time: 0.78826 s
File: fib_sum.py
Function: fibionacci_numbers at line 10
Line # Hits Time Per Hit % Time Line Contents
==============================================================
10 @profile
11 def fibionacci_numbers(n):
12 """computes first n fibionacci numbers.
13
14 the fibionacci sequence starts with 0, 1
15 and following numbers are the sum of its
16 two preceding numbers:
17
18 0, 1, 1, 2, 3, 5, 8, 13, ...
19 """
20 500 219.0 0.4 0.0 result = [0, 1]
21 999500 344837.0 0.3 43.7 while len(result) < n:
22 999000 441049.0 0.4 56.0 result.append(result[-1] + result[-2])
23 500 2155.0 4.3 0.3 return result[:n]
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers at line 26
Line # Hits Time Per Hit % Time Line Contents
==============================================================
26 @profile
27 def sumup_fibionacci_numbers(n):
28 """sums the n first elements of the
29 fibonacci sequence.
30 """
31 sum_ = 0
32 for i in range(n):
33 numbers = fibionacci_numbers(n)
34 sum_ += numbers[i]
35 return sum_
Total time: 1.85324 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized at line 38
Line # Hits Time Per Hit % Time Line Contents
==============================================================
38 @profile
39 def sumup_fibionacci_numbers_optimized(n):
40 """sums the n first elements of the
41 fibonacci sequence.
42 """
43 500 146.0 0.3 0.0 sum_ = 0
44 500 1252844.0 2505.7 67.6 numbers = fibionacci_numbers(n)
45 1000500 272319.0 0.3 14.7 for i in range(n):
46 1000000 327766.0 0.3 17.7 sum_ += numbers[i]
47 500 166.0 0.3 0.0 return sum_
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized_further at line 50
Line # Hits Time Per Hit % Time Line Contents
==============================================================
50 @profile
51 def sumup_fibionacci_numbers_optimized_further(n):
52 """sums the n first elements of the
53 fibonacci sequence.
54 """
55 numbers = fibionacci_numbers(n)
56 return sum(numbers)
!kernprof -vl fib_sum.py 2 500
Wrote profile results to fib_sum.py.lprof
Timer unit: 1e-06 s
Total time: 0.776014 s
File: fib_sum.py
Function: fibionacci_numbers at line 10
Line # Hits Time Per Hit % Time Line Contents
==============================================================
10 @profile
11 def fibionacci_numbers(n):
12 """computes first n fibionacci numbers.
13
14 the fibionacci sequence starts with 0, 1
15 and following numbers are the sum of its
16 two preceding numbers:
17
18 0, 1, 1, 2, 3, 5, 8, 13, ...
19 """
20 500 189.0 0.4 0.0 result = [0, 1]
21 999500 338337.0 0.3 43.6 while len(result) < n:
22 999000 435428.0 0.4 56.1 result.append(result[-1] + result[-2])
23 500 2060.0 4.1 0.3 return result[:n]
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers at line 26
Line # Hits Time Per Hit % Time Line Contents
==============================================================
26 @profile
27 def sumup_fibionacci_numbers(n):
28 """sums the n first elements of the
29 fibonacci sequence.
30 """
31 sum_ = 0
32 for i in range(n):
33 numbers = fibionacci_numbers(n)
34 sum_ += numbers[i]
35 return sum_
Total time: 0 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized at line 38
Line # Hits Time Per Hit % Time Line Contents
==============================================================
38 @profile
39 def sumup_fibionacci_numbers_optimized(n):
40 """sums the n first elements of the
41 fibonacci sequence.
42 """
43 sum_ = 0
44 numbers = fibionacci_numbers(n)
45 for i in range(n):
46 sum_ += numbers[i]
47 return sum_
Total time: 1.28769 s
File: fib_sum.py
Function: sumup_fibionacci_numbers_optimized_further at line 50
Line # Hits Time Per Hit % Time Line Contents
==============================================================
50 @profile
51 def sumup_fibionacci_numbers_optimized_further(n):
52 """sums the n first elements of the
53 fibonacci sequence.
54 """
55 500 1245705.0 2491.4 96.7 numbers = fibionacci_numbers(n)
56 500 41983.0 84.0 3.3 return sum(numbers)
!pyinstrument fib_sum.py 0 1
# you will not see overhead below anymore:
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:05 Samples: 1544 /_//_/// /_\ / //_// / //_'/ // Duration: 1.545 CPU time: 1.535 / _/ v4.2.0 Program: fib_sum.py 0 1 1.545 <module> <string>:1 [4 frames hidden] <string>, runpy 1.545 _run_code runpy.py:64 └─ 1.545 <module> fib_sum.py:2 └─ 1.545 sumup_fibionacci_numbers fib_sum.py:26 ├─ 1.507 fibionacci_numbers fib_sum.py:10 │ ├─ 0.992 [self] │ ├─ 0.268 list.append <built-in>:0 │ │ [2 frames hidden] <built-in> │ └─ 0.247 len <built-in>:0 │ [2 frames hidden] <built-in> └─ 0.037 [self] To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-05 [options]
!pyinstrument fib_sum.py 1 5000
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:07 Samples: 4750 /_//_/// /_\ / //_// / //_'/ // Duration: 4.797 CPU time: 4.764 / _/ v4.2.0 Program: fib_sum.py 1 5000 4.796 <module> <string>:1 [4 frames hidden] <string>, runpy 4.796 _run_code runpy.py:64 └─ 4.796 <module> fib_sum.py:2 └─ 4.754 sumup_fibionacci_numbers_optimized fib_sum.py:38 ├─ 4.360 fibionacci_numbers fib_sum.py:10 │ ├─ 2.964 [self] │ ├─ 0.745 len <built-in>:0 │ │ [2 frames hidden] <built-in> │ └─ 0.651 list.append <built-in>:0 │ [2 frames hidden] <built-in> └─ 0.394 [self] To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-07 [options]
!pyinstrument fib_sum.py 2 5000
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:12 Samples: 4407 /_//_/// /_\ / //_// / //_'/ // Duration: 4.452 CPU time: 4.394 / _/ v4.2.0 Program: fib_sum.py 2 5000 4.451 <module> <string>:1 [4 frames hidden] <string>, runpy 4.451 _run_code runpy.py:64 └─ 4.451 <module> fib_sum.py:2 ├─ 4.384 sumup_fibionacci_numbers_optimized_further fib_sum.py:50 │ ├─ 3.929 fibionacci_numbers fib_sum.py:10 │ │ ├─ 2.723 [self] │ │ ├─ 0.640 len <built-in>:0 │ │ │ [2 frames hidden] <built-in> │ │ └─ 0.566 list.append <built-in>:0 │ │ [2 frames hidden] <built-in> │ └─ 0.441 sum <built-in>:0 │ [2 frames hidden] <built-in> └─ 0.067 [self] To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-12 [options]
RNA translation
The following snippet of code translates a RNA sequence to a sequence of amino acids
"""
translate rna sequence to list of amino acids.
RNA and amino acid sequences can be written down as a stream
of symbols, RNA is built from 4 symbols `UCGA`, for amino acids
there are more symbols: ACDEFGHIKLMNPQRSTVWY.
During RNA translation such an RNA sequence is translated into
a sequence of amino acids, where each triplet (which we call "codon")
corresponds to one single amino acid:
e.g.
UUU -> F
CUU -> L
AUU -> I
The following strings implement this correspondance from codons
to amino acids:
(note for the experts: we translate stop-codons to ".")
"""
triplets_txt = """UUU CUU AUU GUU UUC CUC AUC GUC UUA CUA AUA GUA
UUG CUG AUG GUG UCU CCU ACU GCU UCC CCC ACC GCC
UCA CCA ACA GCA UCG CCG ACG GCG UAU CAU AAU GAU
UAC CAC AAC GAC UAA CAA AAA GAA UAG CAG AAG GAG
UGU CGU AGU GGU UGC CGC AGC GGC UGA CGA AGA GGA
UGG CGG AGG GGG"""
aas_txt = """F L I V F L I V L L I V L L M V S P T A S P T A S P
T A S P T A Y H N D Y H N D . Q K E . Q K E C R S G
C R S G . R R G W R R G"""
def translate(rna_sequence):
"""
uses codon table to translate rna sequence.
example:
UUU AUC GUU -> F I V
spaces can be omitted.
"""
# cleanup
rna_sequence = remove_whitespace(rna_sequence)
aas = ""
for start_idx in range(0, len(rna_sequence), 3):
triplet = rna_sequence[start_idx : start_idx + 3]
aa = lookup_aa(triplet)
aas += aa
return aas
def lookup_aa(triplet):
"""finds aa symbol for given triplet.
returns 'X' for invalid triplet"""
# cleanup the multiline strings
triplets = remove_whitespace(triplets_txt)
aas = remove_whitespace(aas_txt)
if triplet not in triplets:
return "X"
start_idx = triplets.index(triplet)
return aas[start_idx // 3]
def remove_whitespace(txt):
# remove spaces and line breaks from string
return txt.replace(" ", "").replace("\n", "")
long_test_sequence = 2000 * remove_whitespace(triplets_txt)
print("test sequence has length", len(long_test_sequence))
res = translate(long_test_sequence)
print(len(res))
test sequence has length 384000 128000
time, line_profiler and pyinstrument from the command line to profile the previous code %%file rna_translation.py
"""
translate rna sequence to list of amino acids.
RNA and amino acid sequences can be written down as a stream
of symbols, RNA is built from 4 symbols `UCGA`, for amino acids
there are more symbols: ACDEFGHIKLMNPQRSTVWY.
During RNA translation such an RNA sequence is translated into
a sequence of amino acids, where each triplet (which we call "codon")
corresponds to one single amino acid:
e.g.
UUU -> F
CUU -> L
AUU -> I
The following strings implement this correspondance from codons
to amino acids:
(note for the experts: we translate stop-codons to ".")
"""
try:
profile
except:
profile = lambda f: f
triplets_txt = """UUU CUU AUU GUU UUC CUC AUC GUC UUA CUA AUA GUA
UUG CUG AUG GUG UCU CCU ACU GCU UCC CCC ACC GCC
UCA CCA ACA GCA UCG CCG ACG GCG UAU CAU AAU GAU
UAC CAC AAC GAC UAA CAA AAA GAA UAG CAG AAG GAG
UGU CGU AGU GGU UGC CGC AGC GGC UGA CGA AGA GGA
UGG CGG AGG GGG"""
aas_txt = """F L I V F L I V L L I V L L M V S P T A S P T A S P
T A S P T A Y H N D Y H N D . Q K E . Q K E C R S G
C R S G . R R G W R R G"""
def translate(rna_sequence):
"""
uses codon table to translate rna sequence.
example:
UUU AUC GUU -> F I V
spaces can be omitted.
"""
# cleanup
rna_sequence = remove_whitespace(rna_sequence)
aas = ""
for start_idx in range(0, len(rna_sequence), 3):
triplet = rna_sequence[start_idx : start_idx + 3]
aa = lookup_aa(triplet)
aas += aa
return aas
@profile
def lookup_aa(triplet):
"""finds aa symbol for given triplet.
returns 'X' for invalid triplet"""
# cleanup the multiline strings
triplets = remove_whitespace(triplets_txt)
aas = remove_whitespace(aas_txt)
if triplet not in triplets:
return "X"
start_idx = triplets.index(triplet)
return aas[start_idx // 3]
def remove_whitespace(txt):
# remove spaces and line breaks from string
return txt.replace(" ", "").replace("\n", "")
long_test_sequence = 2000 * remove_whitespace(triplets_txt)
print("test sequence has length", len(long_test_sequence))
res = translate(long_test_sequence)
print(len(res))
Overwriting rna_translation.py
!time python rna_translation.py
test sequence has length 384000 128000 real 0m0.690s user 0m0.646s sys 0m0.022s
!pyinstrument rna_translation.py
test sequence has length 384000 128000 _ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:19 Samples: 784 /_//_/// /_\ / //_// / //_'/ // Duration: 0.785 CPU time: 0.780 / _/ v4.2.0 Program: rna_translation.py 0.784 <module> <string>:1 [4 frames hidden] <string>, runpy 0.784 _run_code runpy.py:64 └─ 0.784 <module> rna_translation.py:2 └─ 0.784 translate rna_translation.py:43 ├─ 0.727 lookup_aa rna_translation.py:64 │ ├─ 0.629 remove_whitespace rna_translation.py:79 │ │ ├─ 0.559 str.replace <built-in>:0 │ │ │ [2 frames hidden] <built-in> │ │ └─ 0.070 [self] │ ├─ 0.062 [self] │ └─ 0.036 str.index <built-in>:0 │ [2 frames hidden] <built-in> └─ 0.057 [self] To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-19 [options]
We can see that the majority of the time is spent in str.replace within remove_whitespace. Let's check it with line-profiler too:
!kernprof -vl rna_translation.py
test sequence has length 384000
128000
Wrote profile results to rna_translation.py.lprof
Timer unit: 1e-06 s
Total time: 0.908832 s
File: rna_translation.py
Function: lookup_aa at line 64
Line # Hits Time Per Hit % Time Line Contents
==============================================================
64 @profile
65 def lookup_aa(triplet):
66 """finds aa symbol for given triplet.
67 returns 'X' for invalid triplet"""
68
69 # cleanup the multiline strings
70 128000 419168.0 3.3 46.1 triplets = remove_whitespace(triplets_txt)
71 128000 284969.0 2.2 31.4 aas = remove_whitespace(aas_txt)
72
73 128000 67176.0 0.5 7.4 if triplet not in triplets:
74 return "X"
75 128000 82465.0 0.6 9.1 start_idx = triplets.index(triplet)
76 128000 55054.0 0.4 6.1 return aas[start_idx // 3]
We can see that remove_whitespace is called 128000 for both arguments times! Since the inputs and outputs will not change for each call of lookup_aa, we can try to move this call outside of lookup_aa:
%%file rna_translation_2.py
import sys
try:
profile
except:
profile = lambda f: f
triplets_txt = """UUU CUU AUU GUU UUC CUC AUC GUC UUA CUA AUA GUA
UUG CUG AUG GUG UCU CCU ACU GCU UCC CCC ACC GCC
UCA CCA ACA GCA UCG CCG ACG GCG UAU CAU AAU GAU
UAC CAC AAC GAC UAA CAA AAA GAA UAG CAG AAG GAG
UGU CGU AGU GGU UGC CGC AGC GGC UGA CGA AGA GGA
UGG CGG AGG GGG"""
aas_txt = """F L I V F L I V L L I V L L M V S P T A S P T A S P
T A S P T A Y H N D Y H N D . Q K E . Q K E C R S G
C R S G . R R G W R R G"""
def remove_whitespace(txt):
# remove spaces and line breaks from string
return txt.replace(" ", "").replace("\n", "")
def translate(rna_sequence):
"""
uses codon table to translate rna sequence.
example:
UUU AUC GUU -> F I V
spaces can be omitted.
"""
# cleanup
rna_sequence = remove_whitespace(rna_sequence)
aas = ""
for start_idx in range(0, len(rna_sequence), 3):
triplet = rna_sequence[start_idx : start_idx + 3]
aa = lookup_aa(triplet)
aas += aa
return aas
# cleanup the multiline strings
triplets = remove_whitespace(triplets_txt)
aas = remove_whitespace(aas_txt)
@profile
def lookup_aa(triplet):
"""finds aa symbol for given triplet.
returns 'X' for invalid triplet"""
if triplet not in triplets:
return "X"
start_idx = triplets.index(triplet)
return aas[start_idx // 3]
long_test_sequence = 2000 * remove_whitespace(triplets_txt)
print("test sequence has length", len(long_test_sequence))
res = translate(long_test_sequence)
print(len(res))
Overwriting rna_translation_2.py
!time python rna_translation_2.py
test sequence has length 384000 128000 real 0m0.120s user 0m0.102s sys 0m0.010s
This is around 5-6 times faster!
!pyinstrument rna_translation_2.py
test sequence has length 384000 128000 _ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:21 Samples: 116 /_//_/// /_\ / //_// / //_'/ // Duration: 0.116 CPU time: 0.116 / _/ v4.2.0 Program: rna_translation_2.py 0.116 <module> <string>:1 [4 frames hidden] <string>, runpy 0.116 _run_code runpy.py:64 └─ 0.116 <module> rna_translation_2.py:2 └─ 0.116 translate rna_translation_2.py:27 ├─ 0.064 lookup_aa rna_translation_2.py:53 │ ├─ 0.037 [self] │ └─ 0.027 str.index <built-in>:0 │ [2 frames hidden] <built-in> └─ 0.052 [self] To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-21 [options]
The appropriate data structure for lookup and associations are dictionaries! Let's try this.
%%file rna_translation_3.py
import sys
try:
profile
except:
profile = lambda f: f
triplets_txt = """UUU CUU AUU GUU UUC CUC AUC GUC UUA CUA AUA GUA
UUG CUG AUG GUG UCU CCU ACU GCU UCC CCC ACC GCC
UCA CCA ACA GCA UCG CCG ACG GCG UAU CAU AAU GAU
UAC CAC AAC GAC UAA CAA AAA GAA UAG CAG AAG GAG
UGU CGU AGU GGU UGC CGC AGC GGC UGA CGA AGA GGA
UGG CGG AGG GGG"""
aas_txt = """F L I V F L I V L L I V L L M V S P T A S P T A S P
T A S P T A Y H N D Y H N D . Q K E . Q K E C R S G
C R S G . R R G W R R G"""
def remove_whitespace(txt):
# remove spaces and line breaks from string
return txt.replace(" ", "").replace("\n", "")
def translate(rna_sequence):
"""
uses codon table to translate rna sequence.
example:
UUU AUC GUU -> F I V
spaces can be omitted.
"""
# cleanup
rna_sequence = remove_whitespace(rna_sequence)
aas = ""
for start_idx in range(0, len(rna_sequence), 3):
triplet = rna_sequence[start_idx : start_idx + 3]
aa = lookup_aa(triplet)
aas += aa
return aas
# cleanup the multiline strings
triplets = remove_whitespace(triplets_txt)
aas = remove_whitespace(aas_txt)
mapping = {}
for start_idx in range(0, len(triplets), 3):
mapping[triplets[start_idx : start_idx + 3]] = aas[start_idx // 3]
@profile
def lookup_aa(triplet):
"""finds aa symbol for given triplet.
returns 'X' for invalid triplet"""
return mapping.get(triplet, "X")
long_test_sequence = 2000 * remove_whitespace(triplets_txt)
print("test sequence has length", len(long_test_sequence))
res = translate(long_test_sequence)
print(len(res))
Overwriting rna_translation_3.py
!time python rna_translation_3.py
test sequence has length 384000 128000 real 0m0.083s user 0m0.066s sys 0m0.010s
!pyinstrument rna_translation_3.py
test sequence has length 384000 128000 _ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:22 Samples: 79 /_//_/// /_\ / //_// / //_'/ // Duration: 0.079 CPU time: 0.079 / _/ v4.2.0 Program: rna_translation_3.py 0.079 <module> <string>:1 [4 frames hidden] <string>, runpy 0.079 _run_code runpy.py:64 └─ 0.079 <module> rna_translation_3.py:2 └─ 0.079 translate rna_translation_3.py:27 ├─ 0.046 [self] └─ 0.033 lookup_aa rna_translation_3.py:57 ├─ 0.018 [self] └─ 0.015 dict.get <built-in>:0 [2 frames hidden] <built-in> To view this report with different options, run: pyinstrument --load-prev 2023-05-16T15-50-22 [options]
Observations:
lookup_aa reduced from ~750ms to ~300ms, which is faster by a factor ~2.5. This speedup will be much more for larger data collections.| Command line | Python function | Jupyter magic | |
|---|---|---|---|
| Time measurement | time |
time.time() timeit.timeit() |
%time %timeit |
| Time profiling | kernprof -vl pyinstrument |
%lprun |
|
| Memory profiling | python -m memory_profiler ... |
%mprun %memit |
Time measurement:
time offers a quick time measurement of code execution.time.time() can be used to capture execution time of a single line or a block of code. To get accurate results, programmers are recommended to run it several times and get the minimum or the average of measured times.timeit.timeit() is suitable for micro-benchmarking. It executes the timer for a number of times. Then, it reports the sum runtime of that execution.%) and cell (with %%) magics:%time is similar to the command line time.%timeit, analogously to timeit.repeat(), executes a code snippet repeatedly with a number of runs and, for each run, a number of times. Then, it reports the averaged runtime.Time profiling:
Profiling of the whole script helps to specify bottlenecks in the code. The profilers comes with an overhead and is not suitable for benchmarking (as %timeit does).
%lprun reports easier-to-read line-by-line time measurements of the code. The package needs to be installed and loaded as an extension.kernprof -vl is a command line for line profiling.pyinstrument is a command line which measures and reports time per function.Memory profiling:
We can also see the memory consumption of the code by using the memory profiler. It comes with an overhead, even higher than that of the line profiler. The package needs to be installed and loaded as an extension.
%mprun reports line-by-line memory used of the function which needs to be written to an external file.%memit is a single-line profiler reporting memory use, including temporary memory use, of a line of code.