Como descobrir por que uma solicitação demora para aparecer no log de acesso do apache?

Question

Eu tenho um software cliente que chama e o servidor apache httpd instalado na mesma máquina. Antes de chamar o apache registra uma entrada de log:

2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels

Como você pode ver, a ligação é feita às 13:27:43, hora local. O domínio mydomain.com resolve o IP externo da mesma máquina.

No entanto, quando olho para o arquivo access.log, eu digito uma entrada de log cuja data e hora [1] é 5 segundos depois:

[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels

Este é um servidor base mod_wsgi em execução no modo daemon, mas não tenho certeza se é relevante (o registro de data e hora deve ser o início, se a solicitação estiver no nível do apache).

Como posso proceder melhor para descobrir a origem desses 5 segundos?

Felicidades, Boaz

Esclarecimento: [1] - O registro de data e hora é quando o pedido é iniciado . É verdade que a entrada é gravada no log quando a solicitação termina, mas a hora é do início da solicitação.

    

Answer 1

Isso ocorre porque o log de acesso está escrito no end da solicitação, não no começo. Portanto, se você fizer a solicitação às 12:00 e levar um minuto para ser concluído, a entrada não será gravada até as 12:01. O fato de poder incluir coisas como o número de bytes transferidos é um indicador seguro disso.

Você também pode executar um traceroute de um host para o outro para ver se ele realmente está obtendo o pedido - se você está vendo atrasos durante o roteamento, você tem a origem do seu problema.

    

Answer 2

Duas coisas para verificar:
- o tempo para resolver o nome mydomain.com no servidor (créditos para TokenMacGuy nos comentários)
- o tempo de execução do seu script conforme o log é escrito após a conclusão do pedido