Profiling Django & Python apps

Speaker 1: Hi, my name is Jérôme Vieillon. I am a developer advocate at Blackfire. io.

Speaker 2: Hi, my name is Sumerjib and I work as a senior software engineer at Blackfire. io

Speaker 1: Today I'll be showing you ways to make your applications incredibly fast. Performance optimization is quite often a hard topic, as you may not know where to look and where to begin with. That's the point. You cannot optimize something you don't see or measure. So we will need to collect and organize data for that very purpose. It sounds overwhelming, and it is somehow. So we're going to use a tool specifically designed for this and that will do all the hard work for us. so that we can focus on what matters, writing simple and efficient code and making the world a beautiful place.

Speaker 2: This specific tool is called profiler. So profilers can be categorized into two types, tracing and sampling profilers. Tracing profilers provide detailed information and accurate data about the behavior of an application. They hook into specific events and operate precise measurements under the hood with a cost of an overhead. For example, function tracing profilers operate measurements whenever a function call or exit happens, while a line tracing profiler would work on every line being executed. Sampling profilers, on the other hand, took another approach and they sample the application at regular intervals and aggregate this information, lowering the impact of the implied overhead.

Speaker 2: Profilers definitely measure time, but when it comes to computing, there are different flavors of time. Vol time, CPU time, and Io time. We will be walking over each one of them later in this presentation Another important metric that can be measured is memory. Memory consumption of a function makes sense for debugging some performance-related issues as well. So let's walk over a few profilers in the Python ecosystem as an example that have unique feature sets. So the first one will be the line profiler. Line profiler measures per line volt time and you can inspect its output from the command line. Yappi is another profiler

Speaker 2: which measures perfunction, wall, and CPU time. It can profile multi-threaded applications as well as async ion given applications. and you can see portrait traces from its output. And you can use key cache grind to visualize its output. The PySpy is a sampling profiler and it has a top-like CLI. It measures per function CPU time. You can output as flame graph or speed scope formats and it can also show guild contention if possible when there is a multi-threaded application. TraceMaloc is a memory profiler that's included in the Stone library since 3. 4. It

Speaker 2: basically what it does is it uh traces all malloc, re-alog and free calls and saves a traceback along with the allocation. Thus you can trace C extension allocations as well and you can see the memory consumption of each these allocations. Blackfire measures per function, wall, CPU and IO time and memory simultaneously. It's enabled only on demand, thus have zero overhead when the profile is not used. It has a web UI to show its output as call graph and timeline. And timeline is pretty similar to flame graph. So let's dive in a little bit more on how BlackFirl works.

Speaker 1: So, let's say you've already opened a free account on Blackfire. io and installed BlackFire on your computer. Well, the installation is widely covered in the documentation. But before we jump in profiling of our code, I want you to understand just a little bit about how this all works. Well let's jump to the documentation. And let's look for Blackfire Stack. Here it is. Whoa A diagram that shows you exactly how Blackfire works appears. So let's zoom in a bit here Alright, there are actually three things that we need to install.

Speaker 1: The first, which appears here in the middle, is called the probe, which is really just a pip package. You'll install it in your project wherever your code is running. I mean like your local machine and later on production. The probe's job is simple but huge. It's responsible for collecting all of the information. It means all the function calls, how long it took. uh which function called which other function, how much memory did something take, network request, well you get the idea. And by the way, the process of collecting all the data is sometimes called instrumentation, which I only mention so that uh use

Speaker 1: if you see these fancy words, it hopefully won't confuse you. The second thing we need to install is called the agent. This is a service or daemon that runs on your computer, well within a container or on your production machine. It just sits there and waits. And when the probe is finished with collecting all the measures, it sends them to the agent. And the agent does some processing on it, like removing unimportant information and anonymizing things, then ultimately send the data to the BlackFair servers. It's somehow the middleman.

Speaker 1: So bla basically the probe and the agent work together. To collect the info and send it to Blackfire. The last piece you need to install is a browser extension, which is sometimes called the companion. Remember, uh the probe is not profiling every single request. It's always on demand. Normally, when a request comes in, the probe, well, yons And does nothing. The browser extension's job is to actually activate profiling. It basically says, hey probe, wake up! I'm going to make a request and I actually want you to do your thing. You know, collect all the measures, etc. and send them to the agent. Cool? Well, text me when it's done. And that's it!

