Tengo un software cliente que llama y un servidor httpd apache instalado en la misma máquina. Antes de llamar a Apache registra una entrada de registro:
2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels
Como puedes ver la llamada se realiza a las 13:27:43 hora local. El dominio midominio.com resuelve la IP externa de la misma máquina.
Sin embargo, cuando miro el archivo access.log, digo entrada de registro cuya marca de tiempo [1] es 5 segundos más tarde:
[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels
Este es un servidor base mod_wsgi que se ejecuta en modo demonio, pero no estoy seguro de si es relevante (la marca de tiempo debe ser el inicio si la solicitud está en el nivel de Apache).
¿Cuál es la mejor manera de proceder para descubrir la fuente de estos 5 segundos?
Saludos, Booz.
Aclaración: [1] - La marca de tiempo es cuando se realiza la solicitud.comenzó. Es cierto que la entrada se escribe en el registro cuando finaliza la solicitud, pero la hora es la del inicio de la solicitud.
Respuesta1
Esto se debe a que el registro de acceso se escribe en él.finde la solicitud, no el comienzo. Entonces, si realiza la solicitud a las 12:00 y tarda un minuto en completarse, la entrada no se escribirá hasta las 12:01. El hecho de que pueda incluir cosas como el número de bytes transferidos es un indicador seguro de ello.
También puede realizar un traceroute de un host a otro para ver si realmente recibe la solicitud; si ve retrasos durante el enrutamiento, tiene el origen del problema.
Respuesta2
Dos cosas para verificar:
- el tiempo para resolver el nombre midominio.com en el servidor (créditos a TokenMacGuy en los comentarios)
- el tiempo de ejecución de su secuencia de comandos a medida que se escribe el registro al completar la solicitud