Postgresql – How to debug slow queries in Django+Postgres

apache-2.2djangomod-wsgipostgresql

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.

Best Answer

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.

Related Topic