Fast on my machine: How to debug slow requests in production

Yeah, thank you very much for the introduction. As she already said, my name is Rafael. I'm a software developer, entrepreneur, previous co-organizer of this conference. DSF member, so on and so on. I'm very happy to be here and be speaking to you again. Today I'll be speaking about debugging slow requests. Specifically, debugging slow requests that are slow in production. I will talk a lot about database issues and I will be always using PostgreSQL as an example because it's what I know best. The ideas for the other databases are the same, transfer them at your own peril.

We're gonna look at this in Three different scenarios. The first is the scenario in which a specific view in your application is suddenly slow and you need to figure out why and what to do about it The second is that you notice your database being overworked and using too much resources And uh you want to figure out what part of your application is causing it. And the third is short general look at performance issues that are not related to the database, which is rare but does happen. So let's start with a specific view Um that is slow. A customer calls you, sends you an email, complains, I click this button.

It is slow. And Let's work with an example. Let's build a very simple Django app with a very simple database. We have one model that is a publisher, and one model that is a book. The publisher has only a name, the book gets a title, a description, which is going to model the authors as a text field as well to keep it really simple with a published date and a price. And I found a dataset, uh free dataset on the internet with a hundred thousand books, so we have some amount of data. loaded into it. So depending on what industry and type of application you work with, a hundred thousand rows might be a lot or nothing at all. Um in my day job we deal with tables of up to a few hundred millions of rows, so

a thousand times about. So at a hundred thousand rows, lots of queries are still fast even if they're not. Like even a slow query may be a few hundred milliseconds, which might still be acceptable But once we grow a little bigger, it might no longer be. I just didn't find a larger, suitable, simple free data set that we could use here. So I think we've already seen and talked about the common N plus one query issue today, and I'm just gonna repeat it very quickly so we can move on to the more interesting stuff. Um suppose we have a template snippet where we iterate over a list of books and for every book we print the title, the publisher name and the year, like a very short citation. What this will do behind the scenes

is Um create a select quer run a select query for the books and then another select query for every one of the books to fetch the publisher. And obviously that is not the most efficient way to do it. And we've already heard about select related today, um, and prefetch related and I think probably eighty percent of the people in no uh room know these. Um for beginners it's sometimes a little bit hard to understand when to use Which of the two? Um my general rule of thumb is well you need to use prefetch related for many-to-many relations. And I also find myself using prefetch related when I know that many of the books will share the same publishers and I'm working with a large query set because it will save Django from fetching the same publisher from the database again and again and again.

And these issues, they are very important to find and to fix, but it's quite easy to find them during development using tools like Django DebugToolbar, which can show you the number of queries a specific page takes. And there are tools like Sentry that can run in production and auto-detect them and Since a specific century upgrade I started getting emails. Oh, we found an N plus one uh query in your code. Do you want to fix that? And it's really helpful Um but what if we've done all that and we've learned all that and the code looks good and it's executing the right number of queries and it's fine and fast and efficient in the development environment but still slow in production? What most likely happened is that one of your queries

is suddenly slower than when you tested it because of your growth and database size. But how do we figure out which of the queries it is if they're all slow in our Django debug tuber locally? So there's many ways to do this. You can run Django debug tuber in production only for admin users and stuff like that It's I've come up with a different way that I quickly want to share with you. Um I try to replicate the request that the customer was complaining about in my browser, with my session, with the access to the specific view I open up my browser developer tools and I click copy as curl to get a string representation of the request with all the headers going into it. And I built a neat little tool that is I've called Django debug request. It's a management command

where it can just replace the curl at the beginning of the command with manage. py debug request. And what it does behind the scenes is uses Django. test. client to run the exact same request through the Django stack with debug mode enabled just for that one request and it can print out all the queries it's doing And the uh timings that I have. So it's a it's it's twenty lines of implementation for many mentioned command, but it has changed how I debug things in production a lot. Um now but I found the query in this example there's one that takes fifty milliseconds. Okay, that's not that much and in the other one 128, it's not that much. But I can take one of the queries And I can ask my database for the query plan.

We've also heard about query plans in the QA of Karen Stark this morning. I just pre-pend explain analyses and the database Will give me something like this, and as we've already established today, this is not an easy thing to read So we're going to look at a few very specific examples of keywords to look out for even if you haven't fully understood how to read a query plan. And to do so, let's back up a bit and talk about indexes. Indexes are this magic thing that makes your database go fast. But on closer look, indexes are not that magic. They're actually quite simple to understand. Indexes are basically specialized maps to your data.

It's another table that your database manages for you where it creates But it kind of inverses how the data is stored. So if we have an index on the published date of our books, um we have an additional uh We have an additional table where for every published date in order we have a reference to all the books that have this published date. And it makes both finding books with a specific published date as well as sorting books by the published date a lot easier for the database. So how do we figure out that we're missing an index? Let's work with a little bit simpler example of a query. Um we select all the fields from the book table. We have an join of our

