Profiling in Django

Profile your Django apps with ease.

This article is written as a part of Individual Review competency for Software Projects course 2020 at Faculty of Computer Science, University of Indonesia.

As developers, we strive to bring feature requirements to life. We utilized every tool at our disposal to fulfill them. The product is validated, the features are accepted. Great.

But sometimes, the unintended happens: our application perform poorly, the request-response cycles takes too long, and other performance issues arise. This leads us to a question: how to easily spot which code that bring impacts to the performance?

This article will discuss briefly about profiling and give examples of profiling tools to profile a Django application.

Profiling

Taken from Wikipedia, profiling is a form of dynamic program analysis that measures, for example, the space or time complexity of a program, the usage of particular instructions, or the frequency and duration of function calls.

Profiling can be achieved either by instrumenting either the program source code or using a tool called profiler. This article will limit the discussion to the latter. The aforementioned metrics are related to the performance of our application. Knowing which aspect our application performed poorly is advantageous as to knowing which “hot spot” that can be optimized.

Django Profiling Tools

Many Python profiling tools exist, but this article will limit only to the most used tools: cProfile and django-silk . The two tools mainly profile in regards to function calls and execution time.

Profiling Django with cProfile

cProfile is a built-in profiler tool provided by Python. Alongside profile , it provides deterministic profiling of Python programs. cProfile is recommended for most users as it brings more reasonable overhead than profile . Thus, cProfile is more suitable for profiling long-running programs.

The official documentation provides a manual for profiling simple Python application and detailed reference on its module. To incorporate cProfile to Django views, we can write our own middleware that captures the profiling on every request sent to our Django views. But thankfully, there exists a simpler solution: django-cprofile-middleware. It is a simple profiling middleware created by a Github user omarish. With a simple installation to our Django application, we can profile any Django view with it.

To install this middleware with pip, just run

pip install django-cprofile-middleware 

Then, add django_cprofile_middleware.middleware.ProfilerMiddleware to the end of MIDDLEWARE in the settings file (usually settings.py ).

It should look like this:

MIDDLEWARE = [
    "django.middleware.security.SecurityMiddleware",
    "django.contrib.sessions.middleware.SessionMiddleware",
    ....
    "django_cprofile_middleware.middleware.ProfilerMiddleware",
]

Or, if you are using Django version lower than 1.10, add the middleware to the of MIDDLEWARE_CLASSES setting.

The profiler will only be available when the setting DEBUG is set to True . It also requires us to be logged-in as an authenticated user which is_staff option is set to True . To disable this requirement, we can add an additional setting as follows:

DJANGO_CPROFILE_MIDDLEWARE_REQUIRE_STAFF = False .

Now we are going to profile an endpoint with the code snippet below as its corresponding view class.

Sample view for the demonsration.

Basically, the view will look up a user object from the database by username and email from the given username and email argument. If the query matches any, it will return HTTP 200. Otherwise, it will return HTTP 404.

The view can be accessed from

http://localhost:8000/api/auth/users/availability/?username=<name>&email=<email>/

To profile this view with the installed middleware, we can just append prof parameter to the end of the URL, i.e.

http://localhost:8000/api/auth/users/availability/?username=<name>&email=<email>&prof 

Here is the result from the profiler, displayed in HTML output:

The profiling result from cProfile.

There is a lot going on in the output. Let’s take a look at what every line represents…

• The first line indicates that 1850 function calls were monitored. Out of 1850 calls, 1811 were primitive, which means that they were not induced via recursions.
• The second line: Ordered by: internal time , tells us that the output was sorted by the tottime column.

Now onto the columns…

• ncalls : total number of calls to the given function at the corresponding row. You may noticed that there are two numbers displayed (for example 245/242 ). This data means that the respective function recursed (performed recursion), where the second value, 242 is the number of primitive calls and the first value, 245 is the total number of calls.
• tottime : the total time spent in the given function at the corresponding row (excluding call time to sub-functions).
• percall (the first one): the quotient of tottime divided by ncalls .
• cumtime : the cumulative time spent in the given function including its subfunctions.
• percall (the second one): the quotient of cumtime divided by primitive calls.
• filename:lineno(function_name) : the respective function.

By default, the profile result is sorted by tottime . We can modify the sorting criteria by adding query parameter sort with one of the possible values supported by pstats library. For example:

http://localhost:8000/api/auth/users/availability/?username=<name>&email=<email>&prof&sort=ncalls