Speaker 1: This bottle leg fighting superhero trio is our ticket to performance glory Well next, let's see what they can actually do for us. Alright, let's boot up a server to discover our application. But first, let's dive into our virtual environment for this. So I'm going I'm using ppav is so I'm gonna use the shell command. Alright, we're set to go Well for running a server here, instead of using the Python binary from my virtual environment, I'm going to use Blackfire Python. This command is actually a wrapper around your Python binary which ensures that everything is set as expected.

Speaker 1: Well it mainly instantiates the probe. and asked it to wait for being asked a profile. So I'm gonna do this now. BlackFire Python manage. py I'm using Django applications here. Run server. Alright, it seems that we're good to go. Let's copy this now and jump into the browser. Right, now you understand how important this project is. The world has been looking for the Bigfoot or Sasquatch for years. And thanks to the Bigfoot fanatic community on our site, Sasquatch Sidings, we are closer than ever.

Speaker 1: In our case, better performance doesn't mean more profit, it means more Bigfoot. Do I know where the performance problems are? No. No idea. And honestly, I was too focused on getting the site to production to obsess over performance. That might not be the best idea, but still. Let's use BlackFarr to find the button next, if any, to sasquash them. So we're ready to profile. Uh but where should we start? Well let's just Click on the view details about a Bigfoot sighting. And all this all of this data comes from some data fixtures that we use to pre-populate the database while satining the project. It uses a bunch of random data up here

Speaker 1: and each siding has a bunch of random comments when we loaded the page. Uh a second ago, please note that the BlackFerror probe did absolutely nothing. Um because to activate it you need to click on the browser extension which I installed here. Ho ho, moment of truth. Let's click here. Well, there it goes. It goes from zero to one hundred percent. and as it actually makes 10 requests and averages their data. We can also give this profile a name to keep our account organized. Well Let's say

Speaker 1: show initial sighting page. There we go. Now well In this top bar, we can also see the profile summary with the different dimensions on the profile. So here the wall time, the IOTime, the CPU time, the memory, external HTTP request and database interactions. We'll go into details a bit later. Now just click on the view call graph button to go to a URL on their site on the Blackfire website. Hello to our profile. Well, next.

Speaker 1: Well, let's start diving into this mountain of information. and see how we can use use it to uh find hidden sasquatch I mean hidden performance bug. Yes, I know. The cool looking graph in the middle is calling to us. But let's start by looking at the left side. The list of function calls ordered from the functions that took the longest to execute on the top down to the quickest. on the bottom. Well actually Blackfire prunes or removes function calls that took very little time so you won't see everything here. The functions are ordered by time by default because we are viewing the call graph in the time dimension.

Speaker 1: Uh you can also look at all of this information ordered by several other dimensions like functions to uh the most memory. It's kind of like the process manager on your computer. You can see which applications are currently taking most CPU, most memory, reading most info from your disk. or even using the most network. But more on these dimensions later. In the profiling world, time is called wall time But it's nothing fancy. Wall time is the difference between the time at which a function was entered and the time at which the function was left. So wall time is a fancy world for um time. the amount of time a function took to run.

Speaker 1: So we just find the function with the highest wall time and uh we just want to find it and optimize it, right? Well, what if a function is taking a really long time? But actually 99% of that time is due to a function that it calls itself In that case, the other function might be the problem. To help sort this all out, wall time is divided into two parts, exclusive and inclusive time. So if you hover the red graph here, you'll see this exclusive time 65. 2 milliseconds. Inclusive time 158 milliseconds.

Speaker 1: Inclusive time is the full time it took for the function to execute. Exclusive time is more interesting. It's the time a function took to execute excluding the time spent inside other functions it called. It's a pure measurement of the time that the code inside this very function took. Well, right now we're actually ordering this list by exclusive time. because that usually shows you the biggest problems. Well you can also order by inclusive time. Which is probably not very useful here. The top item is the where your script our script

Speaker 1: starts executing and second in the next function call and so on. So well back to exclusive So, apparently the biggest problem according to exclusive time is the initializer of the Django DB models base sighting class Right, this is matching what of one of my model classes. And before we die we dive further into the root cause behind this slow function. . The other way to order the calls is by the number of times each is called. So let's click here to to change this order. And apparently the function that's called the most time, almost 7000

Speaker 1: times, is built-ins. setr Hmm. I wonder who calls that. Oh, and I can also notice that uh well that sighting nationalizer is also quite high on the lists based on the number of calls Could this be related? Well, first let's uh click to expand the set art function. Even though we are viewing the core graph in the time dimension, this gives us all the information about this function, the wall time, the I. O. time, the CPU time, and even the memory. Well, this isn't seemed to be uh a particularly time-consuming function.

