Я недавно следил это руководство для измерения производительности загрузки сайта на веб-сервере.
Чтобы зарегистрировать время, необходимое Apache для обработки запроса, добавьте это в свой файл конфигурации apache:
LogFormat "%h %D %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
% D означает, что вы увидите время, затраченное Apache на обработку запроса, в журнале доступа. Время измеряется в микросекундах.
Чтобы упростить отладку времени загрузки страницы, добавьте это в свой файл конфигурации:
Header set X-Request-Received: %t Header set X-Request-Processing-Time: %D
Не забудьте сначала включить mod_headers, выполнив заголовки a2enmod. Теперь вы должны увидеть эти заголовки в ответе:
X-Request-Received t=1286995673038485 X-Request-Processing-Time D=251
Я использовал точно указанный выше код (с заголовком, определенным в .htaccess), но получил, например, «525151» в журнале и «262» в заголовке для того же запроса. В целом, кажется, разница между числами на порядки.
192.0.2.1 525151 - - [21/Aug/2011:14:19:53 +0200] "GET /images/site/slide-1.png HTTP/1.1" 262 423285 "http://example.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.112 Safari/535.1"
vs.
X-Request-Processing-Time:D=262
X-Request-Received:t=1313929193502879
Как я могу это исправить?
[Это очень старый вопрос, но он заслуживает лучшего ответа для тех, кто сюда приедет]
Заголовок HTTP обязательно создается до того, как контент будет доставлен конечному пользователю, поэтому он исключает сетевые задержки. С другой стороны, запись access_log записывается после того, как весь контент доставлен конечному пользователю, возможно, по медленному сетевому каналу, и включает время, затраченное на эту доставку.
Какая фигура для вас более полезна, зависит от того, что вы пытаетесь выяснить. Для URL-адреса вашего изображения вы, вероятно, смотрите на производительность конечного пользователя, и задержки в сети, вероятно, являются большей частью ответа.
Если вы отлаживаете производительность динамически сгенерированного контента, вы, вероятно, захотите регистрировать время без учета сетевых задержек. LogFormat позволит вам регистрировать содержимое заголовка с помощью %{X-Request-Processing-Time}i
- не пробовал, но надеюсь, что это сработает.
Я думаю, что лучше всего выбрать «собственное» имя для вашего пользовательского LogFormat, а не повторно использовать / изменять combined
формат журнала.
Помимо всего остального (и как предполагает @polynomial), кажется, что есть разрыв между конфигурацией, которую вы показываете, и выводом, который вы показываете.
Хотя бы для того, чтобы сделать устранение неполадок менее неоднозначным (в настоящее время вы не знаете, combined
(LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\"" combined
) или ваша версия уже используется).
Итак, я бы сначала сделал что-то вроде:
LogFormat "%h %D %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" perf-combined
А затем используйте perf-comb там, где это необходимо.
Глядя на довольно широкие различия между значениями Header% D и AccessLog% D в примере @ polynomial, я также хотел бы задаться вопросом, действительно ли они представляют две разные точки в обработке запроса:
Хотя это полное предположение.
Можете ли вы убедиться, что ваше имя LogFormat "комбинированное" соответствует тому, что использует ваша переменная CustomLog. Я тестировал это на OS X, и за исключением небольшой разницы, которую вы ожидаете между чтением переменной при обратной записи заголовков и при регистрации (после отправки всех данных обратно клиенту), они очень близки:
/etc/apache2# grep LogF httpd.conf
LogFormat "%h %l %u %t \"%r\" %>s %b %t %D" common
/etc/apache2# grep CustomL httpd.conf
# a CustomLog directive (see below).
CustomLog "/private/var/log/apache2/access_log" common
# wget -qqO /dev/null -S http://localhost/
...
X-Request-Received: t=1314588821970347
X-Request-Processing-Time: D=336
/private/var/log/apache2# tail access_log
::1 - - [28/Aug/2011:20:33:41 -0700] "GET / HTTP/1.0" 200 44 [28/Aug/2011:20:33:41 -0700] 587