У меня есть клиентское ПО, которое вызывает и сервер Apache httpd, установленный на той же машине. Перед вызовом Apache регистрирует запись в журнале:
2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels
Как вы видите, звонок был сделан в 13:27:43 по местному времени. Домен mydomain.com разрешает внешний IP той же машины.
Однако, когда я смотрю на файл access.log, я вижу запись журнала, временная метка[1] которой на 5 секунд позже:
[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels
Это базовый сервер mod_wsgi, работающий в режиме демона, но я не уверен, имеет ли это значение (отметка времени должна соответствовать началу запроса на уровне Apache).
Как мне лучше всего выяснить источник этих 5 секунд?
Привет, Боаз.
Пояснение: [1] - Временная метка - это время, когда запросначал. Действительно, запись в журнал записывается по окончании запроса, но время указывается в момент начала запроса.
решение1
Это потому, что журнал доступа пишется на немконецзапроса, а не начала. Так что если вы сделаете запрос в 12:00, и он будет выполнен в течение минуты, запись не будет сделана до 12:01. Тот факт, что он может включать такие вещи, как количество переданных байтов, является верным индикатором этого.
Вы также можете выполнить трассировку маршрута от одного хоста к другому, чтобы проверить, действительно ли он получает запрос. Если вы видите задержки во время маршрутизации, значит, у вас есть источник проблемы.
решение2
Две вещи, которые следует проверить:
- время разрешения имени mydomain.com на сервере (спасибо TokenMacGuy в комментариях)
- время выполнения вашего скрипта, так как журнал записывается по завершении запроса