Speaker 1: Well, all is relative of course, but its exclusive wall time is around 26 milliseconds compared to the whole wall time it looks quite minimal and wall time itself is broken into two pieces And this is actually important. We have the IO time and the CPU time There is nothing else. Either a function is using CPU or it's doing uh IU operation like talking to the file systems or making network calls. Well Uh it seems to be broken into two parts, but most of the time is seems to be spent in the CPU time. Okay, but who actually calls this function so many times?

Speaker 1: Above this, see the those down arrow buttons? These represent the three other functions that call this one. The side is relative to how many times each one calls this. Let's click the first one. Aha! It's our sighting model initializer. So that's the function with the highest exclusive time. And it's uh it calls this function 6812 times so it's definitely a problem. Well and if I click the two other arrows you can see that the other colors One call is well for

Speaker 1: seven twenty-seven times from Django models as well. And the other other one which is less than once and it's less than once probably because you know uh the probe averages the the ten different requests uh it made in the beginning. Alright, let's close this up. And go back to ordering by the highest exclusive time. Here we go. Alright. Let's open up sighting in it. As I mentioned, even though we are currently viewing the call graph in a time dimension, we can see all these functions dimensions here. However the time graph. Um okay

Speaker 1: even though the exclusive time is significant, well most of this function's time is still inclusive right? It's sticking up it by other functions that it calls. That may give us a hint as to if the problem is inside this function or is inside something it calls. But remember that the second uh this the this the function it's called just the just after, which can be can be appeared. here by clicking the uh this button is a built-in function so and it's taking a quite a lot of time here 88 milliseconds at um uh overall so um

Speaker 1: Actually every dimension has an inclusive and um exclusive measurement so backed here in the uh dunder init function So we can observe the uh exclusive and uh inclusive dimensions for input-output and CPU. That's also memory, that's uh also very interesting Alright, um what I really want to know though is what's happening in our code to cause this function citing dunder init Be called so many times. So to figure this out, let's click on the biggest arrow above. Aha It's our Bigfoot models

Speaker 1: comment dunder in it, which seems to be the main culprit But honestly, I'm not sure how these two functions interact together. So next, let's use the call graph, you know, this pretty diagram on the right, to get a full picture of what's happening and how to fix it. There are two different ways to optimize any function. Either optimize the code inside that function, or you can try to call the function less times. In our case, we found that the most problematic function is Django DBModels base citing dunder init dunder function. But while it is based on one of our model classes, the process of creating its instances is specific

Speaker 1: to Django models. So it's probably not something that we can optimize. And honestly, it's probably already super optimized, anyways. However, we could try to call it less times, if we can understand what in our app is causing so many calls. Well The core graph, the big diagram in the center of this page, holds the answer. Let's start by clicking on the magnifying glass. next to siding in it. That zoomed us straight to that node on the right. Let's zoom out a little. The first thing to notice is that the core graph is a visual representation of the information from the function list.

Speaker 1: On the left, it says this function has two colors. On the right, we can see, actually see those two colors. So when you're trying to figure out the big picture of what's going on, the call graph is always nicer. Well, let's zoom out a punch further. Now we can see a clear red path that eventually leads to the dark red node down here. This is called the critical path. One of Blackfire main jobs is to help us make sense out of all this data.

Speaker 1: One way it does that is by highlighting the path to the biggest problems in our app. Well I'm going to hit this little home icon that will reset the call graph instead of centering it around citing init node. In this view, Blackfire hides some less important information around the node, but it gives us the best overall summary of what's going on. We can clearly see the critical path The critical thing to understand here is why is that path in our app so slow? Well, let's trace down to the problem node. to find where our code starts. So let's first start with the main function.

Speaker 1: Alright, so here is our view being rendered. Right? Bigfoot. view sighting show. Okay, then it calls render It goes through the template engine. That's interesting. It means the problem is coming from inside a template. Okay , down further. Oh, it jumps into a Django template extension called User Activity Text. That calls Bigfoot models user get recent comments counts And okay, and right this is the last function before it jumps into jungle

Speaker 1: models internals. So The problem in our code seems to be something around this user activity tag stuff. Well, let's open up the siding show view. That's a part of the code. Okay, it's pretty straightforward and it's rendering this sidings show. html template Okay, well this is the body block. Let's find the user activity text which is here. Okay, it's within a loop. from the site in dot commandset dot all okay if we look at the site itself

Speaker 1: Yeah, it's this. So if we look here, um we can see that each commenter has a label next to them, like uh believer Hobbyist or Bigfoot fanatic? Well this label tells us how active they are in the great and noble quest of finding Bigfoot Over in the template, well, we get this text via a custom filter. Well this custom filter, the user activity text. Oh, let's open that up. Okay, so it counts how many recent

