<jupyter_start><jupyter_text>Profiling Python code with line_profilerOnce we have working, readable, debugged (and hopefully testable) code, it may become important to examine and try to improve the performance of our code. Before we can make any progress in determining if our code is an improvement, we need to measure the current performance and see where it is spending its time. In [another article](https://www.wrighters.io/profiling-python-with-cprofile-and-a-speedup-tip/), I wrote about using the built in Python profiler, ```cProfile```, to obtain a profile of some Python code. When you use ```cProfile```, the results you see show the relative performance of every function called from within the code being profiled. Because of this, the granularity you see is not going to tell you all the details you may need to isolate your slowest lines of code. In the example from that article, the function being tested ended up calling into a few other modules (the sqlite module), and we were able to spot where we were spending out time and made a version that used a cache to speed things up pretty easily.Sometimes though, ```cProfile``` is not the best tool to use to isolate what is happening in our code. It turns out lots of typical code will either * do a lot of work without calling many functions * makes function calls that in turn make a *lot* of other functions calls Both of these situations can make the output of ```cProfile``` pretty useless or hard to wade through. Let's look at an example. Here's some code that takes a sample ```DataFrame``` of names and phone numbers and just splits the name into first and last name. Pretty trivial, but I'll write the first pass of code with a few obvious (or maybe not so obvious) performance problems.<jupyter_code>import pandas as pd
import numpy as np

import logging

from faker import Faker

fake = Faker()

logging.basicConfig(level=logging.INFO)

df = pd.DataFrame([(fake.name(), fake.phone_number()) for _ in range(1000)], columns=['name', 'phone'])
df.head(3)

def function_with_issues(df):
    logging.debug(f'called with {df}') 
    def _get_first_name(n):
        return n.split()[0]
    def _get_last_name(n):
        return ' '.join(n.split()[1:])
    
    df['first'] = df['name'].apply(_get_first_name)
    df['last'] = df['name'].apply(_get_last_name)
    
    return df<jupyter_output><empty_output><jupyter_text>Profiling with cProfileI will also assume that this code has been tested and yields the desired results, i.e. the resulting ```DataFrame``` has first and last names as desired.  Now just by inspection, you very well may be able to spot performance problems here and have plans to fix them, but let's see what a profiler will tell us.<jupyter_code>import cProfile

with cProfile.Profile() as pf:
    function_with_issues(df)
    pf.print_stats()<jupyter_output>12890 function calls (12469 primitive calls) in 0.015 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(all)
        4    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(append)
        2    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(atleast_2d)
        2    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(bincount)
       10    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(concatenate)
        5    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(copyto)
        4    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(ndim)
        4    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(ravel)
       16    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:1017(_handle_fromlist)
        1    0.000    0.00[...]<jupyter_text>So good luck with that. You can take this profile data and try to sort it and figure out what is happening, but essentially, by using pandas you have brought in a fairly complex set of modules that will generate *lots* of function calls. Where do you start to try to speed this up?This is where [```line_profiler```](https://github.com/pyutils/line_profiler) comes in. It is another profiling tool, not included with Python by default, that you can use to profile individual lines in a function so you can see which lines are expensive.You can install it with ```pip```.<jupyter_code>%pip install line_profiler<jupyter_output><empty_output><jupyter_text>I found the ```line_profiler``` documentation a little bit confusing to get started quickly, so I'll try to boil it down to the basic usage here so you can quickly get it running in your environment.  Once you install it with pip, you should be able to use it one of three ways:* import it into a session and use the profiler directly* use the command line tool (```kernprof```) to run your code in another script* use the IPython/Jupyter magic (```lprun```) to run code in a session or notebookI'll go through all three of these now. Running the line_profiler in codeThe first way you could choose to use ```line_profiler``` is directly in code. This is probably not the way you'll likely choose to use it in the end, but I think it's helpful for understanding the mechanics of the tool. Once you import the module, you can make an instance of the ```LineProfiler```, just like you would with ```cProfile.Profile```. You then need to tell the profiler which functions to profile. Finally, you need to run a wrapper function that will cause those functions to execute. You can then print the stats generated by the profiler.<jupyter_code>import line_profiler

lp = line_profiler.LineProfiler()

lp.add_function(function_with_issues)

# this could be any existing function as well, you don't have to write this from scratch
def wrapper_function():
    function_with_issues(df)

wrapper = lp(wrapper_function)
wrapper()

lp.print_stats()<jupyter_output>Timer unit: 1e-06 s

Total time: 0.012014 s
File: <ipython-input-1-7fb197a24a44>
Function: function_with_issues at line 15

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    15                                           def function_with_issues(df):
    16         1       8471.0   8471.0     70.5      logging.debug(f'called with {df}') 
    17         1          2.0      2.0      0.0      def _get_first_name(n):
    18                                                   return n.split()[0]
    19         1          0.0      0.0      0.0      def _get_last_name(n):
    20                                                   return ' '.join(n.split()[1:])
    21                                               
    22         1       2160.0   2160.0     18.0      df['first'] = df['name'].apply(_get_first_name)
    23         1       1379.0   1379.0     11.5      df['last'] = df['name'].apply(_get_last_name)
    24    [...]<jupyter_text>The resultsNow you can see the results of your line profile. Instead of telling you all the underlying code executed by your few lines of pandas code, you just see how much time is spent on each line. Note that the timer unit is at the top of the output (microseconds in this case), and if you multiply the time by this unit, you will get the time spent on that line.Before we start discussing improving these times, let's review the other ways you might choose to run the ```line_profiler```. Using magicIf you're running code in a notebook or IPython session, you'll likely want to use the ```lprun``` magic. Just load the ```line_profiler``` extension and then you can run the code in one line. Just tell it which functions to profile using the ```-f``` switch, and run the driver function on the same line. There are other options for dumping results and running entire modules, you can check the docs or use ```%lprun?``` in your notebook to read the help.<jupyter_code>%load_ext line_profiler

%lprun -f function_with_issues function_with_issues(df)<jupyter_output><empty_output><jupyter_text>Using kernprofYou can also run the ```kernprof``` tool from the command line. In that case, you just need to mark your code with the decorator ```@profile```, then run the script from the comand line. This generates a binary file with the profile data.You then can read the profile data and output the result.For the example above, we could put the following code in a single python file (performance_line_profiler.py).<jupyter_code>import pandas as pd
import numpy as np

import logging

from faker import Faker

fake = Faker()

@profile
def function_with_issues2(df):
    logging.debug(f'called with {df}')
    def _get_first_name(n):
        return n.split()[0]
    def _get_last_name(n):
        return ' '.join(n.split()[1:])

    df['first'] = df['name'].apply(_get_first_name)
    df['last'] = df['name'].apply(_get_last_name)

    return df


if __name__ == '__main__':
    df = pd.DataFrame([(fake.name(), fake.phone_number()) for _ in range(1000)], columns=['name', 'phone'])
    function_with_issues2(df)<jupyter_output><empty_output><jupyter_text>Then, you'd need to make sure that you have the Python environment loaded on the command line where you installed ```line_profiler``` using pip. I use pyenv and virtualenv to create a specific virtualenv that I activated and used for this example. In a session with that virtualenv activated, I can then run the kernprof tool.```$ kernprof -l performance_line_profiler.pyWrote profile results to performance_line_profiler.py.lprof```Then,  you can view the results, like this:```$ python -m line_profiler performance_line_profiler.py.lprof```You'll get the same results you did earlier. The speedupNow, circling back to our profile results. First we see the code is spending a large amount of time in a logging debug statement, even though you'll see that we are not running at debug level. I thought logging was supposed to be essentially a no-op if you aren't running at that level?  What's going on?The lesson here is to not eagerly format your log strings. When you're logging, you should recognize you are sending a format string as the first argument, with the format arguments being passed in but not applied. If you are not logging that statement, you don't want to spend any time doing any string formatting.Second, we can avoid calling apply with a function on our dataframe and use the built in string functions in pandas and do the name splitting with fewer lines of code. Here's a first cut, which we can quickly profile.<jupyter_code>def updated_function(df):
    logging.debug('called with %s', df)

    splits = df['name'].str.split().str
    df['first'] = splits[0]
    df['last'] = splits[1:].str.join(' ')

    return df
%lprun -f updated_function updated_function(df)<jupyter_output><empty_output><jupyter_text>Well, we see right away that removing the eager logging format was wise, it's now basically a no-op. But it turns out this new approach is not faster than our old apply-based method for this test data. It turns out creating a temporary variable to store the result of the split costs some time, and accessing the split data is also slow. We could do the split twice, but it's still slower than the old approach.  It turns out that using ```apply``` and string splitting on the values is faster than using the pandas built-in ```str``` accessors. This was a bit of a surprise to me, and I'm sure we could dig into this to learn some more. Maybe that's another article for another time. But the lesson is it pays to profile! Just to reinforce this with a much simpler example, we can use ```%timeit``` to observe these differences for splitting.<jupyter_code>%timeit df['name'].str.split().str[0]
%timeit df['name'].apply(lambda x: x.split()[0])
%timeit df['name'].str.split().str[1:].str.join(' ')
%timeit df['name'].apply(lambda x: ' '.join(x.split()[1:]))<jupyter_output>520 µs ± 14.5 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)
{'fraction_non_alphanumeric': 0.08526035601397439, 'fraction_numerical': 0.026701048078522707, 'mean_word_length': 3.667313664596273, 'pattern_counts': {'":': 0, '<': 40, '<?xml version=': 0, '>': 40, 'https://': 2, 'lorem ipsum': 0, 'www.': 1, 'xml': 0}, 'pii_count': 0, 'substrings_counts': 0, 'word_list_counts': {'cursed_substrings.json': 8, 'profanity_word_list.json': 0, 'sexual_word_list.json': 0, 'zh_pornsignals.json': 0}}
{'chain_length': '8', 'dir': 'jupyter-structured-clean-dedup', 'id': '642232', 'license': 'CC0-1.0', 'n_tokens_mistral': 3518, 'n_tokens_neox': 3315, 'n_words': 1577, 'path': 'performance/performance_line_profiler.ipynb', 'repo_name': 'wrighter/python_blogposts', 'size': '12022'}