Главная > Open Source, PHP, СУБД > ezComponents — исследуем компонент EventLog

ezComponents — исследуем компонент EventLog

9 июня 2008

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

Сегодня мы оговорим о логах. Если вы разработчик веб-приложений, то во многих случаях лог поможет вам найти причину узких мест в архитектуре, продублировать критически важные места в приложении, а в ряде приложений без системы лога вообще почти невозможно работать. К примеру, такие он-лайн проекты, как игры (имеется ввиду, браузерные), а также любые системы, связанные с финансами - все они требуют производительных и надёжных реализаций системы логирования всех действий.

Кратко объясню, что я имею ввиду. Возьмём, к примеру, он-лайн игру, в которой пользователь может вводить деньги, например, меняя свои WMZ на игровые единицы, ну, допустим, пиастры. Конечно, все стадии этого процесса обрабатываются вашей системой, деньги зачисляются на счёт пользователя. Но что будет, если в процессе транзакции произойдёт непредвиденная ошибка? Даже если вы используете транзакционный движок и данные так и не попадут в основную систему, потому что транзакция обмена не произойдёт, пользователь будет жаловаться в службу поддержки. Для дублирования этого процесса и бОльшей надёжности, а также для случаев расследования различных инцидентов я предпочитаю вести отдельных лог всех событий, кстати,  не только финансовых. В такой лог логично писать все ключевые операции, которые впоследствии пользователи могут оспорить или эти процессы являются ключевыми для вашего сервиса. Не бойтесь - накладные расходы на лог не такие и большие, особенно в свете текущих цен на сервера и дисковое место это вполне оправданная трата.

Возвращаясь к примеру с обменом валют. В лог я бы писал - метку начала операции, то есть фиксируя намерение пользователя совершить обмен. Далее - сумма и курс обмена, а также прочие моменты. Если возможно - я бы очень рекомендовал записать все возможные переменные запроса (User-Agent, IP и прочее). Это, на самом деле, очень может помочь именно в расследовании инцидентов. Ну и потом каждый промежуточный этап транзакции - даже если финансовая система транзакцию не завершит, у вас в логе останется детальное описание что и как происходило - возможно, это поможет найти ошибку в коде или выявить неполадки в работе сервера.

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

Хочу познакомить вас, уважаемые читатели, с компонентом лога из набора ezComponents. И использовал самую последнюю версию, 2008.1beta 1 и провёл несколько экспериментов для исследования принципа работы этого компонента и его применимости в реальных проектах (как раз стоит задача сделать систему лога для он-лайновой игры).

Сначала поговорим об архитектуре компонента.

  • ezcLog - основной класс, инкапсулирующий всю функциональность лога. Именно с ним вам придётся иметь дело чаще всего. Такой класс в приложении может быть только один (singlton) и он координирует всю работу с сообщениями, позволяя одновременно вести несколько различных видов лога.
  • ezcLogMapper - это класс для задания соответствий логов и сообщений, по сути - тот самый координатор. Если быть точным, это только интерфейс, который должен реализовать ваш класс для того, чтобы работать с сообщениями в логе и управлять ими.
  • ezcLogFilterSet - это уже практическая реализация интерфейса ezcLogMapper, при этом допускается использовать целую цепочку фильтров, которые последовательно применяются к входящему  сообщению. Когда срабатывает первый фильтр, условиям которого удовлетворяет сообщение, обработка останавливается, и фильтр направляет сообщение в указанный лог. Таким образом можно строить единую цепочку обработки любых сообщений, гибко разграничивая различные уровни лога, ведя, к примеру, одновременно основной лог, лог ошибок, лог неудачных транзакций и лог всех транзакций на сумму, больше 100 USD. Как отлично замечено в документации, это аналогично правилам в почтовом клиенте, где точно так же работают фильтры для входящих сообщений, раскидывая их по папкам.
  • ezcLogWriter - это интерфейс для реализации системы хранения сообщений лога. Именно сюда, в конечном итоге, направляется сообщение и здесь оно приводится к тому виду, в котором и записывается в систему хранения. Это может быть и файл, и системный лог и даже база данных. Кстати, в определённых случаях может быть полезным создание промежуточного буфера в оперативной памяти и запись лога туда, а потом сброс на диск. Для реализации хранения лога в базе данных применяется отдельный класс -  EventLogDatabaseTiein. Сегодня нас интересует только файловый лог. По умолчанию, в дистрибутиве есть три предопределённых вида стораджей лога:
    • ezcLogUnixFileWriter - записывает сообщение в логе в виде формата, принятом в Unix-like операционных системах.
    • ezcLogSyslogWriter - записывает сообщения в системный лог-файл.
    • ezcLogDatabaseWriter - предоставляет интерфейс для записи сообщений в базу данных.

