1

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.

Improve this question
2
  • 1
    how long does resolving the domain take? time dig mydomain.com – SingleNegationElimination Nov 23 '11 at 13:21
  • domain resolving takes 7ms when I try. Doesn't exclude the fact it may have hiccups. – Boaz Nov 23 '11 at 15:59
1

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.

Improve this answer
2
  • @Redumumba - my issue is with the logged timestamp for request start , not the moment at which the log entry was made. Boaz – Boaz Nov 25 '11 at 21:41
  • @Boaz: Yeah, I realized that may have been what you were asking, so I added the entry about tracerouting the request. That should give you a pretty good round trip time. – Andrew M. Nov 26 '11 at 5:01
0

Two things to check:
- the time to resolve the name mydomain.com on the server (credits to TokenMacGuy in comments)
- the execution time of your script as the log is written upon completion of the request

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.