Line-by-line Profiler for Python

Sometimes you may experience unexpectedly long execution of some of your functions. In some cases, you will not even have an idea what causes this behavior and running code line-by-line will not give you much insight.

Thankfully, there's a tool called line-profiler (link) which solves this nicely.

Example

Let's take a look at this simplified function that processes a pandas dataframe.

import numpy as np
import pandas as pd


def process_df(df: pd.DataFrame) -> pd.DataFrame:
    df = df.copy()

    df['new_col'] = df.apply(lambda row: np.sum(np.cos(row)), axis=1)

    extra_df = pd.DataFrame({
        'col1': np.random.randint(200, size=1000),
        'col2': np.random.randint(200, size=1000),
    })

    df = df.merge(extra_df, how='left', left_on=1, right_on='col1')

    return df


if __name__ == '__main__':
    process_df(pd.DataFrame(np.random.randint(200, size=(50000, 20))))

The process_df function takes quite some time to return the results. But what is to blame? It can be any of these:

df.copy() which copies the whole dataframe
calculation of the new_col which is doing a cos for each single number in the dataframe
df.merge() that join two large dataframes

Profiling

Let's start with installing the profiler:

$ pip install line_profiler

Then, we need to tell it which function(s) to profile. It's as easy as adding a @profile decorator:

@profile  # you don't have to import it, kernprof imports it on its own
def process_df(df: pd.DataFrame) -> pd.DataFrame:

Now it's ready to be profiled, use kernprof command (which is installed with profiler).

-l - use line-by-line profiling
-v - show results (default behavior is to write results to a binary .lprof file)

$ kernprof -l -v test.py
Wrote profile results to test.py.lprof
Timer unit: 1e-06 s

Total time: 18.4293 s
File: test.py
Function: process_df at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           @profile
     6                                           def process_df(df: pd.DataFrame) -> pd.DataFrame:
     7         1       5610.0   5610.0      0.0      df = df.copy()
     8
     9         1   18389148.0 18389148.0     99.8      df['new_col'] = df.apply(lambda row: np.sum(np.cos(row)), axis=1)
    10
    11         1          2.0      2.0      0.0      extra_df = pd.DataFrame({
    12         1         60.0     60.0      0.0          'col1': np.random.randint(200, size=1000),
    13         1        900.0    900.0      0.0          'col2': np.random.randint(200, size=1000),
    14                                               })
    15
    16         1      33577.0  33577.0      0.2      df = df.merge(extra_df, how='left', left_on=1, right_on='col1')
    17
    18         1          1.0      1.0      0.0      return df

Now it's super clear, that the new_col calculation is the culprit. The results are saved in a .lprof file which you can send to someone or later see the output again:

$ python -m line_profiler test.py.lprof

Usage in IPython

To use the profiler in ipython you can use the %lprun extension that comes with the package:

In [1]: %load_ext line_profiler

In [2]: %lprun -f  process_df for _ in range(1000): process_df(pd.DataFrame(np.random.randint(200, size=(10, 20))))
Timer unit: 1e-06 s

Total time: 8.51505 s
File: /Users/stasdeep/Code/sd-blog/_test.py
Function: process_df at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           def process_df(df: pd.DataFrame) -> pd.DataFrame:
     6      1000      68483.0     68.5      0.8      df = df.copy()
     7
     8      1000    5250545.0   5250.5     61.7      df['new_col'] = df.apply(lambda row: np.sum(np.cos(row)), axis=1)
     9
    10      1000       1594.0      1.6      0.0      extra_df = pd.DataFrame({
    11      1000      36796.0     36.8      0.4          'col1': np.random.randint(200, size=1000),
    12      1000     719944.0    719.9      8.5          'col2': np.random.randint(200, size=1000),
    13                                               })
    14
    15      1000    2436563.0   2436.6     28.6      df = df.merge(extra_df, how='left', left_on=1, right_on='col1')
    16
    17      1000       1128.0      1.1      0.0      return df

Note that the profile counts the number of hits to every line. In this case each line was executed 1000 times, as the function was inside a loop.