uh publisher, which is basically the select related that Django does for us And then we filter all books where the title contains a lot of the rings. And the upper function makes sure that check uh the search is case insensitive. And the query plan for this looks like this, and we don't need to understand everything that's going on here, all the numbers and repetitions and loops and so on. But there are a few key phrases to look out for. One of them is sequential scam, abbreviated here to SEC scam And what it means is that the database is going through the entire table row by row and checking one by one, does the title fulfill my condition? And as you can see it says rows removed by filter, one hundred

three thousand and fifty rows that the database needed to look at, even if they were not necessary for the result. Unsurprisingly, this is not very efficient at a hundred uh milliseconds and if we would have um a thousand times the rows on the table I believe this would scale linearly and we would be talking about a lot more time. So what can we do We can add an index, which in this case would be a very specific index, a little bit more complex because we want to do a substring search, we would do a trigram index. on the uppercase version of the title, we can define that in Django these days. And After we created that title, the most important thing to note about the query plan is that there's no longer a sequential scan going on there.

Instead, there's one of the words that we like to see, which is an index scan. And it the performance goes down from a hundred milliseconds to about 3. 6 milliseconds. So that's nice. Let's look at a second example of how we spot a missing index. If we modify the query a little bit, we say again select star from book and in this case we don't apply a filter but we order by the published state and limit To a hundred books. So we want to see the 100 oldest books in our database. Then we see in the query plan that it is again doing some kind of sequential scan. It's fetching all the books from storage and then applies a sorting algorithm to it. So we see here it's heapsort, we don't care.

What we do care a little about it says memory. It uses 100 kilobytes of memory to do the sorting. And this is still good. If you ever see the word disk in a query plan, you should Either very quickly start tuning your database or your queries because you're gonna be ending up in a very bad situation if the data size is too big but it's gonna be able to handle this in memory But we're not satisfied with the result here of 34 milliseconds. This is probably not linear in uh in in the dataset size, but still bad if it if it grows more. So what we can do is uh even simpler in this case, we just add db underscore index to our Django date field. And the query plan

reduces to an index scan that takes 0. 3 milliseconds. So again, a huge improvement. So let's add indexes everywhere. Oh wait, unfortunately indexes do not come for free. Every index needs storage. Again, it's a table the database manages for you basically. It needs to be saved somewhere. Also, it needs to be updated every time your dataset changes. So while you save time on select, you lose time on update, insert and delete. And PostgreSQL comes with tools To find frequent sequential scans, so you might know which tables might use an index, and indexes that are rarely used, so you might

Consider the to drop the index. However, as an application developer I think these are nice, but I try not to rely on them too much. They tell me only about frequency, but I sometimes care about importance more than frequency. A query might be executed a lot and I might still not care That it's a little bit slow and a query might be executed only once per month, and I still care that it is fast. And it these statistics will not be able to tell me these things. Also, which indexes to create is not always obvious because while indexes are not magic, the query planner most certainly is. Let's look at the combined example of the previous two that we've seen.

We select star from book. We don't filter by the title, we filter by a publisher. Instead, we want all books from publisher 42. We order them by how old they are and want to get the 100 oldest. So PostQSQL now needs to decide is it gonna use the publisher ID index to very quickly fetch all books from Publisher 42? And then sort them? Or is it going to use the published date index to very quickly get the oldest books and figure out which ones are from Publisher 42? So let's do a quick show of hands. Who thinks the database will use an index to speed up the publisher forty-two query? Okay, who thinks it's gonna use the published state

to sort quickly? Okay, very interesting. Who thinks we have no idea and we need to test it Wonderful, that is the correct result. Interestingly, it uses the publisher ID index. And then sorts the result if we do it with publisher 42. But if we do it with publisher 10, it goes the other way around And it uses the index scan on the date and for the result. Turns out there are huge multinational publishers with thousands of books published, and there are small indie companies that publish just one book. And depending on which one you're dealing with, one is way faster than the other. So this is something we deal a lot with in our day-to-day projects

because We have very small and very big clients all in the same database. This is exactly what's happening to us all the time. The database needs to guess Which way the query is going to be executed faster? And what if the query planner guesses badly? The option number one is to make sure it has some information to guess. Postgres will build a statistical model of your table to make good guesses. To build that model, you can run the analyze command. PostgreSQL should be doing this automatically, but if you don't have a DBA on your team, chances are your auto vacuum process is not tuned properly. And you can try if that is the case by execu

