How to debug slow queries in Django+Postgres

Question

My database queries from Django are starting to take 1-2 seconds and I'm having trouble figuring out why. Not too big a site, about 1-2 requests per second (that hit Django; static files are just served from nginx.)

The thing that confuses me is, I can replicate the slowness in the Django shell using debug mode. But when I issue the exact same queries at an sql prompt they are fast. It takes about a second for a query to return, but when I check connection.queries it reports the time as under 10 ms.

Here's an example (from the Django shell):

>>> p = PlayerData.objects.get(uid="100000521952372")
>>> a = time.time(); p.save(); print time.time() - a
1.96812295914
>>> for d in connection.queries: print d["time"]
... 
0.002
0.000
0.000

How can I figure out where this extra time is being spent?

I'm using Apache+mod_wsgi in daemon mode, but this happens with just the django shell as well, so I figure it is not apache-related.

Answer 1

I had this problem, except with MySQL. There was an admin page that was taking a very long time to load (15 seconds), but the slowest query was only a few seconds long. Hours of debugging later, I found out what it was.

The mysql database server was indeed returning the results of the query within just a few seconds, but the query hadn't completely finished being processed (through end-of-life, including cleanup) until after the results had returned. Here is a step-by-step explanation of what was going on:

1. The expensive query hits the db
2. MySQL server returns the query results after a few seconds, but keeps working on clean-up (the query hasn't yet reached end-of-life as far as the mysql server is concerned). The time taken for this query as shown in the django debug toolbar (and django.db.connection.queries) stops timing once results return.
3. Django gets back the results and continues to load the page while at the same time, in the background, mysql continues to clean-up the temp table used.
4. Django prepares another sql query and sends it to the server.
5. MySQL hasn't yet finished cleaning up the temp table, so...
6. Django has to sit and wait. Django is using the same mysql db connection as before, and mysql won't let the same connection run another query until the previous one has hit end-of-life, including cleanup.

I figured this out by running "show full processlist;" in a mysql command prompt. For all outstanding queries, it shows the time spent on the query (so far), the status, and the actual query text. Three or 4 seconds after starting the expensive query, it would begin to show "removing tmp table" as the status. It would show this for as long as 7 seconds after the query had already returned results to Django. So apparently MySQL was taking much longer to clean up the query than it was to actually return results. This is exactly what the problem was, in my case.

Interestingly, the "clean up" time didn't show up in the query times of either the offending query nor the follow-up query whose starting was actually delayed.

Not sure if this is your problem, but I suppose it's worth looking into.

Answer 2

A great addon for Django is the Django Debug Toolbar (github.com/robhudson/django-debug-toolbar). It will show you the queries you're making on each page load (along with the explain output for each query).

Answer 3

What version of Django do you use? Stable or Trunk? 1.x? 0.9x? Just one thing you can test. What do you mean with "exact queries". Do you use custom SQL queries with Django or have you fetched the query and ran it on the SQL shell.

The other "wild guess": Is the database on the same machine? Maybe you have a network issue with latency. When you open a SQL Prompt you are already connected to the database server while Django has to make the connection?

Like I was saying it's just a wild guess. The network problem I faced myself because of all the firewall/routing stuff in our company. But not such a high latency you are having.