Написан, перенесен на и запущен большой интернет-магазин. Креативные идеи — выстроились в очередь на реализацию. Однако Вас очень беспокоят вопросы обеспечения стабильности работы решения и удовлетворенность покупателей — клиенты, даже в случае пиков нагрузки, не должны дожидаться перед белым экраном загрузки страницы по 30 секунд и получать сообщение типа «К сожалению, система перегружена или возникла внутренняя ошибка. Налейте себе кофе и попробуйте обратиться еще раз».
Определим простую и эффективную стратегию достижения и поддержки высокого уровня качества обслуживания посетителей интернет-магазина — с использованием бесплатных инструментов анализа и мониторинга.
Статья будет полезна как для проектов на базе Битрикс (в т.ч. веб-кластерных), так и для других решений на nginx+apache-php/php-fpm+MySQL.
Фиксация обращений в логах — можно и нужно
Для веб-проектов с посещаемостью в единицы миллионов хитов в сутки можно и нужно настроить логирование всех обращений клиентов как к страницам, так и ресурсам (изображения и т.п.).
Чрезвычайно важно понять, что система может сохранять информацию о каждом обращении клиента и включить эту возможность — просто (это штатное средство). Если интернет-магазин развернут на веб-кластере — несложно настроить удаленное логирование на выделенный для этих целей сервер, с использованием, например, syslog-ng.
Логирование всех запросов клиентов незначительно, на проценты, снижает производительность конфигурации — однако Вы сохраняете полную информацию и контроль над качеством обслуживания клиентов, практически все случаи ошибок и зависаний интернет-магазина фиксируются и доступны для дальнейшего анализа и корректировки процесса разработки и системного администрирования. Иначе — Вы рискуете, двигаетесь вслепую и, можно сказать, не контролируете ситуацию.
К сожалению и довольно часто при эксплуатации нередко ленятся включать эту возможность (или не знают об этом), и менеджер проекта узнает о зависании веб-решения из твиттера, от коллег или Босса :-) А найти причины уже нельзя — факты ошибок нигде не были зафиксированы и «поезд ушел».
Что нужно фиксировать
Прежде всего нужно модифицировать стандартный формат логов nginx, apache, php-fpm — и добавить туда описанные ниже ключевые показатели производительности. Важно фиксировать по каждому хиту следующие данные (кроме стандартных данных, таких как URL запроса, код ответа и т.п.):
Время выполнения запроса
Для nginx это "$request_time". При двухуровневой конфигурации nginx+apache или nginx+php-fpm полезно зафиксировать в логе nginx также "$upstream_response_time".
Для apache это "%D".
Для php-fpm это "%{mili}d".
Пиковое использование памяти при обработке запроса
Если Вы используете php-fpm, полезно сохранить в логе "%{bytes}M".
Код HTTP ответа
Обычно код HTTP ответа сохраняется в логах по умолчанию. Важно сохранять эту информацию, т.к. ошибки в обслуживании клиентов как правило имеют код ответа 40х или 50х (мы разберем коды ответов подробнее далее).
Отдельные логи производительности и настройки логов
Иногда удобно создавать отдельные логи «производительности», сохраняющие информацию о времени отработки скрипта и пиковом использовании памяти, живущие рядом со «стандартными» логами. Мы часто используем такие опции:
nginx:
log_format main '$remote_addr - $remote_user [$time_local] "$host" "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for" -> $upstream_response_time';
apache:
LogFormat "%t "%r" %>s %b child:%P time-> %D" timing
php-fpm:
access.format = "%R # %{HTTP_HOST}e # %{HTTP_USER_AGENT}e # %t # %m # %r # %Q%q # %s # %f # %{mili}d # %{kilo}M # %{user}C+%{system}C"
Оффлайн анализ логов
Итак, Вы организовали процесс фиксации информации об обращении клиентов в логах (в случае веб-кластера логи централизованно собираются на отдельную машину с помощью, допустим, syslog-ng). Все ошибки и зависания страниц (даже по причине медленного канала между браузером клиента и веб-сервером) — попали в лог. Теперь нужно научиться их трактовать и инициировать устранение причин их появления.
Распространенные типы ошибок
В случае ошибок в PHP коде или самом ядре языка, прекомпиляторе (Segmentation Fault) или в операционной системе как правило отдается статус 500 (Internal Server Error). В этом случае, в большинстве веб-проектов, посетителю показывается страница о регламентных работах (или, если не настроить — техническое сообщение об ошибке :-) ).
Во время перегрузки apache или php-fpm в двухуровневой конфигурации: долгие запросы к БД или в коде идет обращение к внешнему сокету, или число воркеров на бэкэнде (число процессов apache/php-fpm) не соответствует реальной нагрузке — фронтэнд (nginx) зафиксирует в своих логах превышенное время отдачи страницы бекэндом или ошибки 502 Bad Gateway, 504 Gateway Timeout. В этом случае, если не используется балансировщик нагрузки, посетителю как правило показывается страница о регламентных работах. При использовании балансировщика (например upstream в nginx) — время отдачи страницы клиенту просто увеличится (что также будет зафиксировано в логах).
При превышении скриптом PHP памяти в лог попадет ошибка 500 (Internal Server Error).
Иногда, правда, нужно сознательно из приложения отдать код ошибки — в этом случае можно просто исключить эти записи из лога при обработке.
В общем теперь мы знаем, что факты отображения клиенту страницы о регламентных работах и другие ошибки и зависания — зафиксированы в логе и, что важно, стало легче определить причину ошибки.
Полезные отчеты по логам
Теперь можно проанализировать что происходило с обслуживанием наших покупателей за сутки. Внимание — приведенные ниже листинги скриптов адаптированы под конкретный формат лог-файлов, поэтому их скорее всего нужно будет адаптировать к Вашему проекту, что не должно вызвать сложностей.
Гистограмма HTTP-ответов на фронтэнде и бэкэнде
Total hits: 265532
200 : 264654, 99.67% ***************************************************************************************************
207 : 34, 0.01%
302 : 830, 0.31%
401 : 7, 0.00%
403 : 1, 0.00%
404 : 1, 0.00%
500 : 16, 0.01%
#!/bin/bash
TOTAL=`cat /var/log/nginx.access.log | wc -l`
echo "Total hits:" $TOTAL
cat /var/log/nginx.access.log | awk '{ hits[$14]++; }
END {for (z in hits) {printf("%6s: %8s,%6.2f% ",z,hits[z],hits[z]/total*100);{s="";a=0;while(a++<int(hits[z]/total*100)) s=s"*";print s} } }'
total="$TOTAL" - | sort -n
Аналогичный крошечный bash/awk скрипт можно адаптировать для логов apache/php-fpm. Мы видим, что более 99% хитов были успешны (код 200), однако было 16 ошибок, с которыми нужно разбираться разработчикам (в логах PHP) и искать способы их устранения — ведь это 16 страниц о регламентных работах :-). Наша цель — 0 кодов ответов 50x.
Гистограмма времени выполнения страницы на фронтэнде и бэкэнде
Total: 386664
0 ms: 276203, 71.43% ***********************************************************************
100 ms: 81466, 21.07% *********************
200 ms: 13155, 3.40% ***
300 ms: 4282, 1.11% *
400 ms: 2183, 0.56%
500 ms: 1373, 0.36%
600 ms: 968, 0.25%
700 ms: 721, 0.19%
800 ms: 586, 0.15%
900 ms: 470, 0.12%
1000 ms: 398, 0.10%
#!/bin/bash
TOTAL=`cat /var/log/nginx.access.log | wc -l`
echo "Total:" $TOTAL
cat /var/log/nginx.access.log | awk -F'->' '{ $2=$2*1000; zone = int($2/100)*100; hits[zone]++; }
END {for (z in hits) {printf("%8s ms: %8s,%6.2f% ",z,hits[z],hits[z]/total*100);{s="";a=0;while(a++<int(hits[z]/total*100)) s=s"*";print s} } }'
total="$TOTAL" - | sort -n
Видим, что подавляющее число запросов клиентов было обслужено со временем менее 500 ms. Однако с 398 хитами более секунды нужно основательно разбираться. Визуально удобно смотреть на столбики из звездочек (звездочка ставится если значение >1%) и учитывать только их.
Почему страницы или сервисы могут отрабатывать единицы секунд:
— Не используется кэширование результатов обращений в базу данных, либо само обращение в базу данных не оптимизировано.
— Выполняется тяжелый аналитический запрос, например число заказов такого-то товара за такой-то период. В этом случае ошибки нет, такой запрос лучше исключить из анализа (например они могут идти с управляющего домена admin.myproject.ru).
— В коде скрипта идет обращение к внешнему ресурсу, который завис (RSS лента, внешняя авторизация и т.п.).
Общее правило тут — обращаться с подобным «рискованным» внешним ресурсам либо в отдельном потоке (cron), либо асинхронно из браузера клиента по ajax — кэшируя результаты ответа. Т.е. даже если внешний ресурс недоступен — веб-страница должна отдаться посетителю быстро, менее чем за секунду (и аккуратно догрузить части страницы).
Гистограмма потребления скриптами памяти на бэкэнде — php-fpm
Total hits: 265562
0 KB: 25, 0.01%
4000 KB: 16, 0.01%
6000 KB: 67094, 25.26% *************************
7000 KB: 123746, 46.60% **********************************************
8000 KB: 61102, 23.01% ***********************
9000 KB: 3453, 1.30% *
10000 KB: 1263, 0.48%
11000 KB: 890, 0.34%
12000 KB: 826, 0.31%
13000 KB: 917, 0.35%
14000 KB: 1129, 0.43%
15000 KB: 1125, 0.42%
16000 KB: 936, 0.35%
17000 KB: 798, 0.30%
18000 KB: 631, 0.24%
#!/bin/bash
TOTAL=`cat /var/log/php.access.log | wc -l`
echo "Total hits:" $TOTAL
cat /var/log/php.access.log | awk -F# '{ zone = int($11/1000)*1000; hits[zone]++; }
END { for (z in hits) {printf("%8s KB: %8s,%6.2f% ",z,hits[z],hits[z]/total*100);{s="";a=0;while(a++<int(hits[z]/total*100)) s=s"*";print s} } }'
total="$TOTAL" - | sort -n
Видно, что большинство скриптов веб-решения потребляют 6-8 МБ памяти, что немного. Нередко однако, при разработке «в сжатые сроки» получаются скрипты, которые потребляют 500МБ или единицы гигабайт памяти — что вызывает зависание сервера, своппинг и общую дестабилизацию системы. Клиенты могут при этом несколько минут «ловить» страницы о регламентных работах. Важно анализировать данную гистограмму и ставить ТЗ разработчикам на оптимизацию объема потребляемой страницами памяти в пределах, допустим 64 МБ. Таким образом, постепенно, система будет потреблять стабильно предсказуемый объем памяти и Вы будете уверены, что она внезапно не впадет «в спячку» на несколько десятков минут.
Максимальные значения
Полезно также получить статистику по:
— топу самых медленных страниц в сутки
— топу самых прожорливых по памяти страниц в сутки
#!/bin/bash
echo "Max today slow times in php access logs: "
cat /var/log/php.access.log | awk -F'#' '{ print $10" "$2" "$1" "$6" "$7" "$8}' | sort -nr
Более подробно о зависаниях PHP-скриптов
В php-fpm есть замечательная возможность логировать скрипты, выполняющиеся более N секунд и делать бэктрейс в лог:
Mar 11 03:42:39 ec2-* [11-Mar-2012 03:42:38] [pool www] pid 26452
Mar 11 03:42:39 ec2-* script_filename = /var/www/html/index.php
Mar 11 03:42:39 ec2-* [0x0000000001971ea0] mysql_query() /var/www/html/bitrix/modules/main/classes/mysql/database.php:173
Mar 11 03:42:39 ec2-* [0x00000000019718a0] Query() /var/www/html/bitrix/modules/tasks/classes/general/task.php:1145
Mar 11 03:42:39 ec2-* [0x000000000196d078] __GetAllowedGroups() /var/www/html/bitrix/modules/tasks/classes/general/task.php:797
Mar 11 03:42:39 ec2-* [0x000000000196cb78] GetFilter() /var/www/html/bitrix/modules/tasks/classes/general/task.php:1442
Mar 11 03:42:39 ec2-* [0x0000000001968348] GetRootSubquery() /var/www/html/bitrix/modules/tasks/classes/general/task.php:730
Mar 11 03:42:39 ec2-* [0x0000000001967a08] GetFilter() /var/www/html/bitrix/modules/tasks/classes/general/task.php:1473
Mar 11 03:42:39 ec2-* [0x00000000019677b8] GetCount() /var/www/html/bitrix/modules/tasks/classes/general/task.php:1505
Mar 11 03:42:39 ec2-* [0x0000000001964998] GetCountInt() /var/www/html/bitrix/components/bitrix/tasks.filter/component.php:105
Мы часто пользуемся данным функционалом, т.к. он сокращает время поиска причины в разы.
«Замыкаем» системных администраторов на разработчиков
Настроив сбор ключевой статистики по хитам клиентов интернет-магазина, нужно создать постоянно действующий бизнес-процесс по доработке и оптимизации веб-решения:
— Раз в сутки статистика рассылается всем участникам технологического процесса и Вам
— При превышении заранее оговоренных показателей автоматически начинается поиск и устранение ошибок/оптимизация кода веб-проекта
В качестве целевых критериев можно взять:
— Число показов клиентам страницы о регламентных работах (т.е. число ошибок 50х) — 0
— Число хитов в публичной части, обслуженных быстрее 0.5 секунды — 100%
— Число хитов в админке (где могут выполняться «тяжелые» аналитические выборки), быстрее 10 секунд — 100%. Среднее время хита в админке — 0.5 сек.
— Максимальный объем памяти, использованный скриптом — менее 128МБ, средний — 32МБ.
Итоги
Настроив сбор и обработку ключевой статистики высоконагруженного веб-решения в течение одного-двух дней, определив целевые показатели качества обслуживания клиентов и настроив рассылку статистики — Вы создали постоянно действующий бизнес-процесс контроля и обеспечения устойчивого качества проекта — что, разумеется, позитивно скажется на удовлетворенности посетителей интернет-магазина и конверсии. В случае кратковременного выхода показателей из «зеленой зоны» по причине нехватки вычислительных мощностей, постоянного развития функционала проекта, ошибок и т.п. — все задействованные в процессе разработки и эксплуатации службы об этом сразу узнают и система достаточно быстро вернется в стабильное состояние :-), даже если вы будете в отпуске.
P.S.
В следующей статье мы рассмотрим способы организации он-лайн сбора и анализа ключевых показателей высоконагруженного веб-проекта с использованием pinba, nagios, awk. Иногда узнать из статистики к исходу дня что клиенты увидели 50000 страниц о регламентных работах — просто недопустимо :-) и необходимо реагировать оперативно в течении 5-10 минут. Тем не менее, ежесуточная статистика даже в этом случае — будет очень полезна. Удачи!
Автор:
