понедельник, 28 декабря 2009 г.

Проблемы логирования отладочной информации


Как известно вывод отладочной информации значительно замедляет выполнение программы, особенно если Вам приходиться дампить сложные структуры данных. После завершения этапа тестирования отключают вывод лишней информации, но все же вызовы функций остаются, и они съедают системные ресурсы. Особенно необходимо избегать такого - logger("Message1", Message2", Dumper($mega_structure_ref); Дампер будет вызываться всегда для формирования списка аргументов.
Есть разные варианты решения данной проблемы: использовать Smart::Comments, вставлять условия( logger("debug info") if DEBUG_ON #DEBUG_ON - константа) - эти варианты я сейчас не рассматриваю.
Я рассмотрел 2 варианта:
Вариант 1 (передача ссылки на функцию) 
sub logger(&){}
logger{"Message1", Message2", Dumper($mega_structure_ref)}; 
Таким образом дампер вызовется только во время формирования аргументов для переданной анонимной функции, то есть когда мы точно решим, что нам это необходимо.

Вариант2 (Определяю внутри функции, что мне передали ссылку и дамплю ее):
logger("Message1", Message2", $mega_structure_ref);

Выводы
Преимущества 1-го варианта:
  1. Гибкость.  Он гибче чем 2-й вариант, поскольку позволяет вычислять аргументы, только если мы действительно хотим что-то вывести в лог. А в аргументах могут быть любые операции.
Преимуществ 2-го варианта:
  1. Скорость.  Он быстрее в 6-7 раз по сравнению с 1-м, хотя при логировании константой строки всего в 1.5 раза. Тест на скорость приатачен.
  2. Удобство. Он удобнее, нет необходимости подключать Data::Dumper и прописывать постоянно Dumper(...).
  3. Опциональный дампинг. Позволяет выборочно дампить ссылки. Если мы не хотим дампить структуру, то мы можем заключить ее в двойные кавычки.

Для меня 2-вариант безоговорочно лучший. Он проигрывает только тогда когда нам необходимо в аргументах передать данные, получение которых требуют серьезных затрат ресурсов ( logger("Users online:" . calc_statistics(get_data_from_db)) ) .  Но для решения данной проблемы мы можем попросту разрешить логеру принимать ссылки на функции как один из аргументов  - logger("Users online:" , sub{ calc_statistics(get_data_from_db) } ). Это не так удобно, ква вариант 1, но поскольку такие ситуации возникают очень редко - то это для меня приемлим.

Приложение
Результаты тестов
                      Rate  log_sub log_string log_const_sub log_const_string
log_sub           506414/s       --       -85%          -88%             -92%
log_string       3478006/s     587%         --          -17%             -44%
log_const_sub    4211435/s     732%        21%            --             -32%
log_const_string 6227402/s    1130%        79%           48%               --



Скачать бенчмарк