Your browser is not supported anymore. Please update to a more recent one.


Download Chrome

Download Firefox

Download
Internet Explorer

Download Safari

Эволюция сборки логов «облака» и сборщик логов в open source

6 октября 2015 | Юрий Насретдинов
Здравствуйте, меня зовут Юрий Насретдинов, я работаю старшим инженером в Badoo. За последние полтора года я сделал несколько докладов на тему того, как работает наше облако. Слайды и видео можно посмотреть тут и тут.

Сегодня настало время рассказать о ещё одной части этой системы — о сборщике логов, который мы вместе с этой статьей выкладываем в open-source. Основная часть логики нашего облака написана на языке Go, и эта подсистема не является исключением.
Исходные коды системы: https://github.com/badoo/thunder/
В этой статье я расскажу вам о том, каким образом мы доставляем логи приложений в нашем облаке, которое мы называем просто «скриптовым фреймворком».

Логи приложений


Наши приложения, запускаемые в облаке, представляют из себя классы на PHP, которые в простейшей реализации имеют метод run() и получают на вход данные задания, например, число от 1 до N, где N — максимальное число экземпляров для этого класса. У каждого задания есть свой уникальный id, и конечной целью является доставка логов в какое-то централизованное хранилище, где можно будет легко найти логи как конкретного запуска, так и все логи класса сразу.


<?php
class ExampleScript extends ScriptSimple {
    public function run() {
        $this->getLogger()->info("Hello, world!");
        return true;
    }
}

Первая реализация: по файлу на id запуска


Поскольку каждый запуск задания в облаке представляет из себя запуск отдельного PHP-процесса, самым простым и очевидным для нас способом собирать логи каждого запуска по отдельности было перенаправление вывода каждого процесса в отдельные файлы вида <id>.<out|err>.log, где out и err используется для каналов стандартного вывода и ошибок соответственно.

Таким образом, задача сборщика логов состояла в регулярном опросе директории с логами на предмет изменений и отправке новых строк, которые появлялись в файлах. В качестве средства доставки логов на центральный сервер мы использовали scribe, а последнее отправленное смещение запоминалось прямо в имени файла (это работает, если вы продолжаете писать лог в открытый дескриптор файла). Смещение из себя представляет размер файла на момент отправки — размер будет расти по мере записи новых логов в файл, и новые строки нам нужно доставлять начиная с последней доставленной позиции в файле:


<?php // упрощенный пример
while (true) {
  foreach (glob("*.log") as $filename) {
    $filesize = filesize($filename); // 200
    $read_offset = parseOffset($filename); // "id.out.log.100" -> 100
    if ($filesize > $read_offset) {
      sendToScribe($filename, $read_offset); // послать в scribe начиная с $read_offset
      rename($filename, replaceOffset($filename, $filesize); // "id.out.log.100" -> "id.out.log.200"
    } else if (finishedExecution($filename)) {
      unlink($filename);
    }
  }
  sleep(1);
}


Этот подход нормально работает, пока у вас есть небольшое количество файлов в директории, в каждый из которых более-менее активно пишут. Перенаправление в отдельные файлы позволяет легко отличать вывод каждого запуска по отдельности, даже если приложение делает простое echo вместо использования «логгера», который добавляет в начало строки идентификатор запуска. По сравнению с записью в один и тот же файл, в этом случае невозможно перемешивание вывода от разных «инстансов» приложения. Также легко понять, что в файл больше никто не пишет: если процесс с заданным id уже завершился, то мы можем удалить соответствующий файл с логом, когда он полностью доставлен в scribe.

Однако, у этой схемы есть множество недостатков. Вот основные из них:

  1. в имени файла не содержится информации об имени класса — эту информацию нужно запрашивать из базы облака;
  2. в scribe можно легко «засунуть» намного больше данных, чем может успевать обрабатывать сервер-приемник. В такой ситуации scribe начинает буферизовать данные локально в файловую систему, дублируя те логи, которые уже есть на диске;
  3. если сборщик логов перестает успевать удалять старые файлы, то их может накопиться очень много. У нас несколько раз скапливалось по миллиону файлов на хост, и доставить нужные логи к тому времени, когда они еще были бы актуальны, уже не было никакой возможности;
  4. файловая система ext3 (и ext4 в меньшей степени) не очень хорошо себя ведет, когда вы постоянно создаете, переименовываете и удаляете много файлов — мы регулярно видели наши процессы «залипшими» на сотни миллисекунд в D-state при записи в файлы и при их создании;
  5. если вы хотите избавиться от постоянного опроса stat() файлов и начать использовать inotify, вас тоже ждет неприятный сюрприз. Из-за особенностей реализации, особенно хорошо заметных на многоядерных системах с большим количеством свободной памяти, при вызове inotify_add_watch() в директории, в которой регулярно создаются и удаляются файлы, может происходить «залипание» всех процессов, которые пишут в файлы в этой директории, и длиться это может десятки секунд.

Если вас интересуют подробности по поводу причин «плохого» поведения inotify в условиях, описанных в пункте (5), читайте спойлер ниже.

Причины очень медленного inotify_add_watch()
Как было описано в пункте (5), у нас была директория с логами. В этой директории постоянно создавалось, удалялось и переименовывалось большое количество файлов. Важно, что файлы содержали уникальные имена, поскольку в них содержались id запуска и прочитанные смещения. Проблему достаточно легко воспроизвести даже на одноядерной системе с небольшим количеством памяти, хоть и в меньшем масштабе. Те цифры, которые приведены в статье, получены на многоядерной машине с десятками гигабайтов памяти. Создадим пустую директорию, назовем ее, например, tmp. После этого запустим простой скрипт: $ mkdir tmp $ cat flood.php Все, что этот скрипт делает — 10 миллионов раз выполняет stat() или access() на несуществующие файлы вида fileN, где N — число от 0 до 9 999 999. Теперь выполним системный вызов inotify_add_watch (начнем следить за изменениями в директории с помощью inotify): $ cat inotify_test.c #include void main(int argc, char *argv[]) { inotify_add_watch(inotify_init(), argv[1], IN_ALL_EVENTS); } $ gcc -o inotify_test inotify_test.c $ strace -TT -e inotify_add_watch ./inotify_test tmp inotify_add_watch(3, "tmp", …) = 1 <0.364838> Флаг -TT для strace заставляет печатать в конце строки время выполнения системного вызова в секундах. Мы получили время в сотни миллисекунд на системный вызов, который добавляет одну пустую директорию в список для уведомлений о новых событиях. В рамках такого простого эксперимента сложно получить наблюдаемые нами десятки секунд на production-системе, но проблема все равно налицо. Давайте создадим новую пустую директорию tmp2 и проверим, что для нее все отрабатывает моментально: $ mkdir tmp2 $ strace -TT -e inotify_add_watch ./inotify_test tmp2 inotify_add_watch(3, "tmp2", …) = 1 <0.000014> Можно видеть, что для свежесозданной пустой директории ничего подобного не наблюдается: системный вызов отрабатывает практически мгновенно. Чтобы выяснить, почему у нас возникают проблемы с директорией, в которой много раз выполнили stat() от несуществующих файлов, давайте немного модифицируем исходную программу так, чтобы она не выходила, и посмотрим результат работы команды perf top для этого процесса: $ cat inotify_stress_test.c #include void main(int argc, char *argv[]) { int ifd = inotify_init(); int wd; for (;;) { wd = inotify_add_watch(ifd, argv[1], IN_ALL_EVENTS); inotify_rm_watch(ifd, wd); } } $ gcc -o inotify_stress_test inotify_stress_test.c $ strace -TT -e inotify_add_watch,inotify_rm_watch ./inotify_stress_test tmp inotify_add_watch(3, "tmp", …) = 1 <0.490447> inotify_rm_watch(3, 1) = 0 <0.000204> inotify_add_watch(3, "tmp", …) = 2 <0.547774> inotify_rm_watch(3, 2) = 0 <0.000015> inotify_add_watch(3, "tmp", …) = 3 <0.466199> inotify_rm_watch(3, 3) = 0 <0.000016> … $ sudo perf top -p 99.71% [kernel] [k] __fsnotify_update_child_dentry_flags … Можно видеть, что почти 100% времени проходит в одном вызове внутри ядра — __fsnotify_update_child_dentry_flags. Наблюдения производились на версии ядра Linux 3.16, для других версий могут быть немного другие результаты. Исходники этой функции можно посмотреть по следующему адресу: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/fs/notify/fsnotify.c?id=v3.16 . Путем добавления отладочных printk или посмотрев на результаты perf достаточно пристально можно увидеть, что проблема происходит в следующем месте:

/* run all of the children of the original inode and fix their
 * d_flags to indicate parental interest (their parent is the
 * original inode) */
spin_lock(&alias->d_lock);
list_for_each_entry(child, &alias->d_subdirs, d_u.d_child) {
    if (!child->d_inode)
        continue;
Для того чтобы начать следить за изменениями в файлах в указанной директории, ядро проходится по структуре dentry, в которой, грубо говоря, содержится кеш вида "filename" => inode data. Этот кеш заполняется даже в случае, когда запрашиваемого файла не существует! В этом случае поле d_inode будет равно нулю, что и проверяется в условии. Таким образом, при вызове inotify_add_watch, ядро проходится по своему (в нашем случае огромному) dentry-кешу для указанной директории и пропускает все элементы, поскольку директория на самом деле пустая. В зависимости от размера этого кеша и от «конкурентности за локи» системный вызов может занимать весьма продолжительное время, блокируя при этом возможность работы с этой директорией и содержащимися внутри файлами. К сожалению, проблема легко не решается и является архитектурной проблемой VFS-слоя и подсистемы dentry. Одним из очевидных и простых решений является наложение ограничений на максимальный размер кеша для несуществующих записей, однако это требует серьезной переделки архитектуры VFS и переписывания большого количества функций, которые рассчитывают на текущее поведение. Наличие счетчиков для кеша несуществующих файлов также наверняка ухудшит производительность подсистемы VFS в целом. Когда мы разобрались в причинах возникновения этой проблемы, то решили не пытаться ее исправить, а обойти: мы больше не создаем файлов с уникальными именами в директориях, за которыми следим с помощью inotify, и тем самым не забиваем dentry cache. Такой способ вполне решает нашу проблему и не создает значительных неудобств.

Проблему с необходимостью делать запросы в базу облака можно было бы решить добавлением имени класса в файл, а вот с остальными все не так радужно. Чтобы сохранить возможность разделять вывод от разных экземпляров одного и того же приложения, не заставляя пользователей использовать наш логгер, можно было бы перенаправлять вывод приложений не в файлы, а в «пайпы» (unix pipes), однако это создает новую проблему — если требуется обновить код прокси (который осуществляет запуск PHP-классов), работа текущих задач может прерваться при попытке записи в «сломанную трубу» (broken pipe).



Это происходит, потому что при рестарте демона все дескрипторы, соответствующие читающей стороне пайпа, закрываются, и при попытке последующей записи в них процессы будут получать SIGPIPE, завершаясь. Кстати говоря, именно на этом механизме основана работа цепочек unix-команд с использованием утилиты head и других: команда cat some_file.txt | head не приводит ни к каким сообщениям об ошибке, потому что после прочтения необходимого количества строк команда head просто выходит, соответствующий pipe «ломается» и процесс cat, продолжающий писать в свой конец «пайпа», получает сигнал SIGPIPE, который просто завершает его исполнение. Если в цепочке было несколько процессов, то эта же ситуация произойдет с каждым элементом цепочки, и все промежуточные приложения благополучно выйдут по сигналу SIGPIPE.

Можно заменить «обычные» unix pipes на «именованные» named pipes, то есть продолжать писать в файлы, только они будут иметь другой тип — named pipes. Однако, чтобы иметь возможность легко переживать падения и рестарт прокси, нужно куда-то класть информацию о соответствии имени файла и id запуска. Одним из таких вариантов является непосредственно имя файла, что возвращает нас к исходной проблеме. Другие варианты заключаются в том, чтобы хранить это в отдельной базе, к примеру, в sqlite или rocksdb, но это кажется слишком громоздким для такой, казалось бы, простой задачи, а заодно добавляет проблемы двухфазного коммита (когда в pipe сообщили новый id запуска, а читающий процесс в это время умер, запись в базе не обновится, и следующая инкарнация читающего процесса будет считать, что id запуска все еще старый).

Решение


Какие свойства должно иметь новое решение?
  1. Устойчивость к перезапуску и падению любых компонентов — прокси, сборщика логов и сервера-приемника.
  2. Если один из классов пишет столько логов, что они не успевают обрабатываться, логи остальных классов все равно должны доставляться за приемлемое время и быть доступны для просмотра разработчиками.
  3. При проблемах с доставкой логов ситуация не должна выходить из-под контроля и должна быть легко исправима вручную (например, не должны создаваться миллионы файлов).
  4. По возможности, система должна быть real-time и иметь большой запас пропускной способности.


Из-за описанных выше проблем с inotify и засорением dentry cache, новая схема должна всегда писать в файлы с одними и теми же именами. В качестве простого и логичного решения представляется писать вывод приложений в файлы вида имя_класса.out.log и периодически их ротировать, называя, к примеру, имя_класса.out.log.old. К сожалению, запись логов от разных инстансов в один и тот же файл требует модификации приложений: если раньше допустимо было делать простое echo, то в новой схеме придется всегда использовать логгер, который добавляет к каждой строке пометку с идентификатором запуска. Использование flock() при одновременной записи также нежелательно, поскольку это сильно снижает производительность и может вызвать ситуацию, когда один «залипший процесс» может заблокировать исполнение всех остальных инстансов этого приложения на текущем сервере. Вместо использования flock() можно просто открывать файл в режиме O_APPEND (флаг a) и писать блоками не более 4 Кб (в Linux), чтобы каждая запись была атомарной.

Таким образом, пункты 1 и 3 мы решили путем простой записи в «файл-на-класс» вместо «файла-на-запуск».

Как собирать логи?


Итак, решение для проблем с inotify, большим числом файлов и устойчивостью к падению прокси мы нашли. Осталось теперь понять, как эти логи собирать. Логичным решением было бы просто оставить scribe или использовать его аналоги, например, syslog-ng и прочие. Однако, по факту, мы и так пишем логи в файлы, поэтому можно было бы вместо этого написать простую «стримилку» содержимого этих файлов на центральный сервер. Схема будет выглядеть следующим образом:



Как можно видеть на рисунке, у нас есть 2 большие подсистемы: сервер-приемник (processor) и сборщики логов на каждой машине (collector).

Общение между приемником и сборщиками осуществляется с помощью постоянно установленного TCP/IP соединения, а для упаковки пакетов используется Google Protocol Buffers. Коллекторы с помощью inotify отслеживают изменения в файлах и отправляют пакеты с новыми строками в приемник. Тот, в свою очередь, присылает обратно полученные им (и успешно записанные в файл с логом) смещения в файлах на исходном сервере.

Приемник периодически (раз в секунду в нашей реализации) сбрасывает новые смещения в отдельный файл в формате JSON в виде списка [{Inode: …, Offset: …}, ...]. Такая схема позволяет быть устойчивой к сбоям сети, но не защищает от сбоев питания и kernel panic на серверах. Эта проблема для нас несущественна, поэтому приемник отсылает подтверждения о записанных данных после успешного вызова write(), не дожидаясь реального сброса данных на диск. При сбоях сети, приемника и сборщика, последние строки могут быть доставлены 2 и более раз, что нас тоже устраивает. Если вам нужна не только гарантированная, но и однократная доставка, вы можете прочитать о намного более сложной системе, которую построил Яндекс: habrahabr.ru/company/yandex/blog/239823/.

«Троттлинг» доставки отдельных классов


Как я уже говорил, нас не устраивало то, что один сильно «флудящий» скрипт мог полностью забить пропускную способность и затормозить обработку всех остальных логов. Такое случалось, поскольку в scribe можно писать намного быстрее, чем будет происходить доставка до приемника, а обработка событий из scribe у нас была однопоточной из-за необходимости соблюдать порядок следования строк в логах хотя бы в пределах одного задания.

Решение этой проблемы достаточно простое: нужно сделать аналог «вытесняющей многозадачности», т.е. за один проход обрабатывать не более N строк в файле, после чего переходить к следующему. Когда все отправленные куски для «нормальных» логов будут получены на сервере, можно вернуться к отправке «жирного файла» и действовать по тому же алгоритму. Таким образом, доставка «большого файла» имеет ограниченное влияние на систему: логи всех оставшихся классов продолжают доставляться с фиксированным опозданием, которое регулируется максимальным размером пачки N. В остальном скорость доставки ничем искусственно не ограничивается — если активная запись идет только в один файл, он будет доставляться с максимально возможной скоростью.



Ротация файлов


Для того, чтобы логи со временем не занимали все место на сервере, необходимо их ротировать. Ротацией логов называется процесс удаления самого старого файла с логом и переименования более свежих файлов в «старые». В нашем случае под ротацией подразумевается удаление старого файла с логом и переименование текущего (class_name.out.log -> class_name.out.log.old). При переименовании файла все процессы, которые держат этот файл открытым, могут продолжать с ним работать, в нашем случае — писать. Поэтому нам нужно продолжать отправлять изменения, произошедшие как в новом, так и в старом файле с логом. У файла при переименовании также сохраняется inode, поэтому в базе мы храним успешно отправленные смещения в файлах именно для inode, а не для имен файлов.

Еще одна небольшая проблема, связанная с ротацией, заключается в том, что перед удалением файла нужно каким-то образом определить, что в него больше никто не пишет. Поскольку все приложения пишут в файлы с использованием флага O_APPEND, не используя flock(), мы можем использовать flock() для какой-нибудь другой цели. В нашем случае приложение перед началом работы берет разделяемую блокировку (LOCK_SH) на файловый дескриптор, в который оно пишет. Чтобы убедиться, что файл больше не используется, нам остается попробовать взять эксклюзивную блокировку (LOCK_EX). Если блокировку удалось получить, значит, файл больше не используется, его можно удалить. В противном случае нам нужно ждать, пока файл с логом освободят, и временно откладывать его ротацию.



Производительность, выводы


Поскольку предыдущая версия сборщика логов работала в один поток и была написана на PHP, сравнение будет не очень честным. Тем не менее, хотелось бы привести результаты и для старой, и для новой архитектуры.

Старая система (PHP, один поток) — 3 МиБ/сек на сервер — вполне достойный результат для PHP.

Новая система (Go, полностью асинхронная и многопоточная) — 100 МиБ/сек на сервер — упирается в сетевую карту и диски.

В результате переделки системы сборки логов мы решили все проблемы, которые у нас с ней были, и получили огромный запас по скорости доставки, а также устойчивость к «флуду» отдельных классов — теперь один скрипт не может замусорить всю систему и вызывать многочасовые задержки в доставке. Также, хотелось бы отметить, что на языке Go задача решается просто и элегантно, с великолепной производительностью конечного решения и низким требованиям к ресурсам.

Ссылки


Open-source реализация сборщика: https://github.com/badoo/thunder/
Другие наши open-source проекты: https://tech.badoo.com/open-source/