Мониторинг веб-проектов: real-time мониторинг и аналитика, поиск ошибок и «боевая» отладка Александр Демидов «1С-Битрикс» - презентация

1 Мониторинг веб-проектов: real-time мониторинг и аналитика, поиск ошибок и «боевая» отладка Александр Демидов «1С-Битрикс»

2 Поиск и отладка «узких» мест в проекте

3 Поиск и отладка «узких» мест в проекте

4 Почему сайт должен быть быстрым и всегда доступен? Клиенты и их лояльность (сайт недоступен – потеряны заказы). «Избалованность» клиентов быстрыми ajax- интерфейсами Индексация сайта поисковыми роботами Финансовые потери во время рекламных компаний Стоимость контекстной рекламы Репутационные риски

5 Real Time мониторинг – как узнавать о проблемах? Можно – так…

6 Real Time мониторинг – как узнавать о проблемах? Или – так…

7 Организация системы мониторинга Лучше – стандартные решения (Nagios, Zabbix и т.п.), а не самописные. Дежурная смена и/или мгновенные уведомления. Мониторить – всё. Но – аккуратно. Тысячи уведомлений будут бесполезны. Автоматизация типовых реакций. Мониторить систему мониторинга. В идеальном мире – распределенная система мониторинга.

8 Мониторинг «железа» Рейды S.M.A.R.T. – диск возможно скоро «умрет» Утилиты вендора – внутренние аппаратные тесты Имеем «запчасти» (блоки питания, вентиляторы …) или знаем где их быстро найти Периодическое тестирование железа в оффлайне

9 Мониторинг сети Загрузка канала Потери пакетов Связность узлов

10 Мониторинг операционной системы Место на дисках Очередь выполнения Размер и использование swap И т.д.

11 Тесты критичного софта Для критичного софта: считаем число процессов, объем RSS, %CPU, process system/user time

12 Тесты БД Пример для MySQL

13 Мониторинг нетипичных характеристик Наличие бэкапов Срок делегирования доменов Срок действия SSL сертификатов Баланс у провайдера смс-уведомлений

14 SSL сертификаты Чаще всего по HTTPS работает не весь сайт, а отдельные разделы Проэкспайрившийся SSL сертификат можно заметить не сразу При этом закрыты наиболее критичные разделы (корзина, авторизация и т.п.)

15 Мониторинг веб-приложения Лог работы скрипта (>) – обновился за N часов Лог ошибок работы скрипта (2>) – должен быть пуст

16 Уведомления – как у нас Cкрипт, опрашивающий страницу «Problems» Шлем «дайджест» проблем, а не по одному сообщению на каждое событие Несколько уровней критичности событий Разные списки адресатов на разные события Повтор (через 15 минут, через 2 часа), чтобы не «потерять» уведомление ОК – если все стало хорошо

17 Автоматизация типовых реакций Рост / падение LA – автоматическое масштабирование вверх / вниз Автоматический рестарт «сбойных» сервисов Автоматическое «удаление» проблемных машин Автоматическое восстановление репликации Автоматическое переключение траффика в случае аварии на уровне целого ДЦ

18 event handler # LA on the server define service{ use local-service host_name ec compute-1.amazonaws.com service_description Current Load check_command check_nrpe_1arg!check_load! event_handler restart_phpfpms } define command{ command_name restart_phpfpms command_line /usr/lib64/nagios/plugins/check_nrpe -H $HOSTADDRESS$ -c restart_phpfpm }

19 Если нет админа… Внешние системы: Яндекс.Метрика И т.д. Зачастую можно найти бесплатные варианты. Вы быстро узнаете об отказах, но не будете знать, где они произошли и почему.

20 Мониторим: Доступность и работоспособность сайта с фиксацией времени простоя и вычислением убытков Истечение срока действия: Домена SSL-сертификата Срок активности поддержки и обновлений лицензионного ключа Push-уведомления в мобильное приложение о недоступности и медленной загрузке сайта Инспектор сайта Облачный сервис по мониторингу

21 Аналитика Видим, что было Предвидим, что будет Улавливаем тренды Планируем мощности железа Сравниваем настройки софта Веб-система перестает быть черным ящиком, видно ее развитие с течением времени

22 Аналитика

23 Аналитика - MySQL Следите за числом запросов и коннектов в БД, количеством медленных запросов, прочими характеристиками

24 Если оставить все «по умолчанию»? По умолчанию MaxClients в Apache 2.x – 256 Если PHP может занять 64 Мб (на самом деле – см. memory_limit в php.ini) – весь веб-свервер может занять 16 Гб RAM 256 потенциальных коннектов к MySQL Память для одного коннекта: read_buffer_size + read_rnd_buffer_size + sort_buffer_size + thread_stack + join_buffer_size swap, OOM, деградация производительности всей системы

25 Аналитика Память Apache MaxClients MySQL buffers … Нужно «прикинуть» максимальный расход памяти в приложениях и следить за ней

26 Аналитика Дисковая подсистема

27 Аналитика Сеть

