I have a client software which calls and apache httpd server installed on the same machine. Before calling the apache logs a log entry:
2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels
As you can see the call is made on 13:27:43 local time. The domain mydomain.com resolve the external IP of the same machine.
However , when I look at the access.log file, I say log entry whose time stamp[1] is 5 seconds later:
[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels
This is a mod_wsgi base server running in daemon mode but I'm not sure if it is relevant (the time stamp should be the start if the request on the level of apache).
How can I best proceed to find out the source of these 5 seconds?
Cheers,
Boaz
Clarification:
[1] – The time stamp is when the request started. It is true the entry is written to the log when the request ends, but the time is of the request start.
Best Answer
This is because the access log is written at he end of the request, not the beginning. So if you make the request at 12:00, and it takes a minute to complete, the entry will not be written until 12:01. The fact that it can include things like the number of bytes transferred is a sure indicator of this.
You can also perform a traceroute from one host to the other to see if its actually getting the request--if you're seeing delays during the routing, you have the source of your problem.