Profiling: using kernprof in Blender add-ons

When implementing add-ons that contain very time consuming activities, profiling can be a tremendous help in pinpointing the hotspots in your code. And if you use Numpy a lot, where a lot of hard work is hidden in a few lines of code, a line profiler is a godsend. I used it for instance in researching bottlenecks in some tree related code.

Now the excellent kernprof package offers basically all we need and works fine for stand-alone Python programs but I want to use it inside Blender add-ons and this article illustrates what is needed to get it working. It's a bit fiddly but well worth it if you really want to optimize your code.

Installing the kernprof package

This works under Linux if your python3 version is the same as the one inside Blender (3.5.x as I am working with Blender 2.78a, I am not sure this works under Windows).

Installation

First we have to install the kernprof package:
pip3 install line_profiler
This will install the package in whatever location you use as default with pip, in my case /home/michel/.local/lib/python3.5/site-packages

Now currently the developer of kernprof decided to make IPython a hard requirement which in our case makes things more difficult because we want to use the profiler just in Blender and do not want to rely on any extra stuff. It is however simple enough to remove these dependencies and leave us a LineProfiler class that just works.

This stripped version is available on GitHub and you should download this version to replace the one that was installed by pip (in my case /home/michel/.local/lib/python3.5/site-packages/line_profiler.py)

Now we can start creating add-ons where functions can be profiled on a line by line basis and I will highlight the relevant pieces of code.

Because we installed the kernprof package outside Blender's Python libraries, we have to make sure we can find the modules by adding the path:

sys.path.append('/home/michel/.local/lib/python3.5/site-packages')

from line_profiler import LineProfiler
profile = LineProfiler()

After adding the path we can import the LineProfiler class and create an instance of it.

This instance can be used as a decorator on functions that we want to profile. Note that it is currently not possible to add this decorator to the execute() function of an operator otherwise Blender will complain. Apparently there is something weird going on when the function is wrapped.

 @profile
 def expensive_stuff(self,a,b):
  for i in range(a):
   c = b * b

 def execute(self, context):
  self.expensive_stuff(1000,100)

Currently I have chosen to dump the statistics when we disable the add-on. On disabling the unregister() function is called automatically and we use this to write the statistics in the same directory as where our module is located and use a filename with the same name but with a .prof extension:

def unregister():
 bpy.types.INFO_MT_mesh_add.remove(menu_func)
 bpy.utils.unregister_module(__name__)
 profile.dump_stats(splitext(__file__)[0]+'.prof')

If our addon file was called exampleaddon.py we could (after disabling the add-on) use the same line_profiler module outside of Blender to show the accumulated statistics:
python3 -m line_profiler /home/michel/.config/blender/2.78/scripts/addons/exampleaddon.prof
The result for our silly example function looks like the listing below, interpreting the results is up to you (please refer to the documentation on the kernprof site.)

Timer unit: 1e-06 s

Total time: 0.002952 s
File: /home/michel/.config/blender/2.78/scripts/addons/exampleaddon.py
Function: expensive_stuff at line 33

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    33                                            @profile
    34                                            def expensive_stuff(self,a,b):
    35      3003         1411      0.5     47.8    for i in range(a):
    36      3000         1541      0.5     52.2     c = b * b

Full example code

The complete code for a tiny example add-on that provided the code snippets showed earlier is listed below:

bl_info = {
 "name": "Expensive Operation",
 "author": "Michel Anders (varkenvarken)",
 "version": (0, 0, 201612231212),
 "blender": (2, 78, 0),
 "location": "View3D > Add > Mesh > Expensive Op",
 "description": "A time consuming operator to test profiling options within Blender add-ons",
 "warning": "",
 "wiki_url": "",
 "tracker_url": "",
 "category": "Add Mesh"}
         
import bpy
import sys
from os.path import splitext

# make sure we can find (the hacked version of) line_profiler
sys.path.append('/home/michel/.local/lib/python3.5/site-packages')

from line_profiler import LineProfiler
profile = LineProfiler()


class ExpensiveOp(bpy.types.Operator):
 bl_idname = 'mesh.expensiveop'
 bl_label = 'Expensive Operator'
 bl_options = {'REGISTER','UNDO'}

 @classmethod
 def poll(self, context):
  return (context.mode == 'OBJECT')

 @profile
 def expensive_stuff(self,a,b):
  for i in range(a):
   c = b * b

 def execute(self, context):
  self.expensive_stuff(1000,100)
  # this is just to show something happened
  bpy.ops.mesh.primitive_cube_add()
  context.active_object.name = 'Expensive Cube'
  return {"FINISHED"}

def menu_func(self, context):
 self.layout.operator(ExpensiveOp.bl_idname, text=ExpensiveOp.bl_label, icon='PLUGIN')

def register():
 bpy.utils.register_module(__name__)
 bpy.types.INFO_MT_mesh_add.append(menu_func)

def unregister():
 bpy.types.INFO_MT_mesh_add.remove(menu_func)
 bpy.utils.unregister_module(__name__)
 profile.dump_stats(splitext(__file__)[0]+'.prof')