if if you execute analyze and suddenly everything gets faster, you should be looking into tuning out a vacuum. However, what we found also to be helpful in our case is to allow PostgreSQL to save more statistics. By default, it would look at a thousand rows and then build a statistical model of your table Based on that, we found for some of our tables it is useful to just let it look at ten thousand rows instead and build a more in-depth statistical model. The second option is to look at specialized indexes, not only on a specific column, but on the Query based on the queries that we often need to do. For our case, we could define a combined index on the published state and the publisher And if we do that, PostgreSQL will decide that the quickest way is to use this specialized index, and our query

time consistently goes down to a very small amount. There is a third option and I'm very cautiously mentioning it. You can try to trick around the query planner, but it's hard because the query planner is is really really clever. Here three times the same query and excl increasingly complex variations. The first is just Select where I order a limit, the second is wrapping the where part in a subquery, and the third in a common table expression. And PostgreSQL, I think, starting version twelve is clever enough to figure out that these are all the same thing and will not be fooled by you trying to write a query and thinking you're clever more clever than the database. In case you are

very, very sure you are more clever than the database, you can tell it to do what you want it to do and do the one thing first. But I would I have seen maybe one or two situations in my career where this was an adequate solution and even there you could probably discuss about it. So usually try one of the other options Give your database the ability to collect more statistics or figure out what indexes are actually useful to you So let's move on to the second situation where we know everything is slow. The database uses a lot of CPU time or disk bandwidth or whatever. And

all our users are suffering because the application is slow. But we don't really know why. And the first thing we we do in a situation like this is we check do we just have high incoming load? Do we have a thousands of people trying to access our site at the same time and if we do it's probably not a problem with our code or not one specific problem we can easily find and fix. It's just what we Need to optimize generally or get more server power or whatever. But sometimes a single feature creates so much load on the database that everything slows down just because one query is execu being executed a lot. So what we do first is we look

on the database directly for long-running queries. PostgreSQL can tell you which queries are currently running and for how long they've been running. And in my experience, if you execute that statement A few times in a row over a few minutes and just look at the results with your eyes, you will see the same query running for ten, twenty seconds over and over again and it will be obvious which query is causing the problem. It is usually less obvious to then figure out which part of your Django code is generating that query. But I have not found a quicker way than knowing your code base very well to work around that. Maybe someone has ideas to share there. If you want to do this in a more scientific way than looking at the output five times

There is PGStat statements, a Postgres extension that can collect statistics about which queries are running how often and how long they take. And again there's tools in Django level like Sentry that we use that can proactively look add performance data of specific queries and where they are coming from. In the third situation and then of course repeat the same process that we had in the first situation where we already knew where the issue was Occasionally though, the application starts to get slow or is slower than we would like it to be under load. But the bottleneck is not the database. So we need to figure out um which resource

Is the bottleneck. And ideally we have some kind of instrumentation in place to look at statistics of our machines, and we can look, is it Is it the memory? Is it the CPU power? Is it I've seen our application to be constrained on network bandwidth before? But with Django applications, I'm gonna bet you ninety-five percent it is the CPU power. Um because Django applications if you don't screw up too much usually don't leak memory too much. They usually have rather constant memory profile once they're running. Um network bandwidth is rarely the issue. Usually you're using up more CPU time than you have. And we've been talking about profilers

today as well already, and my favorite one for a number of years is PySpy. PySpy, unlike C profile, which runs in the Python process and runs the process in a different way, PySpy is a sampling profiler that attaches to a running process. You can do that in your development environment, but you can also attach to running production process without needing to start the process. You can SSH into your server, install PySpy And point PySPy to one of your Gunicorn U Whiskey worker threads and collect profiling information for a few minutes. And unlike C profile as well, it gives you actual trace specs and it can provide

a very nice heat chart like this where you can look into the specific code paths your uh application is spending a lot of time in. Now when pointing this at a production GUNICONBORKI you need to like filter out a few things where it says okay I'm spending a lot of time work waiting for the next requests. That is fine and should be spending a lot of time there. But there are many other things and you will see a lot of Django template engine taking up a lot of time. There's probably not so much you can do about that in many situations. But we found the most interesting things For example, we use Django Countries, a package that allows us to render a country selection box for an address. And Django Countries does this very well in it gives an alphabetical list

and it is localized and it uses a Unicode-aware sorting algorithm to alphabeticalize the list of countries And this Unicode we're sorting is surprisingly slow. So on a page where we have 10 address forms, this became a major performance issue for us. that it was sorting the list of countries ten times to render that page. So we introduced caching for our usage of Django countries. I don't think we would have ever found that performance issue without a tool like PySpy. So this has been a quick twenty two minute look into the toolbox I open when we deal with performance issues that are happening suddenly

and without a specific optimization plan, but often under a lot of stress, and we need to fix this today or someone will be very unhappy. And I hope That maybe some of these tools have been new to you and will be helpful in making your applications go faster. And I believe that's the end and we will have some time for questions before the coffee break.