Анализ логов в реальном времени

    Современные системы мониторинга “из коробки” позволяют отслеживать практически все показатели отдельного узла системы, но обладают рядом существенных недостатков
    • зная все об одном узле, о работе системы в целом они не имеют никакого представления — попробуйте из коробки выдать руководству “в данный момент у нас 1200RPS на фронте, 90% страниц отдается за 300мс, 95% за 650мc, системных ошибок и таймаутов происходит меньше 10 в секунду” (см картинку под катом)
    • выход за рамки одного из системных показателей одного из узлов системы еще не значит, что стоит бить тревогу — возможно узел попал под повышенную нагрузку, или разработчики сменили алгоритм
    • в рамках мониторинга отдельных узлов практически невозможно уследить постепенную деградацию сервиса — как правило он срабатывает только когда уже “ничего не работает”
    • деградация производительности внешних сервисов не отслеживается в принципе (вас никогда не банил CDN?)


    На исходной у нашей площадки более 1.000.000 уников, ~100.000.000 http запросов на фронтенд в сутки и развесистый, в плане сопровождения, зоопарк проектов. Набор ключевых слов — nginx, apache, php (двух вариаций), oracle. С заядлой периодичностью возникают ситуации “у нас все работает” по отдельно взятым зонам ответственности либо, что тоже не редкость, “у вас ничего не работает”. На границах ответственности идет сплошная передача тикетов.
    Мы не стали изобретать велосипед и решили сделать мониторинг по времени и корректности отклика пользователю с отслеживанием отклика бекендов, а также какие из них были задействованы при обработке конкретного запроса. Ну и плюс наши объемы — не сильно большие, но несколько граблей по ходу изложения можно продемонстрировать.


    Что мы получили в итоге.



    1. Подготовка исходных данных.


    Если узлов в системе больше одного, то неплохо бы иметь способ отследить один запрос начиная с front сквозь всю систему. Если узлов десятки — IP клиента уже не поможет. Если внизу стоит база, то DBA порой будут бегать с паяльником и фразой “чей запрос???”. Ну и стандартный combined просто не содержит какой-либо информации о времени обработки на бекенд, попадании в кеш, выбранном upstream, времени отдачи данных пользователю. В стандартных модулях nginx есть практически все, что может нам понадобиться. Мы добавили только один модуль от HeadHunter
    github.com/hhru/nginx_requestid, присваивающий уникальный идентификатор каждому запросу на nginx и позволяющему писать его в лог, а также пробрасывать его вверх и вниз в заголовках. Итоговый формат нашего nginx лога выглядит следующим образом.



    Страшно? Веселее, что в полях типа upstream могут быть следующие вещи “upstream_1: upstream_2”, для всех бекендов, что обрабатывали данный запрос. Request_id уже описывался, два последних uid_got, uid_set — модуль ngx_http_userid, который позволяет отслеживать уже конкретного пользователя, установкой ему системных кук. Почему в качестве разделителя используются четыре пробела будет описано в разделе парсинга. На уровне Apache или php-fpm имеет смысл записывать в логи пришедший сверху request_id, а наверх отдавать имя хоста, если в качестве upstream указан балансировщик запросов. На уровне приложения стоит завести правило указывать request_id в сообщених об ошибках. Один из способов пробросить данные запроса в сессию Oracle я описывал в небольшой заметке. Его преимущество в том, что не приходится просить разработчиков делать то же самое их средствами и есть гарантия, что данные у Вас появятся по всем проектам сразу. Также есть смысл смотреть в сторону pinba или xhprof для отслеживания времени ожидания внешних ресурсов (базы, api сервисов, системных вызовов) для каждого запроса и в среднем по проекту/площадке. Наше адаптированное решение в этой области будет готово ближе к зиме.

    Дальнейшее изложение посвящено наше попытке анализа логов на примере логов nginx — как самых информативных и объемных в нашей системе на данный момент.

    2. Сбор логов в единый центр.


    Стандарт де-факто в аггрегации логов — различные форки и потомки syslog. В качестве транспорта используется UDP, чтобы избежать накладных расходов в виде поддержки соединения и гарантирования доставки. Потерять несколько процентов сообщений в штатном режиме можно себе позволить, более глобальные потери будут связаны уже с глобальными проблемами вашей инфраструктуры, о которых вы узнаете из других источников. Подробнее о подводных камнях на большом потоке сообщений можно узнать из доклада директора по эксплуатации hh.ru “Опыт перехода на SOA” www.slideshare.net/kuchinskaya/sivko, в нем рассмотрены несколько вариантов сбора логов в единое место. Помимо доставки по udp есть смысл собирать логи в единое файлохранилище на будущее.

    На нашей площадке исходно была решена вторая часть задачи — все логи изначально пишутся на сетевое хранилище. Для упрощения в прототипе своего анализатора мы просто читаем логи по nfs. Чем это плохо в принципе — запись логов тратит ресурсы всей системы круглые сутки, доступность логов зависит от исправности сетевого хранилища (у Вас никогда не падал NetApp посреди рабочего дня?), буферизация записи усложняет алгоритм разбора логов. Также в лог файл пишется строка в текстовом формате, если пересылать данные о запросе в сериализованном виде — избежим затрат на парсинг на стороне приемника.

    2.5 Парсинг логов.


    В нашем случае парсер написан на Perl, данные кладутся в MongoDB 2.2.0. Алгоритм прост до безобразия — помним последнюю обработанную позицию в файле, сравниваем текущий размер, если дельта больше отсечки — отправляем в парсинг файла, в парсинге проверяем корректность записи (про буферизацию записи все помним?). Из граблей
    • если файлов много — храните дескрипторы, вместо открытия файла всякий раз, не так много по времени, но хранилищу станет приятней
    • reg exp по нашему формату обрабатывал 700 строк в секунду, после перехода на формат со стандартным разделителем и заменой регулярки на split скорость возросла до 10-20 тысяч строк в секунду. Здесь цифры говорят лучше внутренних убеждений
    • если время итерации меньше двух-трех секунд — сделайте небольшой sleep, хранилищу станет еще приятней, что его не дергают на stat сотен файлов каждую секунду
    • batch_insert сделает приятно базе, но у mongo есть ограничение в 16MB на один вызов insert (4MB до 2.2)


    Всех этих прелестей можно избежать отсылая данные по udp.

    3. Временное хранилище для обсчета аналитики и поиска.


    Хранить все данные за много времени вместе с индексами можно, но ОЧЕНЬ дорого. В реальной жизни используется временное хранилище с возможностью строить аналитику с данными за последние несколько часов — сутки. Для оперативной диагностики больше данных не имеют смысла, глобально исторические отчеты всегда можно построить по сырым данным.

    Мы используем MongoDB потому что … нам так захотелось. Грубо, но это так — Вы можете выбрать любой инструмент, в котором Вы будете готовы реализовывать подобную систему. Чем более удобно и быстро реализуется группировка записей и обновление данных в хранилище, тем лучше.

    Из нерелигиозных плюсов Mongo
    • capped collections — fifo коллекция записей, в нашем случае пока вполне хватает коллекции в 3GB, файлы которой лежат на ramdisk
    • aggregation framework — новая фишка с версии 2.2, под наши задачи группирует посекундные 1.200-10.000 за 50-200мс
    • ttl collections — коллекции, где можно указать время жизни записей (аналог expire в memcache), imho несколько сыро
    • скорость записи в один поток — 5-6 тысяч записей в секунду, можно масштабировать несколькими потоками записи


    Грабли
    • в версии 2.2.0-rc0 в aggregation $project можно было передавать в оператор $add строки, таким образом формировался ключ группы из нескольких полей, в версии 2.2.0-rc1 и выше такой возможности нет, а оператор $concat обещается в 2.3.x без каких-либо сроков. Пришлось обходить на уровень выше, в парсере — записью группового ключа в каждую запись
    • чем больше индексов будет создано, тем медленней будет вставка. Чем меньше индексов — тем меньше возможностей для поиска. У нас сейчас два индекса — системный идентификатор и timestamp из записи. Больше на тестовом стенде мы себе позволить не можем.
    • capped collection не шардится встроенными средствами, это придется делать на уровне приложения.


    Несмотря на вторую граблю относительно сложный запрос “выяснить top-50 IP по числу запросов, нагрузке на бекенд, трафику за последнюю минуту” вычисляется за 800-1200мс. В нашем случае одна железяка обслуживает запись данных и их вытеснение (master), на вторую идет реплика, чтобы обсчет аналитики не тормозил запись.

    Есть также желание опробовать мейловский Tarantool (tarantool.org) — до исправления грабли в парсере с regexp он показывал не очень красивые цифры по скорости загрузки данных. После исправления не тестировалось, надеюсь на приятные неожиданности.

    Из потенциальных плюсов Tarantool
    • memory based база данных
    • встроенный язык lua для хранимых процедур
    • доступность автора на русском языке и high perfomance тусовках в Москве


    4. Агрегаты, персентили …


    На прошлых этапах мы получили массив записей из лог файлов узлов нашей системы, доступный для быстрого поиска и группировки по необходимым правилам. Наш тестовый скрипт на Perl подготавливает данные следующим куском

                    my $res3=$slave->logs2->run_command(
                            {
                                    aggregate=>'lines',
                                    pipeline=>[
                                            {'$match'=>{'tstamp'=>{'$lt'=>$i,'$gte'=>$i-1}}},
                                            {'$project'=>{
                                                            'gf'=>1,
                                                            'upstream_time'=>1
                                                            ,'resp_time'=>1
                                                            ,'size'=>1
                                                    }
                                            },
                                            {'$group'=>{'_id'=>'$gf',total=>{'$sum'=>1},traffic=>{'$sum'=>'$size'},'times'=>{'$push'=>'$upstream_time'},'response'=>{'$push'=>'$resp_time'}}}
                                    ]
                            }
                    );
    
    


    где поле gf

    $inf{gf}=join(' ',($inf{upstream},$inf{code},$inf{host},$inf{backend},$inf{frontend},$inf{cache_status},$inf{content_type},$inf{url},$inf{upstream_code}));
    


    На выходе получаем ссылку на массив предварительно сгруппированных данных, которые в дальнейшем превращаем в конечные метрики. В нашем случае нас интересуют общие метрики крутости=нагруженности площадки, показатели времени ответа конечным пользователям в целом/по типам контента, эффективность наших кешей, число ошибок. Примерная картина по площадке в целом может выглядеть как на скрине в начале поста. Наборы попроектных/посистемных метрик формируются из пожеланий службы эксплуатации, администраторских групп (у нас например отдельный экран посвящен запросам к полнотекстовому индексу из разных проектов — чтобы видеть источник нагрузки на узел), разработчиков, владельцев сайтов и непосредственного руководства. После первой демонстрации у нас из пожеланий стали формироваться один-два экрана в неделю.

    Ключевое требование к обсчету — время обсчета временного интервала и загрузки в системы мониторинга должно быть меньше этого интервала.

    У нас это время порядка 100-200мс на секундный интервал. Секундный интервал выбран на этапе сборки конструктора, чтобы обкатать все в самых жестких условиях. В реальных условиях больше прав на жизнь имеют 5/10/30/60-секундные средние значения.

    5. Посчитали мы и что дальше?


    Сначала данные надо как-нибудь красиво отобразить. На этапе отладки предыдущих шагов использовалась библиотета highcharts, данные брались из MongoDB, куда складывались скриптом из пункта 4.
    • не решает вопросов произвольного формирования набора графиков на страницу конечным пользователем
    • не приспособлен для задач мониторинга в принципе (нет отслеживания граничных значений, подсчета доступности сервиса по SLA и т.д.)
    • обеспечил WOW-эффект




    В дальнейшем оформились ключевые пожелания к системе мониторинга, куда мы грузили бы данные

    • возможность заводить свои метрики
    • загружать их снаружи (api/софт для загрузки)


    Не так уж много, нам вполне подошел zabbix, который и показан на заглавном скрине. Здесь, как и с mongo, все зависит от личных предпочтений и конкретной ситуации. Свои метрики заводятся с типом zabbix trapper, а данные загружаются утилитой zabbix_sender в batch режиме, в качестве базы mysql. Загрузка сотни значений занимает 1-2мс.

    6. Итоги


    После проделанной работы, которая отняла около человеко-месяца в фоновом режиме у нас появились
    • актуальная информация по выбранным метрикам с задержкой в 90 секунд (время гарантированной записи сквозь буферы, парсинг, запись в монго, репликация на slave, обсчет)
    • возможность отслеживать обработку запроса пользователя по всем узлам системы (ngx_request_id)
    • понимание на самом нижнем уровне — db, чем ее грузят сверху (проброс host, request_uri, request_id внутрь информации о сессиях)
    • статистика использования сервиса полнотекстового поиска проектами
    • взгляд на площадку с позиции предоставляемого сервиса — генерации и раздачи контента множеством проектов
    • метрики-маяки проблем, специфичные для отдельных проектов и площадки в целом
    • красивые картинки для руководства
    • платформа для реализации большинства возможных хотелок (должно стоять нулевым пунктом на нынешней стадии)


    К путям развития
    • отслеживать как пули долетают до конечного пользователя (время загрузки и отображения всех элементов страницы)
    • сокращение окна с 90 до 30 секунд
    • алгоритмы отслеживания постепенной деградации сервиса
    • поиск по сырым данным — здесь нам собирают тестовый стенд со splunk и нашими данными за две недели
    • адаптация xhprof под наши пожелания


    Если есть желание подробней окунуться в тему — на профи тусовках за последний год тема мониторинга и профайлинга поднималась неоднократно, если в комментах будут ссылки на подобные публикации — буду только рад.

    В данной заметке очерчены основные контуры нашей системы, которая только начинает обрастать конкретикой. Начальные шаги самые важные и я буду рад услышать, что положено в основу Ваших систем — принципы и технологии.
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More
    Ads

    Comments 17

      +2
      Создалось впечатление, что основное достигнутое — это «красивые картинки для руководства». Вопрос — кроме того, что обеспечивает zabbix «из коробки», достигнуто? Насколько я понимаю, целей для такого рода работ может быть две — понять что привело к проблеме и выявить проблему. Мне всегда хотелось как-то припахать карты Шухарта, не смотрели в эту сторону?
        0
        На первом этапе, который описан здесь, стояла задача найти способ мерить показатели не отдельных узлов площадки, а предоставляемого сервиса. Самым сложным оказалось связать между собой поступающие данные с трех его уровней — фронтенда, сервера приложений и сервера БД, что было достигнуто единым для всех уровней идентификатором запроса. Это дает возможность, заметив признаки проблемы на любом из уровней, найти его следы на остальных. Для полноценного мониторинга нам еще не хватает возможностей по измерению отклика вспомогательных сервисов (баз данных, схд, сторонних api) — когда он появится мы сможем находить зависимости между проблемами на главном сервисе и вспомогательных. В этом направлении будем двигаться осенью.

        За карты Шухарта — спасибо, пригодится когда будем настраивать триггеры.
        +2
        Мне кажется решение Splunk как раз предназначено для вашей задачи. Без бубнов.
          0
          Очень даже может быть, но не без бубнов. Splunk из коробки дает анализатор логов, поиск по ним, красивые картинки, но не имеет никакого «статистического аппарата» (это информация технарей, делавших нам презентацию), его надо расширять самостоятельно на питоне, насколько он будет быстро считать все что нам нужно пока что под большим вопросом. На просьбу распарсить наши двухнедельные логи на стенде сначала бойкий интегратор пропал уже скоро на месяц.
          0
          1) Почему в разделителях логов 4 пробела и потом это парсится регуляркой? Можно было взять более уникальный разделитель и нарезать строчки простым split/explode/etc.
          У нас, например, в подобных логах используется ' | ' между полями.

          2) Если perl скрипт разбора логов работает от предыдущего смещения файла до текущего конца, то как вы выполняете ротацию самого файла лога? Не может же он бесконечно разрастаться.
            0
            1. Неудачно выразился — мы сначала парсили близкий к традиционному формат регуляркой, потом перешли на четыре пробела и split. Пробелы в числе четырех штук имеют мало шансов появится в наших данных, классические односимвольные разделители — запросто.
            2. Перед смещением проверяется текущий размер файла по имени, если он меньше последнего — указатель смещаем в ноль и переинициализируем дескриптор.
            +1
            Вот у нас, фактически, тоже самое. Дополнительно еще используется graylog2, куда разработчики в real-time шлют результаты работы логики приложения. В нем есть триггеры, которые по регуляркам парсят логи и сразу поднимают тревогу, если сообщений вдруг по каким-либо причинам превышено. То есть все само аггрегируется и проводится первоначальный анализ. Это уже не системные логи, а логи работы приложения. Например, rps клиента с заданным ключом, либо как посчиталась реклама (или не посчиталась).
            Критичные и нужные данные (системные и access логи), необходимые для обсчета и анализа, и которые надо хранить хоть чуть-чуть сырыми — складываются также на диск и дальше уже отложено обрабатываются парсерами и анализаторами. Ну и заббикс с кучей логики и веб-проверками.

            Также наблюдается тенденция превращения наших фронтендов в web-app. Nginx может сам сформировать нужный лог (с аггрегацией и первичным анализом) и отправить куда-нибудь уже готовую статистику.
              0
              Спасибо за информацию. Скажите — на каком железе у Вас это работает, за какой срок хранятся сырые логи для поиска?
                0
                Виртуалки openvz, штук 6 в среднем для всех задач. В каждой 4 камня, 250 Gb disk, 16Gb RAM. Примерно неделю хранятся сырые логи. В основном тут логи Postgres и немного Nginx. Аггрегированая и обработанная статистика от системных сервисов хранится год (собственные скрипты и pgfouine).
                Ну еще у нас есть сервис с OLAP кубами, который анализирует бизнес-статистику, про них не скажу, другое подразделение занимается. Заббикс в такой же виртуалке, там данные за год, мониторится порядка 4000 элементов.

                А, забыл еще сказать про профилирование скриптов приложений. Мы используем pinba, но там «мгновенная» статистика, только посмотреть и отладить, хранить ее смысла нет. Система постоянно расширяется и дополняется функционалом, вот, доросли до geo распределенного кластера, его тоже надо мониторить, причем с разных точек.
                Нам недавно программисты написали тесты для своих аппликух, сейчас пробуем их запускать из Германии, например. Получается что-то типа pingdom или hosttracker, но информации внутри немного больше.
              0
              1. Хорошо бы добавить в статью гиперссылки на доклад и модуль хедхантера
              www.slideshare.net/kuchinskaya/sivko
              github.com/hhru/nginx_requestid
              2. Чтобы работало быстро можно некоторые метрики строить сразу в парсере логов, те которые не требуют пересортировки данных (кол-во запросов в секунду с разбивкой по типам, среднее время ответа, средний размер запроса и т.п.), мы таким образом анализируем свои 400 000 запросов в секунду
              3. Те метрики которые требуют обработки всего минутного блока, совершенно не нуждаются в базе данных, какой-нибудь аналог утилиты sort с буфером в памяти должен быстрее и экономичнее, мы считали когда-то так уников, получается быстро
              4. посчитанные метрики удобно хранить в Graphite, в него удобно писать метрики из приложений, хранит только данные, а график строит динамически в момент запроса, графики можно очень широко комбинировать и построить практически любой отчет онлайн (например можно выделить графики со всплесками отфильтровав по производной)
              5. С тарантулом могут быть сложности, не помню чтобы он умел инвалидировать по Expires блоки записей
              6. Отправка логов по UDP хороша, позволяет гарантированно не втуплять в диск на фронтах, чтобы работало на приемной стороне надо увеличивать приемный буфер до нескольких мегабайт, тогда держит порядка 150 000 запросов в секунду
                0
                Спасибо за развернутый комментарий.
                1. Ссылки добавил.

                По остальным пунктам — может выступите первого октября, думаю многим будет интересно поспрашивать вживую?
                  0
                  пропустил сообщение, при случае могу рассказать на какой-нибудь конференции тематической
                  0
                  Чем вы парсите, что 400к в секунду выдает? Или просто 8 потоков по 50к?
                    0
                    код на языке C, но это конечно близко к пределу производительности одного ядра
                  0
                  А вы не делали интеллектуальный анализ логов: поиск корреляций, зависимостей, приближенных циклов и повторений? Вопрос скорее общий, не конкретно по описанной задаче. Например, на протяжении продолжительного времени каждый день приходит определенное кол-во запросов с каким-нибудь ключом, а вот сегодня их в два раза меньше, но вместе с этим упали / выросли запросы с другим ключом. Как найти такую закономерность, если точно не знать, что она есть, а только допускать ее возможность?
                    0
                    Задумывались, но пока не делали. Эта задача уже ближе к математике, чем к технологиям.
                    Как вариант для частной задачи — просчитать на выбранном периоде эталонные значения/соотношения для всех ключей, при нарушении на выбранный процент — генерировать аллерт по каждому нарушенному ключу.
                      0
                      Тут можно нейронные сети использовать, вот только время работы у них может быть неприемлемое.

                  Only users with full accounts can post comments. Log in, please.