Еволюція складання логів «хмари» і збирач логів в open source

Здрастуйте, мене звуть Юрій Насретдинов, я працюю старшим інженером в Badoo. За останні півтора року я зробив кілька доповідей на тему того, як працює наша хмара. Слайди та відео можна подивитися тут і тут.

Сьогодні настав час розповісти про ще однієї частини цієї системи — про збирача логів, який ми разом з цією статтею викладаємо в open-source. Основна частина логіки нашого хмари написана на мові Go, і ця підсистема не є винятком.
Вихідні коди системи: 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);
$read_offset = parseOffset($filename); // "id.out.log.100" -> 100
if ($filesize > $read_offset) {
sendToScribe($filename, $read_offset); // послати в scribe починаючи з $read_offset
rename($filename, replaceOffset($filename, $read_offset); // "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
<?php
for ($i = 0; $i < $argv[1]; $i++) {
file_exists("tmp/file$i");
}
$ php flood.php 10000000


Все, що цей скрипт робить — 10 мільйонів разів виконує stat() або access) на неіснуючі файли виду fileN, де N — число від 0 до 9 999 999.

Тепер виконаємо системний виклик inotify_add_watch (почнемо стежити за змінами в директорії з допомогою inotify):

$ cat inotify_test.c
#include < sys/inotify.h>
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 < sys/inotify.h>
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 <pid>
99.71% [kernel] [k] __fsnotify_update_child_dentry_flags
...


Можна бачити, що майже 100% часу проходить в одному виклику всередині ядра — __fsnotify_update_child_dentry_flags. Спостереження проводилися на версії ядра Linux 3.16, для інших версій можуть бути трохи інші результати. Джерело цієї функції можна подивитися за адресою: 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 their fix
* 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 реалізація складальника: github.com/badoo/thunder
Інші наші open-source проекти: tech.badoo.com/open-source

Юрій youROCK Насретдинов
Lead PHP developer

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.