Como depurar consultas lentas no Django + Postgres

Question

Minhas consultas ao banco de dados do Django estão começando a demorar de 1 a 2 segundos e estou tendo problemas para descobrir o porquê. Não é um site muito grande, cerca de 1-2 pedidos por segundo (que atingiu o Django; arquivos estáticos são servidos apenas do nginx).

O que me confunde é que eu posso replicar a lentidão no shell do Django usando o modo de depuração. Mas quando eu emito exatamente as mesmas consultas em um prompt sql, elas são rápidas. Demora cerca de um segundo para uma consulta retornar, mas quando eu verifico connection.queries ele relata o tempo como abaixo de 10 ms.

Aqui está um exemplo (do shell do Django):

>>> 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

Como posso descobrir onde esse tempo extra está sendo gasto?

Estou usando o Apache + mod_wsgi no modo daemon, mas isso acontece apenas com o shell do django, então acho que não é relacionado ao apache.

    

Answer 1

Eu tive esse problema, exceto com o MySQL. Havia uma página de administração que demorava muito tempo para ser carregada (15 segundos), mas a consulta mais lenta durava apenas alguns segundos. Horas de depuração depois, descobri o que era.

O servidor de banco de dados mysql estava de fato retornando os resultados da consulta em apenas alguns segundos, mas a consulta não tinha sido completamente processada (até o fim da vida, incluindo a limpeza) até após os resultados retornaram. Aqui está uma explicação passo-a-passo do que estava acontecendo:

1. A consulta cara atinge o db
2. O servidor MySQL retorna os resultados da consulta após alguns segundos, mas continua trabalhando na limpeza (a consulta ainda não atingiu o fim da vida útil no que diz respeito ao servidor mysql). O tempo gasto para esta consulta, como mostrado na barra de ferramentas de depuração do django (e django.db.connection.queries), pára a temporização quando os resultados retornam.
3. O Django recupera os resultados e continua carregando a página enquanto, ao mesmo tempo, em segundo plano , o mysql continua limpando a tabela temporária usada.
4. O Django prepara outra consulta SQL e a envia para o servidor.
5. O MySQL ainda não terminou de limpar a tabela temporária, portanto ...
6. Django tem que sentar e esperar. O Django está usando a mesma conexão db mysql como antes, e o mysql não permitirá que a mesma conexão execute outra consulta até que a anterior tenha atingido o final da vida, incluindo a limpeza.

Eu percebi isso executando "show full processlist;" em um prompt de comando do mysql. Para todas as consultas pendentes, ele mostra o tempo gasto na consulta (até o momento), o status e o texto da consulta real. Três ou quatro segundos depois de iniciar a consulta cara, ela começaria a mostrar "removendo a tabela tmp" como o status. Ele mostraria isso por até 7 segundos após a consulta já ter retornado resultados para o Django. Então, aparentemente, o MySQL demorava muito mais tempo para limpar a consulta do que retornar resultados. Este é exatamente o problema, no meu caso.

Curiosamente, o horário de "limpeza" não apareceu nos tempos de consulta da consulta incorreta nem na consulta de acompanhamento cujo início foi realmente atrasado.

Não tenho certeza se isso é problema seu, mas acho que vale a pena investigar.

    

Answer 2

Um ótimo addon para o Django é a barra de ferramentas de depuração do Django (github.com/robhudson/django-debug-toolbar). Ele mostrará as consultas que você está fazendo em cada carregamento de página (junto com a saída de explicação para cada consulta).

    

Answer 3

Qual versão do Django você usa? Estável ou Tronco? 1.x? 0,9x? Apenas uma coisa que você pode testar. O que você quer dizer com "consultas exatas"? Você usa consultas SQL personalizadas com o Django ou já buscou a consulta e a executou no shell SQL.

O outro "palpite": o banco de dados está na mesma máquina? Talvez você tenha um problema de rede com latência. Quando você abre um prompt SQL, você já está conectado ao servidor de banco de dados enquanto o Django tem que fazer a conexão?

Como eu estava dizendo, é apenas um palpite. O problema da rede eu me enfrentei por causa de todas as coisas de firewall / roteamento em nossa empresa. Mas não tão alta latência você está tendo.