Python Profilers

BY Dinesh Surapuraju

October 01, 2019

Python Profilers.png

Python performance measurement tools help us to identify performance bottlenecks in our app. This allows us to focus on the business logic as opposed to writing custom code, setting it up with our app, and then figuring out whether the results are accurate enough. These tools are well tested by the open source community and used by many companies to measure the performance of their web apps.

What are we looking to measure? 

When it comes down to performance for any web application, we mainly want to measure the following things:

  1. Page load time/response time
  2. SQL queries: Number of queries, n+1 queries (click here to find out how Scout can help you here), Long-running queries
  3. Performance bottlenecks in the application
  4. Third party HTTP calls

1. Page load time/response time

Page load time and response time measurements gives us a fair idea as to where we should be looking. When using Django templates, we measure the page load time as the entire HTML file is fetched from backend. In the case of rest-based services, we measure the response time of the individual API’s, which sends data to the JavaScript code that gets executed in the browser. This then generates the HTML code. 

2. SQL queries

This metric helps us to figure out if database queries are what is degrading the performance of our app.

3. Performance bottlenecks in the application

In some cases, the application code might not be efficient and can cause the app’s performance to degrade. For example, a routine which takes O(n2) might drastically slow down the app as the size of the data increases.

4. Third party HTTP calls

Knowing that the issue is with a third party allows us to focus on this instead of profiling the code that we have written.

Now that we know what we want to measure, let us find some tools that can be used to measure the above parameters.

In this post, we will look at two such tools in Django.

Django-debug-toolbar (DDT)

This is one of the early performance measurement tools created for Django and is the main reason why it is tailored more towards Django templates. The initial version was created in August, 2008. It only works for responses that have content-type as text/html or application/xhtml+xml. If you are using templates, then the debug-toolbar fits perfectly in your toolbox. 

The toolbar opens up right in the page that you are measuring.

python-profilers-1.png

Django-debug-toolbar (In the right corner)

We can measure page load times, SQL query time, and perform code profiling to identify performance issues. DDT also has many third party plugins like flamegraph, line-profiler, etc., which can come in handy. Line profiler allows the developer to profile the code line by line without much of a setup, and flamegraph shows a visual representation of CPU time, allowing the most frequent code-paths to be identified quickly and accurately.

All of the stats are provided in the same page so that we don’t have to navigate to a different page.

Let’s look at the page load time as shown by DDT.

python-profilers-2.png

Page load time

It shows the CPU time for the entire page to be processed. It also shows the browser timing. Browser timing makes sense for Django templates, as Django generates the entire HTML that the page requires. In case of a rest-based service, the response usually is either XML or JSON data, not HTML.

Let’s see what stats are available for SQL queries. They can be found by clicking on the SQL navigation bar.

python-profilers-3.png

SQL query time

It shows all of the SQL queries made in that page and the individual query time for each of those queries. We can also look at the query plan by clicking on Expl. From these stats, we can identify long-running queries and the queries that have joins in them. We can also see if there are any duplicate queries being made in the page.

DDT also shows us stats for cache. Using this information, we can make well-informed decisions about when to evict cache and how effective they are being utilized in a particular page.

python-profilers-4.png

Cache stats

When it comes to setting up DDT, if you are using Docker for your app, you might find it difficult to do the initial setup. It expects us to set INTERNAL_IPS in settings.py, and finding the IP in a container is quite complicated, as it is not fixed and it takes the IP address from the Docker network. If you are running locally using python manage.py runserver, then you can add ‘127.0.0.1’ to INTERNAL_IPS.

DDT provides profiling information for the processing of the request.

python-profilers-5.png

Profile information

Since the information is provided for the entire request, there might be a lot of noise. This is because it also shows the timing for all of the internal function calls of Django and other libraries that we might be using in our app.

So, in conclusion, we can see that DDT pretty much supports measuring all of the metrics that we are interested in.

Django-silk

Django-silk works with templates and rest-based API’s. Unlike Django-debug-toolbar, silk has a separate dashboard page where it displays relevant statistics. So, be it a template or an API, it works very well. The initial release was June, 2014.

The summary (home page) in the silk dashboard shows the following metrics:

  1. Most time overall (shows the requests which took the most time)
  2. Most time spent in database (shows the requests which spent the most time in database)
  3. Most database queries (shows the requests which did the greatest number of DB queries)

python-profilers-6.png

Home page

The home page shows us most of the metrics that we are interested in. 

Just by looking at the home page we can easily identify the requests that are problematic. This is very convenient for a developer, as it is presented in a sorted fashion.

Let us look at how Django-silk presents the stats for response time of a request.

python-profilers-7.png

Response time

It shows the overall time, the time spent in database queries, and the number of queries made in the request.

If we go to the SQL tab from a request that we are interested in, silk shows the query time and the number of queries made in that request. It also displays the tables being accessed and the number of SQL joins made. It shows the execution time for individual queries as well. SQL joins stat is very useful. As Django ORM abstracts the database queries, it is very difficult to reason if an SQL join is being made when we query from Django.

python-profilers-8.png

SQL time

It also stores all of the metrics in the database. This is an added advantage, as we can look at the past data as well. Restarting the server or refreshing the page doesn’t remove the stats.

Adding the setting SILKY_META = True will tell us how much overhead Django-silk adds to the request/response.

It also allows us to profile the code using either a decorator or a context manager, providing us with a choice to profile an entire function or just a few lines of code.

Here’s an example of profiling using silk_profile context manager.

from rest_framework import status

from rest_framework.response import Response

from silk.profiling.profiler import silk_profile

from post.serializers import PostSerializer


def get(self, request):

        posts = Post.objects.all()

        post_count = 0

        with silk_profile(name='posts count'):

            for _ in posts:

                post_count += 1

        serializer = PostSerializer(posts, many=True)

        return Response(data=serializer.data, status=status.HTTP_200_OK)


Silk output for the profile looks like this. Profile stats can be found by navigating to the page by clicking on the Profiling tab on the home page. This is very useful, as we can get the query time and the number of queries made in a particular function instead of an entire API. This helps us narrow down the problem.

python-profilers-9.png

Silk profile output with context manager

Using silk_profile decorator for the same example as above, the output looks like this.

python-profilers-10.png

Silk profile output with decorator

Decorator can be used only with functions, but using the context-manager we can choose which code block to profile.

In conclusion, Django-silk also provides pretty much all of the information that we are looking for.

Summary

As you can see both Django-debug-toolbar and Django-silk are useful tools to use during your development process. Which one is more suitable for your project will depend on a number of different factors. Let's compare them based on metrics and features, and leave you to decided which is the best!

Comparison based on the metrics:

undefined

Comparison of the tools based on features:

undefined

As useful as these tools are, it is not recommended that you use these tools in a production environment, as the performance overhead is high and there are also some security concerns (like exposing settings.py and storing plain text passwords, in the case of Django-silk).  If you don’t want to use these tools, and instead you want to write your own custom middleware to collect metrics, you can find a simple code here and add/modify it as per your needs.

Alternatively you can look at application performance monitoring solutions if you want to measure the performance of your production instance without having to worry about a performance overhead. Why not try out Scout APM to monitor your production instance with less overhead and other useful metrics like N+1 queries, memory bloat analysis, GitHub integration etc. which none of the above tools provide.