Назад | Перейти на главную страницу

Время загрузки Apache в микросекундах - разница между заголовком и журналом

Я недавно следил это руководство для измерения производительности загрузки сайта на веб-сервере.

Чтобы зарегистрировать время, необходимое 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, я также хотел бы задаться вопросом, действительно ли они представляют две разные точки в обработке запроса:

  • поскольку значение заголовка% D ниже во всех примерах на этой странице, оно может показывать время, необходимое для формирования заголовков ответа, но не обязательно тело
  • значение AccessLog% D может быть временем для отправки полного ответа.

Хотя это полное предположение.

Можете ли вы убедиться, что ваше имя 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