28 Поиск узких мест и действия Нужно быстро понять – где и как починить Смотрим срабатывание тестов nagios – часто единственный источник информации Смотрим уведомления от nagios Смотрим логи. Держим заготовленные скипты-парсеры логов на поиск ошибок. Смотрим графики Если получается, запускаем инструменты поиска узких мест

29 Симптомы. Что видит Клиент. URL сайта – не открывается, браузер висит Открывается пустая белая страница Отображается техническое сообщение об ошибке nginx, apache Браузер отображает свое сообщение об ошибке При отправке заполненной формы (заказа) сайт сообщает об ошибке и данные теряются Начинают «глючить» и тормозить динамические элементы сайта

30 Как узнавать о проблемах? Плохо: display_errors = On Хорошо: error.log access.log Инструменты мониторинга и отладки

31 error.log Агрегирующие скрипты (PHP, Perl, bash): PHP Signals: 62 […] PHP Fatals: 94 […] PHP Warnings: 5 […]

32 access.log Среднее время – менее 1 сек., пики – до 3-5 сек. Все ли здесь хорошо?

33 access.log Apache LogFormat "%t \"%r\" %>s %b child:%P time-> %D" timing Nginx log_format timing … '->$upstream_response_time'; PHP-FPM access.format = … %{mili}d … s %b child:%P time-> %D" timing Nginx log_format timing … '->$upstream_response_time'; PHP-FPM access.format = … %{mili}d …">

34 Аналитика – со стороны пользователя Гистограммы распределения времени хитов, памяти, кодов ответа и т.п. Мало знать «среднюю температуру по больнице» и мониторить только главную страницу сайта

35 php-fpm.conf ; рестартовать при ошибках emergency_restart_threshold = 1 emergency_restart_interval = 10 ; лог медленных запросов request_slowlog_timeout = 5 slowlog = /var/log/php/

36 Поиск «узких» мест Apache /server-status Включенные логи медленных запросов php-fpm, nginx, apache, mysql

37 Xdebug Помогает при отладке Практически не применим «на бою» Учимся снимать и понимать трейс страниц: ini_set('xdebug.collect_params', 3); xdebug_start_trace(); … xdebug_stop_trace(); TRACE START [ :37:13] > {main}()../trace.php: > str_split('Xdebug')../trace.php: > ret_ord('X')../trace.php: > ord('X')../trace.php: > ret_ord('d')../trace.php:10 …

38 Инструменты поиска узких мест XHProf, pinba

39 Инструменты поиска узких мест XHProf (github.com/facebook/xhprof) Почти не создает нагрузку на бою Можно быстро найти корень проблемы Полезно автоматически сохранять трейсы долгих страниц … и анализировать их с разработчиками

40 Поиск «узких» мест Pinba – для аналитики Xhprof – профилирование extension=xhprof.so extension=pinba.so pinba.enabled=1 pinba.server= :3307 Подключение – dbconn.php, init.php, но чаще удобнее через auto_prepend_file

41 Подключение xhprof php.ini: auto_prepend_file = "/home/bitrix/www/auto_prepend.php" auto_append_file = "/home/bitrix/www/auto_append.php auto_prepend.php

42 Подключение xhprof auto_append.php

43 xhprof

44

45 Инструменты поиска узких мест Если никаких других инструментов нет Или надо срочно локализовать проблему на «бою» Можно просто перезапустить Apache / nginx / PHP-FPM Но… Вы не найдете суть проблемы, и она повторится Старые добрые утилиты unix lsof strace gdb grep, awk, sort, uniq и т.д.

46 Определение процесса lsof | grep php_sessions […] httpd bitrix 56u REG 0, /tmp/php_sessions/sess_3m8ulspjvousm6nndmle3ul8s5 httpd bitrix 57uW REG 0, /tmp/php_sessions/sess_bvgb0oaeq6ilqq8ooneo1j7e61 […] top PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND bitrix m 128m 99m S :40.13 httpd 4006 bitrix m 86m 63m R :05.61 httpd bitrix m 121m 94m R :42.52 httpd

47 strace strace -p […] access("/home/bitrix/www/bitrix/modules/cluster/classes/general/memcache_cache.php", F_OK) = 0 sendto(54, "get 4ac3269f374e0dde2ea7074e4f2a"..., 60, MSG_DONTWAIT, NULL, 0) = 60 poll([{fd=54, events=POLLIN|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=54, revents=POLLIN}]) recvfrom(54, "VALUE 4ac3269f374e0dde2ea7074e4f"..., 8192, MSG_DONTWAIT, NULL, NULL) = 106 sendto(55, "get 0ae4f4fdcffaa0d250c34fd3d7f6"..., 61, MSG_DONTWAIT, NULL, 0) = 61 poll([{fd=55, events=POLLIN|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=55, revents=POLLIN}]) recvfrom(55, "VALUE 0ae4f4fdcffaa0d250c34fd3d7"..., 8192, MSG_DONTWAIT, NULL, NULL) = 107 sendto(55, "get 0ae4f4fdcffaa0d250c34fd3d7f6"..., 112, MSG_DONTWAIT, NULL, 0) = 112 poll([{fd=55, events=POLLIN|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=55, revents=POLLIN}]) recvfrom(55, "VALUE 0ae4f4fdcffaa0d250c34fd3d7"..., 8192, MSG_DONTWAIT, NULL, NULL) = 325 […] Process detached

