Very slow Django: Multiple "SHOW default_transaction_isolation" calls in log

Question

I am using Django 1.5.4 with PostgreSQL 9.2.4.-2 through psycopg2 2.5.1.

From some point of time I noticed that my Django site became extremely slow - it takes about 2-3 seconds to load small pages with only several lightweight queries.

Django-debug-toolbar says:

241,70 ms (161 queries) - query time

time 2992ms - total page load time

So, the queries should not be the problem... But that's not true! I've set up postgresql query logging and I got this:

[LOG ENTRY] 2013-09-18 11:17:05.148 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.762 ms  statement: SELECT ...
[LOG ENTRY] 2013-09-18 11:17:05.155 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.086 ms  statement: SHOW default_transaction_isolation
[LOG ENTRY] 2013-09-18 11:17:05.158 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.804 ms  statement: SELECT ...
[LOG ENTRY] 2013-09-18 11:17:05.164 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.092 ms  statement: SHOW default_transaction_isolation
[LOG ENTRY] 2013-09-18 11:17:05.168 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.757 ms  statement: SELECT ...
[LOG ENTRY] 2013-09-18 11:17:05.175 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.085 ms  statement: SHOW default_transaction_isolation
[LOG ENTRY] 2013-09-18 11:17:05.178 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.779 ms  statement: SELECT ...
[LOG ENTRY] 2013-09-18 11:17:05.185 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.091 ms  statement: SHOW default_transaction_isolation
[LOG ENTRY] 2013-09-18 11:17:05.190 MSK 10304 127.0.0.1(38834)LOG:  duration: 1.492 ms  statement: SELECT ...
[LOG ENTRY] 2013-09-18 11:17:05.197 MSK 10304 127.0.0.1(38834)LOG:  duration: 0.090 ms  statement: SHOW default_transaction_isolation

There is a SHOW default_transaction_isolation query after my target query. Log says that it takes 0.086 ms to perform this strange query, but it creates about 10 ms delays around it:

• query #1 finished 11:17:05.148
• strange query
• query #2 finished 11:17:05.158

Does anybody know whether this is a bug of django, psycopg, postgres or any other app? How can I investigate this?

UPD Pure Django project (only Django, postgresql, psycopg2) executes queries without that bug. Maybe there is something in project's apps or third-party apps. I'm trying to investigate.

Answer 1

It took me several days to discover the source of the problem. It took so much time because of my wrong guesses: I was sure the problem was caused somehow by database or database-python connection library.

The reason was django-debug-toolbar - as I understand, its measurement of SQL execution time causes poor performance in general.

As a summary, if your Django site is slow - check whether DEBUG = False and django-debug-toolbar is switched off.