Notes on profiling Python applications
I've been watching a looooot of Scott Hanselman lately and in one of his videos, he googles for the sentence "penny pinching in the cloud" and a bunch of his articles are the top hits. He talks about how he blogs about things as a way of maintaining notes for his future self. My articles might not be top hits on google for any sentence but I can still find them in my blogpost history.
Over the weekend, I spent a little bit of time profiling a Python GUI application. It's been a while since I profiled Python code and every single time I forget how to set things up and get it working. There are the usual Python standard library modules cProfile and pstats but there are a lot of powerful visualisation techniques that help you better understand the profiling results.
First of all, when you are profiling a GUI application (or profiling anything for that matter) in Python, the first question to answer is what exactly are you trying to measure? In my case, what I was really trying to measure was the "Time to first interaction" (which is a new word that I learnt recently). Time to first interaction is the time it takes between when a user starts the application (say by double clicking the application icon) and when the user can start interacting with the application.
TFI (Time to First Interaction) is important because we want to provide a good user experience and we don't want them to wait for multiple minutes while the application starts up.
So we now know what I want to measure and why it is important. Let's look at how.
In this specific case, I was debugging an Envisage TasksApplication. This is relevant because the TasksApplication class thankfully emits an application_initialized event when the GUI application has been initialized. So, theoretically, I could try hook up my profiler such that it counts the time between when I start the application and when this event is emitted.
I was lazy. So, instead of figuring out how to get that working, I just decided to close the application as soon as the event is emitted. I can do that by simply saying application.on_trait_change(application.exit, 'application_initialized'). What that does is - when "application_initialized" event is emitted, run "application.exit". And then I just profiled the application lifecycle i.e. from when I start the application to when it stops itself.
I can now write a simply script which starts the application - and then the application immediately stops itself. I can now use cProfile to profile this script using
python -m cProfile -o startstopprofile.prof start_and_stop_application
This should now create a startstopprofile.prof binary file in your current directory. Investigating the contents of the file using the pstats standard library package is a bit of a pain - especially in the case of this GUI application which has multiple dependencies and have a large call stack.
So, we instead turn to GUI tools. I was struggling to remember the visualization tool that an ex-colleague of mine introduced me to (Thanks Pankaj!). And after searching haphazardly for python profile visualization tools, I finally caught a partial word "Snake" which triggered my memory to remember thet tool - snakeviz. It takes a couple of seconds to get a handle on the UI but once you do, it is very useful.
I tried profiling an example script in the Envisage GitHub repository using almost the same process and here is the output of the profiling, visualized using snakeviz.
I still need to figure out how to visualize the profiling results using flamegraphs but let's leave that for another time.