We can also tell the middleware how many results to be displayed by adding query parameter count with zero or positive integer value. For example:

http://localhost:8000/api/auth/users/availability/?username=<name>&email=<email>&prof&count=200

This has the default value of 100.

Are we stuck with this form of display? Of course not, we can visualize the profile result further with Python profiler visualizing library, such as SnakeViz . We will choose SnakeViz for this demonstration.

To install SnakeViz using pip , run pip install SnakeViz .

Before visualizing the profile result, we need to download it by adding query parameter download . For example:

http://localhost:8000/api/auth/users/availability/?username=<name>&email=<email>&prof&download 

Save the output file to any directory. By default the file will be named view.prof .

Open the command line to where the view.prof is located, then run snakeviz view.prof . The library will open a web server on port 8080 and automatically open a web page containing the visualization.

The visualized profile result.

The visualized data is very interactive. We can inspect a single function call to see its profile information, such as call stack, file name, line number (where the function resides), and the file directory in which the file resides in our working directory. In addition, we received the previous profile data with sorting and searching features.

Profiling, stylized.

We can also tweak the SnakeViz ‘s settings such as display style, function call depth, and cutoff, as shown in the figure above.

With this tool, we can interactively pinpoint which line of code that brings performance impact to our view. Once pinpointed, we can take appropriate action such as optimizing the code.

Profiling Django with django-silk

So far, cProfile has done us good in pinpointing which line of code that brought performance impact to our view. But the profile result could not show which database query that brings performance hit. This is needed especially when our application is centered around database (SQL) queries.

That’s where django-silk comes in. django-silk is developed and maintained by the good folks at Jazzband. The library, called Silk, has the ability to display database queries information to its user interface (UI). That’s what makes this tool is much more powerful and more suitable for Django application. In fact, Silk can also be combined with cProfile , giving us a complete profiling tool.

Silk can be installed via pip via this command:

pip install django-silk

Then, we need to add the followings in settings.py :

MIDDLEWARE = [
    "django.middleware.security.SecurityMiddleware",
    "django.contrib.sessions.middleware.SessionMiddleware",
    "silk.middleware.SilkyMiddleware",
    ...
]
INSTALLED_APPS = [
    ...
    "silk",
]

To enable access to the UI, we need to add the following to urls.py :

urlpatterns += [path("silk/", include("silk.urls", namespace="silk"))]

Make sure to run python manage.py migrate and python manage.py collectstatic before using Silk.

Now, Silk will automatically intercept requests we make to our views and the UI can be accessed from the path /silk/ .

We will use the same URL from the cProfile section for this demonstration:

localhost:8000/api/auth/users/availability/?username=<username>&email=<email>/

After making some requests to the view, the results will be displayed in the Silk UI.

The profile results displayed on Silk UI.

We can see from the above figure that every requests were intercepted. Silk gives us the timestamp of the request (in UTC), the HTTP method and response code, the URL accessed, the total time spent overall, the total time on making database queries, and how many queries were made.

We can inspect a profile result to see the details, as shown in the figure below.

The detail of a profile result.

Each detail contains the information on query parameters (if any), request headers, response headers and raw response body (not shown above).

Note: Because Silk intercepts and stores all HTTP requests into the database in plain text (to Silk’s own database tables), including sensitive ones, it is imperative that we should only use Silk in development or testing environment as to not bring the Silk database into production environment.

Remember that Silk has the ability to show the database queries? We can see them by going into the “SQL” section.

The SQL queries that were made.

We can see all the queries including involved tables, number of SQL joins, and execution time in miliseconds. Clicking one of the query will result in another SQL detail page.

Detailed query and the related Python traceback.

We can see the raw SQL query alongside the Python stacktrace that leads up to the said query. By having this information, we can learn what goes on behind the scene as we make Django ORM (Object Relational Mapping) calls from the Python level inside the view. We can decide whether our ORM queries were efficient or not and we can take appropriate actions.

Conclusion

Profiling is an important activity in software engineering. It enables us to inspect our application so we can decide whether we should do optimization or not. Having a good profiling tool is also important; we can rely on them on finding “hot spot” in our application.

This wraps up the article. If you have any suggestions, don’t hesitate to comment :)

Thanks for reading!

References

The Python Profilers - Python 3.8.2 documentation

omarish/django-cprofile-middleware

jazzband/django-silk