Speaker 1: comments this user has made And via our complex and proprietary algorithm, it prints the correct label. Okay, back over in Blackfire, it told us that the glass call before Django models was user. getresent comments count. There it is! Okay, let's open that up. Whoa hokay, here's the story But if you don't use Django models, you might not see the problem. But it's one that can easily happen, no matter how you talk to a database. So yeah, each user on our site has a database relationship to the comment

Speaker 1: table. Every user can have many comments The way our code is written, Django is querying for all the data for every comment that the user has ever made. Simply to loop over them and count how many we're creating within the last three months. It's a massively inefficient way to get a simple count. This is problem number one. It seems obvious now that while I'm looking at it. But the nice thing is that it's not a huge deal that I did this wrong originally because Black Friday points it out.

Speaker 1: Let's Fix that performance bug. Okay, we're gonna do a risk return comment. Oops Return comment dot objects filter and yeah, still filtering on owner ID the self ID and date at its greater than Well, uh we already have datum imported. Uh datime

Speaker 1: dot well starting from now alright minus daytime dot time delta And well let's say three uh three month is well more or less ninety days so three times thirty Okay, now that we have it, we just return the count. Alright, let's use this instead of my current crazy logic. If we've done a good job, we will hopefully be calling our model init function many less times. So let's

Speaker 1: profiles and see the results. But first let's see if I didn't make any mistake. Okay, it seems to work correctly Alright, it looks a little faster. So well in order to see what impact I could have We're gonna use BlackFires comparison feature to prove that this change was actually good We've just updated our code to make a count query instead of querying for all the comments for a user

Speaker 1: just to count them. So the patch would be definitely faster, right? Are we absolutely sure? Well, I think it is faster. But sometimes making one part of our code faster will make other parts slower. Fortunately, Blackfire has a special way to prove that a performance tweak does in fact help. Well first uh before seeing that let's give this profile a name to stay organized. So show page after count query All right. Now, let's go see the call graph.

Speaker 1: Hey, it's well 580 milliseconds. The last one was 770 five seven fifty-four. So it is faster. We win! Well, yeah, I agree. It does look faster, but an important aspect of optimization is understanding why something is faster. Like, did it reduce CPU time, IOA time, and maybe more importantly, did this change cause anything to be worse? For example, a change might decrease CPU time but increase memory. And if that happens, well would the change really be a good one? Well, it depends.

Speaker 1: Well, this leads me to one of my favorite tools in Blackfire, the ability to compare profiles. So let's click back to our dashboard. The two profiles on the top are from well the initial profile, then the page after using the count query. On the right, we can hover these compare buttons. So okay, click the first one, this was the original, and click the second one. And say hello to the comparison view. Everything that's faster or better is in blue Um

Speaker 1: well in if anything that's slower or worse it will be red. And yeah, it looks like the new profile is better in every single category. Good. And anyway, um This comparison proves that this was a good change. Really, it's a big win. And on the call graph, the darkest blue, the critical pal this time, is the path that improved the most. Now, let's look for the siding dunder init function that was causing all the pain. Well, well it is

Speaker 1: the inclusive time is down to um down by 150 milliseconds 150 milliseconds and the memory even plug it. But okay, right, wait a second. On the top, one of the items is called SQL queries. Let's click on it. Oh, yeah. The total query time is less than before. Well, less by 1. 2 milliseconds, that's negligible. But we removed 27 queries but added 27 ones. Yeah, obviously We remove the big query

Speaker 1: getting everything to and replace it by a simple count. Is that a problem? No, probably not. This change overall was good. And if having too many queries does create a real problem, not just an imaginary one of too many queries. Blackfair will help us discover that. The big takeaway here is don't just assume that a performance enhancement is actually better. Always compare and always reprofile. Okay, we fixed our first performance issue, but we should examine the new profile to check if we could improve it more.

Speaker 1: The function with the highest exclusive time now is this method execute of Psycho PG2 extensions cursor objects. Well, which is a low-level function that executes SQL queries. These are taking well almost 50 milliseconds and are being called 57 times. It more or less corresponds to the number of SQL calls that are being reported in the database dimension. And clicking on BlackFarry recommendations tab on the left shows what BlackFarrer is suggesting us. It clearly is saying that we are