В общих чертах вот такая архитектура системы лога в ezComponents. Конечно, там несколько больше внутренних классов и отношений, но это вам будет нужно только в случае написания собственного лога или некоторых его частей. Вы можете самостоятельно наследовать и реализовывать собственные системы хранения лога (это очень просто, и в примерах есть код, достаточно создать класс и реализовать всего несколько методов), реализовать свою систему роутинга сообщений по необходимым вам правилам, а также изменить стандартный текстовый формат лога на любой необходимый (например, XML или даже сразу форматированный HTML).

Следует отметить ещё несколько возможностей компонента. Как вы понимаете, в лог пишется огромное количество информации, причём, она пишется постоянно. Поэтому в компоненте предусмотрена такая функциональность, как Log rotation - обновление лога или ротация. При достижении некоторого заданного объёма, файл лога переименовывается и начинается следующий. Количество таких логовых файлов также ограничено (это можно задать в настройках, так же как и размер файла до срабатывания ротации), а при его переполнении - будут затираться самые старые записи. Поэтому если вам очень критично хранение всех записей - возможно следует или регулярно архивировать логи или же переписать класс ezcLogWriter так, чтобы лог хранился всегда и ничего не удалялось.

Теперь мы подошли к практической части статьи. Давайте напишем простейшую систему лога. Это выглядит примерно следующим образом:

1 // получаем объект лога
2 $log = ezcLog::getInstance();
3
4 //получаем объект маппера для роута наших сообщений
5 $mapper = $log->getMapper();
6
7 // определяем метод хранения сообщений.
8 // Этот момент будет далее описан детальнее
9 $writer = new ezcLogUnixFileWriter( "/tmp/logs/testezc", "default.log", 1024, 6);
10
11 // создаем фильтр
12 $filter = new ezcLogFilter();
13
14 //создаем правило, которое просто передает сообщение в лог
15 $rule = new ezcLogFilterRule( $filter, $writer, true );
16
17 // применяем правило роута сообщений к мапперу
18 $mapper->appendRule( $rule );
19
20 //непосредственно сообщение в лог
21 $log->log( 'Тестовое сообщение.', ezcLog::INFO );

В принципе, здесь все достаточно ясно. В результате, в файле будет записано следующее сообщение:

Jun 09 11:59:34 [Info] [default] [default] Тестовое сообщение

Кстати, по умолчанию, все сообщения имеют четыре характеристики, которые также пишутся в лог. Первой, конечно, идёт полная дата сообщения и время. Далее есть три характеристики:

  • severity - по сути, "вес" или уровень сообщения.
  • source - источник сообщения
  • category - категория сообщения

Исходя из этих данных класс роута (ezcMapper) и фильтры принимают решение, куда направить то или иное сообщение. Кстати, совсем не обязательно задавать именно такие характеристики, вы можете заменить их на произвольные собственные, например: UserID, TransactId и Amount для нашего примера с финансовым логом. Передавать эти данные можно вместе с сообщением, в виде ассоциативного массива. Соответственно, если эти данные определены, они будут использованы для перенаправления сообщения в подходящий лог. При этом заметьте, что первый параметр, severity, должен быть в любом случае целым числом (int), остальные могут быть произвольными строковыми параметрами.

Далее давайте рассмотрим сам код инициализации файла лога. Конструктор класса ezcLogFileWriter (и любого наследника, реализующего конкретный вид лога) принимает четыре параметра:

  • $logDirectory - путь к директории, где будут храниться файлы лога. Путь должен существовать и быть доступным для записи.
  • $defaultFile - имя файла, в который будет писаться лог. По умолчанию, это "default.log". При этом файлы журнала будут иметь расширение состоящие из цифр-идентификаторов сегмента (1,2...N).
  • $maxLogRotationSize - задаёт максимальный размер файла лога. Если он превышен - включается механизм ротации и создаётся новый лог. Если установить значение в false - ротация будет отключена и все будет записываться в один файл. Кстати, нигде в документации так и нет упоминания, в каких единицах задаётся размер файла, пока самым реальным кажется размер в байтах. Это можно установить, только исследуя  исходники классов. И там мы столкнёмся со следующей сложностью. На 32-битных платформах ваш лог не может быть больше 2-х Гб, иначе используемая функция filesize для определения размера лога будет возвращать неверные значения. Имейте это ввиду, работая с большими логами, особенно без ротации.
  • $maxLogFiles - количество файлов лога в системе ротации (сегментов лога). После того, как будет исчерпано их максимальное количество, самые старые сегменты будут стёрты и перезаписаны новыми.

