Сбор и обработка логов. Пример из жизни

Некоторое время назад мне нужно было проанализировать как различные приложения используют один из компонентов системы. Этот компонент (или, скажем , библиотека) предоставляет API из нескольких функций, которые почти никогда не вызываются приложениями напрямую. Вместо этого цепочка вызовов может идёт через довольно пухлого посредника, логика работы которого не до конца понятна и очевидна.

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

Изначальный план был такой:

1. В тестовый вариант библиотеки добавляется код для вывода интересующей нас информации в лог;

2. Подготавливается сборка системы, включающая тестовый вариант библиотеки, и прогоняется через серию тестов, проверяющих совместимость системы с наиболее распространёнными приложениями. При таком тестировании используются оригинальные версии программ, т.е. библиотека будет вызываться из того же кода, что и в «полевых условиях»;

3. Сгенерированные логи затем импортируются в SQL базу и изучаются там по всякому.

В процессе работы собрано (или успешно перепрыгнуто) немало граблей, о которых не подумали в самом начале. Многие из них были связаны с большим объемом информации. Вот список того, что удалось вспомнить:

1. Изначально логи писались в CSV (Comma-Separated Values) формате. Оказалось, что некоторые значение текстовые содержали запятые. Чтобы не городить огород с кавычками формат поменялся на TSV (Tab-Separated Values).

2. Запись в лог замедлила выполнение программ раза в два. Ничего страшного? По идее да, но таймауты по умолчанию в тестовых скриптах этого не знали. К счастью не мы были первыми, общий множитель для таймаутов давно придумали. :-)

3. Суммарный объём данных составил около 80-100GB. Копировать это по сети, да и хранить тоже, не слишком удобно. Поэтому, сгенерированные логи перед отправкой паковались и копировались на выделенный сервер уже в виде одиночного архива.

Выбор архиватора тоже оказался непростой задачей. В результате победил bsdtar. Его ключевыми достоинствами оказались: корректная работа в Win32 окружении, отсутствие смешных ограничений на максимальный размер архива, минимальный набор нужных библиотек, а также умение паковать файлы открытые другими процессами. Интересно, что его, казалось бы, родственник – tar (вернее его Win32 порт) оказался абсолютно непригодным для этой цели. Как впрочем и различный варианты zip.

4. Для импорта логов в SQL базу использовалась утилита bcp.exe (Bulk Copy) завернутая в обвязку из CMD/SQL скриптов. Оказалось, что не смотря на всю временность этой конструкции, делать её однопоточной было ошибкой. Вместо двух с половиной дней (с перерывом на обед :-)), во время которых один процессор трудился не покладая рук, а остальные прохлаждались, снисходительно поглядывая на страдальца, импорт мог бы уложиться в один, а то и пол дня.

5. А вот то, что процесс импорта полностью прерывался при малейшей ошибке оказалось очень кстати, хотя и получилось случайно. Это позволило в лёгкостью восстановиться с места возникновения проблемы, вместо того, чтобы восстанавливать резервную копию базы и начинать все сначала.

6. Генерируемые логи был очень избыточны. Достаточно сказать, что они с легкостью паковались архиватором (gzip) в 20 раз (bzip2 вообще сжимал их в 40-50 раз, но при этом время сжатия было в десятки раз больше). Структура базы была заранее продумана так, что повторяющиеся данные агрегировались во время импорта. В результате финальный размер базы данных составил всего около 5GB, что не могло не сказаться на скорости работы.

На последок добавлю, что мучения не прошли даром. Полученные цифры пригодились и помогли обнаружить несколько новых проблем.