Статус кэша в журнале nginx: разобрать жалобу на медленную загрузку за минуту

Заказчик пишет: «Вчера вечером страница долго грузилась». Вы проверяете — HIT, 30 миллисекунд. Заголовок X-Cache-Status отлично отвечает на вопрос «что сейчас», но ничего не говорит о том, что было вчера. Для этого статус кэша нужно писать в журнал.

Это двенадцатая часть цикла «Кэш страниц без MISS».

Повод

На одном сайте после жалобы мы прогнали обход 248 страниц: MISS — 0, среднее время первого байта 0,23 с. Всё отлично. Но что получил сам заказчик, узнать было нельзя: в журнале nginx стандартного формата нет ни статуса кэша, ни времени ответа PHP.

Формат журнала

log_format cache '$remote_addr [$time_local] "$request" $status '
                 '$upstream_cache_status rt=$request_time '
                 'urt=$upstream_response_time '
                 'm=$is_mobile lang=$cookie_lang '
                 '"$http_user_agent"';

access_log /var/log/nginx/access.log cache;

• $upstream_cache_status — HIT, STALE, MISS, BYPASS, UPDATING;
• $request_time — сколько ждал посетитель;
• $upstream_response_time — сколько работал PHP (пусто при HIT);
• составные части ключа — чтобы понять, какой именно вариант страницы он получил.

Как разбирать жалобу

С таким журналом жалоба разбирается за минуту: найти строку по времени и адресу и посмотреть статус.

Что в журнале	Что это значит
BYPASS, 1,5–3 с	посетитель был залогинен — для него кэша нет, это норма
MISS	холодный вариант ключа: какой — видно по m= и lang=
HIT, rt маленький	сервер ответил быстро — медленно было в сети или в браузере

# сколько MISS за сутки и по каким адресам
grep ' MISS ' /var/log/nginx/access.log | awk '{print $4, $5}' | sort | uniq -c | sort -rn | head