Из описания следует следующая логика для определения размера лога и его работы. Общий размер лога - $maxLogRotationSize (размер одного сегмента в байтах) * $maxLogFiles (количество сегментов). Кстати, по умолчанию, размер одного сегмента равен 200 Кб, а количество их - 3, итого 600 Кб. При этом мы ожидаем, что при работе в реальной среде, где параллельно работают несколько пользователей (запрашивают страницы), в один и тот же лог и его сегмент будет записываться все в порядке поступления информации. А когда первый сегмент заполнится, включиться механизм ротации и мы, в результате, будем иметь несколько файлов фиксированного размера (сегменты по $maxLogRotationSize) и один текущий переменного размера, меньше, чем $maxLogRotationSize.

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

Но в упрощённом тесте, когда я просто обновлял страницу в браузере, все вроде работало. Но работало следующим образом. Основной лог пишется всегда в один и тот же файл - задаваемый при создании лога дефолтный файл (в нашем случае - defaults.log), а при его переполнении - часть  данных будет переносится в другие сегменты лога, начиная с самого младшего номера и выше. А вот само задание размера как то не так работает - при задании в байтах размера в 1 Кб, все файлы имеют свой размер в 1860 байт, но как это соотносится с системой определения и РНР-функциями для определения размера я пока не смог опознать. И иногда срабатывают исключения ввода/вывода, сообщающие про недоступность файла лога или его сегмента.

Ну да ладно, в принципе, как то он работет и при желании и настройке под свой проект вполне будет надёжным помощником. Кстати, я попробовал написать свою реализацию формата сохранения - просто используя дамп переменной, и это оказалось в два раза быстрее стандартных компонент. Поэтому, если вам критична скорость, придётся отказаться от всяких промежуточных стадий обработки и максимально упростить формат записи. Хотя я измерял производительность на одиночном скрипте, записывая в один и тот же лог множество сообщений, при его размере в несколько десятков мегабайт время записи было более-менее одинаковое, у меня составило примерно 5 сек. на 15 тысяч сообщений в цикле. Однако в интенсивной среде со многими параллельными пользователями я предвижу проблемы логов, основанных на файлах, в таких случаях лучше всего применять базу данных. Например, можно переопределить собственный LogWriter, но не использовать встроенный функционал записи в базу данных, а написать свою реализацию, использующую, к примеру, SQLite или Firebird базы, то есть, использовать совершенно отдельную базу для лога. Стандартный же компонент влечёт за собой использование и стандартного слоя абстракции для доступа к базе, что для лога, мне кажется, является не оптимальным усложнением и уменьшением скорости доступа.

В целом для большинства случаев применения стандартного компонента будет достаточно. Если у вас нет большого потока данных в лог, и вы не заинтересованы в хранении полной истории за недели и месяцы, то даже стандартные механизмы вас полностью устроят. Конечно, для подгонки под проект придётся поэкспериментировать с настройками, но в результате у вас будет надёжная и мощная система - поверьте, лучше иметь лог, пусть и ценой некоторых системных ресурсов, чем потом долго и сложно разбираться с неудовлетворёнными пользователями.

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

Для высоконагруженых проектов, где предполагается, что количество сообщений в лог будет велико, можно смотреть в сторону хранения сообщений в базе данных, при этом лучше всего немного поднапрячься и написать собственный механизм хранения, при этом вполне логично и оправданно использовать независимую базу данных, даже другой архитектуры. Так как у вас будет большой поток запросов на запись, логичнее всего использовать оптимизированные для этого базы данных, которые поддерживают транзакционность, при этом не теряя в производительности. Я бы рекомендовал обратить внимание, в случае сложных логов и больших требований к надёжности, на Firebird.

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

  1. 12 июня 2008 в 09:47 | #1

    Хорошая информация! Приняла к сведению схему лога! Не знала! Спасибо!

  2. 24 июля 2008 в 18:19 | #2

    Да, спасибо автор

Комментирование отключено.
Developers.org.ua