Speaker 1: executing too many queries and that we're loading too many RM entities. Let's click here to see. Yeah, it's basically telling us to reduce the number of SQL queries and how to do it. And the same for RRM entities here mentioning the Django models objects we are loading. Alright, it's not an ideal situation, but is it worth fixing? I guess it depends on how much you care. And whether the fix would be easy or if it would add a lot of complexity to our app. Okay. But

Speaker 1: when you're trying to identify where the problem is, there are two ways to look at the call graph. First, you can read from top to bottom like we did before. Trace through your whole application flow to figure out what's going on down the hot path. Or you can do the opposite. Start at the bottom, start where the problem is and trace up, using the critical path again to find where your code starts. Well, here again I'm going to start from the top. Alright, the main function. And then we can see Django is putting up. It's loading all the middlewares

Speaker 1: And then it renders our view, citing show view. This is well it renders then our template. This is really the same as before. And now down to again our user activity text called 27 times Which again calls user. getresent comments count. Right, that makes sense. 27 counts, uh 27 times. Well, we probably have 27 comments on the page And for each comment we need to count all the author's comments to print out this label. Before we think about if and how we might fix this.

Speaker 1: Let's back up and look at other dimensions to this profile. Let's have a look at IOTime. Yeah! We can now have a completely redrawn call graph only based on I. O. time. We can do the same on CPU time, also using memory. Um okay. When we look at this IOTime dimension, the Psychopg2 execute function, the function that makes SQL calls. shows up here as well as a big problem. The point

Speaker 1: is, while wall time is typically the first dimension you're facing, don't forget about these other ones They can give us more information about what's going on. Is a function slow because of inefficient code? Or is it for example because of a network call? Or is it some I. O. problem? Maybe you you have an issue with your SSD or your hard disk. As we already discovered. The problem is coming from the user dot get command count get user command count that we had in the wall time view

Speaker 1: Okay. Here, there, and there. Okay. Let's go into our code again. As we already discovered , the problem is getting from this function Which is called by the user activity text filter. Um Bigfoot extras, let's open it As we already discovered, the problem is coming from user. getRecentCommons account, which is called from the user activity text filter. Each time we render a comment, getRecentCommandsCount

Speaker 1: is called from the user object attached to this comment. It happens that the same user can comment many times on the same siding, as well as uh on other ones. When that happens We are making a query to count that user's comments and repeat the operation for each comment. That's wasteful. So here's one idea. Let's leverage caching. We'll keep track of the status string for each user and use that to avoid calculating the status more than once for a given user. Let's first enable the cache in our settings. py. Alright. here activating the lock

Speaker 1: memcache backend here perfect now let's update user activity filter import Django dot core dot cash import cache okay And now let's update this to use the cache. Right, first we define a cache key, which should be unique here per user ID We f then get the commons uh the common count from the cache and if it's none then we

Speaker 1: compute it and add it to the cache for one hour That looks there. Okay, I just refreshed and reprofiled the page. This time things look way better, but let's not trust it. Let's go compare the original profile to this new one. Okay. The changes are significant and there doesn't seem to be any downsides to the changes we made. And the SQL queries counts dropped by 27, which was expected. And really this is no surprise. Full caching things will of course be faster. But the good thing here is that the user activity text cache is now distributed.

Speaker 1: I mean each user being able to comment on all citing pages Well, their activity text will be reused everywhere they're commenting. And yeah, I think that's quite a big win.

Speaker 2: The most common mistake that is done during performance optimization is premature optimizations as not states. We should be measuring our code. if possible even in all development steps from development to production. So using a tool for this very purpose is key. Although there are no common rules to fix all kinds of performance-related problems, here are some guidelines for debugging and fixing performance issues. So the first one is obviously measure and always is better. Use using a tool for this is key like I said. The second one might be you should be focusing first on architecture design and algorithms rather than doing some language level micro-optimizations.

Speaker 2: A simple performance problem can open you a new way of refactoring your architectural core base and make it even better than before. And during development, check if there is a standard library that function that accomplished what you are trying to do or what is the best practice for your case Although this might seem very simple, we as developers may waste time because of not checking the documentation properly or not looking for best practices of the framework And if you really need performance at the end of the day, there are numerous tools for that. In Python world, you can few examples might include like Cyten, number, or directly write your code as a C extension.

Speaker 1: During this workshop I showed you how profiling with Blackfire can be useful to track down performance issues. You learned how functions are interacting with each other, how BlackFire provides recommendations based on the behavior of the application. How to read a call graph and to use the critical path. How to check the different dimensions of your application Input output, CPU, memory, database goals, and how to compare profiles to visualize the impact of your changes I hope you enjoyed this workshop as much as I did. Happy profiling and feel free to ask any question. Bye bye!