48 gdb gdb –p (gdb) source /src/php /.gdbinit (gdb) dump_bt executor_globals.current_execute_data [0x0252d628] stemming() /var/www/html/bitrix/modules/search/tools/stemming.php:231 [0x0252bc78] stemming() /var/www/html/bitrix/modules/search/classes/mysql/search.php:1090 [0x02525ec8] StemIndex() /var/www/html/bitrix/modules/search/classes/general/search.php:1332 [0x025223f8] Index() /var/www/html/bitrix/modules/iblock/classes/general/iblockelement.php:4857 [0x0251b670] UpdateSearch() /var/www/html/bitrix/modules/iblock/classes/general/iblockelement.php:3295 [0x02519c40] Add() /var/www/html/bitrix/modules/crm/classes/general/crm_webdav_helper.php:486 [0x ] Save Attachment() /var/www/html/bitrix/modules/crm/classes/general/crm_ .php:867 [0x065c2030] MessageAdd() [0x0250fcc8] call_user_func_array() /var/www/html/bitrix/modules/mail/classes/general/mail.php:2477 …

49 Смотрим в БД Собираем и анализируем ошибки SQL: define("LOG_FILENAME", "/var/log/db_error.log"); Наблюдаем за запросами в БД – лог медленных запросов MySQL, innotop. Используем стандартные возможности Битрикс: «Настройки/Производительность/Сервер БД»

50 Борьба за долгие запросы log-output = FILE slow-query-log = 1 slow-query-log-file = mysql_slow.log long-query-time = 1 #percona log_slow_verbosity = microtime,query_plan,innodb # Time: :43:47 # [ ] # Thread_id: Schema: user Last_errno: 0 Killed: 0 # Query_time: Lock_time: Rows_sent: 0 Rows_examined: 1 Rows_affected: 0 Rows_read: 0 # Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # InnoDB_trx_id: 33E7689B # QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No # Filesort: No Filesort_on_disk: No Merge_passes: 0 # InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: # InnoDB_rec_lock_wait: InnoDB_queue_wait: # InnoDB_pages_distinct: 4 UPDATE b_user_option SET `COMMON` = 'N', `VALUE` = 'a:19:{i:1;b:1;i:25;b:1;i:59;b:1;i:63;b:1;i:89;b:1;i:97;b:1;i:103;b:1;i:10 5;b:1;i:117;b:1;i:127;b:1;i:175;b:1;i:213;b:1;i:231;b:1;i:267;b:1;i:293;b:1;i:363;b:1;i:391;b:1;i:401;b:1;i :427;b:1;}', `NAME ` = 'openTab', `CATEGORY` = 'IM', `USER_ID` = 263 WHERE ID=1719;

51 Одиночные медленные запросы Одиночный медленный запрос всегда работает медленно Его просто найти (slow.log) Его просто изучать (EXPLAIN)

52 Подробная статистика без Percona mysql> SHOW PROFILES; Empty set (0.02 sec) mysql> SHOW PROFILE; Empty set (0.00 sec) mysql> SET PROFILING=1; Query OK, 0 rows affected (0.00 sec) mysql> SELECT COUNT(*) FROM mysql.user; | COUNT(*) | | 3024 | row in set (0.09 sec)

53 Подробная статистика без Percona mysql> SHOW PROFILES; | Query_ID | Duration | Query | | 1 | | SELECT COUNT(*) FROM mysql.user | row in set (0.00 sec)

54 Подробная статистика без Percona mysql> SHOW PROFILE; | Status | Duration | | starting | | | Waiting for query cache lock | | | Waiting on query cache mutex | | | checking query cache for query | | | checking permissions | | | Opening tables | | | System lock | | | init | | | optimizing | | | executing | | | end | | | query end | | | closing tables | | | freeing items | | | logging slow query | | | cleaning up | | rows in set (0.00 sec)

55 «Живая» система – много небольших запросов mysql> SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME; | time | count | total | | | 0 | | | | 2011 | | | | | | | | 4624 | | | | 2994 | | | | 200 | | | | 33 | | | | 1 | | | | 0 | | | | 0 | | | | 0 | | | | 0 | | | | 0 | | | TOO LONG | 0 | TOO LONG | rows in set (0.00 sec)

56 Аналитика - MySQL Одиночные медленные запросы отлавливаются просто. Сложнее мониторить общее состояние системы с большим количеством относительно быстрых запросов.

57 Приложение всегда работает в условиях ограниченных ресурсов Постоянный feedback в две стороны: админам и разработчикам – в автоматическом и полуавтоматическом режиме

58 «Здоровый» сайт Сайт всегда доступен для посетителей Вы оперативно узнаете о любых проблемах и имеете план их решения Отлажены сценарии поиска «узких» мест Аналитические данные позволяют прогнозировать, где могут появиться «узкие» места Вы умеете оценивать комфорт пользователей в реальных «цифрах»

59 Спасибо за внимание! Вопросы? Александр Демидов