Analyzing Python Profiles with the Blackfire Timeline
The timeline view is a power profile visualization, which is complementary to the call-graph view. Learn how to use it through a classical N+1 query performance issue resolution.
By Sümer Cip, on Mar 17, 2020 Releasing the Timeline view for Python profiles
In our Profiling 101 for Python Developers blog series, we discussed about the various types of profiles visualizations. We have just released the Timeline feature for Python profiles. Check our full features support list, as Python support is still in Beta.
The Timeline representation sorts stack frames according to their execution time, from the start of the profiled code to its end. It gives a better understanding of when, in time, a specific event happens or function call is executed.
Keep in mind that part of the data pre-processing done by Blackfire involves removing function calls that take less that 1% of the global costs on all dimensions (time, CPU, memory, etc.). This is done to reduce the size of the profiles and to provide a responsive UI.
You can see the full features of Timeline view from our docs.
Using the timeline view on Python Code
Let’s try to diagnose and fix a common performance problem (N+1 query) in Django.
ORMs make it easy to fetch data. But it also becomes easy to write inefficient queries. N+1 queries is such an example. While it might go undiscovered in small development databases, it might become a major problem as data grows. And you don’t want to figure it out in production.
Below is a Django template that renders comments and the question that the comment belongs to.
<body>
<h1>Comments:</h1>
<ul>
{% for comment in comments %}
<li>{{ comment }} - {{ comment.question }}</li>
{% endfor %}
</ul>
</body>
Here is a corresponding model:
class Comment(models.Model):
comment = models.CharField(max_length=255)
user = models.ForeignKey(User, related_name="user_comments")
question = models.ForeignKey(Question)
And finally the view that shows all of the current users comments:
def comments(request):
comments = request.user.user_comments.all()
template = loader.get_template('polls/comments.html')
context = {'comments': comments,}
return HttpResponse(template.render(context, request))
Assume that the current user has hundreds of comments. Let’ see what is shown in the timeline view when profiling this code:
As can be seen from the above image we have hundreds of SQL queries happening that are distributed evenly across the timeline view. The comments of a user should be retrieved in a single query.
What is happening under the hood is a common problem:
Every time {{ comment.question }} is evaluated in the template, an additional query retrieving the Question is executed, which can be seen from the timeline. We can easily see same query is being run over and over again.
To fix this common problem, Django provides a very useful method defined in its model layer: select_related(...). With select_related(...), Querysets will follow the foreign-key relationships and related data will be pre-fetched.
Our fix is to modify the queryset in comments view:
# comments = user.user_comments.all()
comments = user.user_comments.select_related('question').all()
Let’s profile our comments and look at the timeline view again:
We can see that all those queries are merged into a single one.
Timeline and Call-graphs, complementary visualizations
Blackfire offers two complementary visualizations. The call-graph is an amazing option to visualize global bottlenecks, the most consuming calls or code path, or excessive number of calls to a given function.
The Timeline shines for instance in following situations:
- when a specific function is slow only at certain times,
- when there is lots of repetitive work with small overhead like in the N+1 problem example above.
We hope you will enjoy this new visualization for Python code!
Blackfire’s support for Python is still in Beta. We keep on working on new features, and will announce more soon!
