Замер производительности малой кровью

— Что ты пишешь? — спросили программиста.
— Сейчас запустим — узнаем! — ответил программист.

Задача повышения производительности стояла и стоит перед нами (разработчиками) всегда. Не только в процессе написания свежего кода, но и месяцы (годы) спустя — когда нагрузка на систему естественным образом возрастает. Или неестественно — в тяжелые предновогодние дни, когда графики всех показателей похожи на карпатские горы. А особенно критичные — напоминают пик Эверест.

В общем, такие вещи надо мониторить, желательно — автоматически и постоянно, с извещениями о том, что на каком-то фронте (процессе) происходят невиданные доселе вещи — например, учет документа стал занимать 5 минут вместо 5 секунд.

Для этих целей был написан спец.инструмент — я бы даже назвал его мини-фреймворком :) Идея почерпнута из аспектно-ориентированного программирования.

По-простому говоря, очередной лог производительности, до безобразия простой в использовании:

1. Имеется таблица Log, куда отписываются события трех видов — CheckPoint, Start и Finish.
   • Checkpoint — идет фиксация прохождения некой контрольной точки.
   • Start — начало процесса (например, начало выполнения функции).
   • Finish — окончание процесса (выход из функции).
   • На каждую функцию может быть только один Start и несколько Finish’ей — один в конце и один перед каждым EXIT’ом.
   • Допускается вложенность процессов — т.е., если внутри одной функции идет вызов другой — это необходимо отражать в логе. При этом есть т.н. «уровень вложенности процессов», который при каждой открывающей скобке (Start) ныряет на единичку вглубь, а при каждой закрывающей скобке (Finish) выныривает обратно.
   • Если за стартом сразу идет финиш — то две строки в логе только запутывают. Такая конструкция схлопывается в одну строчку со временем начала и окончания и ей присваивается тип Execution.
   • В логе фиксируется:
     1. Тип события.
     2. Пользователь.
     3. Дата и время события.
     4. Дата-время начала и окончания процесса (для типа Start).
     5. Длительность процесса (в миллисекундах).
     6. Затраты на запись в лог (в миллисекундах), для того, чтобы иметь адекватную картину производительности.
     7. Сессия и хост.
2. Имеется singleinstance-кодеюнит со следующими функциями:
   • Start (txtMessage) — отписывает в лог новое событие — начало процесса.
   • Finish (txtMesage) — закрывает скобку начала процесса, при этом ищется предыдущая открытая скобка с таким же сообщением (т.е. лучше, чтобы они были уникальными, но не обязательно). Рекурсия в данной версии не обрабатывается.
   • Checkpoint (txtMessage) — отписывает в лог новое событие — прохождение контрольной точки.
3. Имеется форма для анализа лога, в которой с помощью Indentation показана вложенность процессов.

Какие бонусы мы получаем при запуске такого протоколирования:

1. Сразу видим тормозящие процессы.
2. Видим вложенность вызовов функций, а в больших проектах она  не всегда очевидна, учитывая огромное количество кода на Validate’ах и т.п. Я в первый день «промышленной эксплуатации» нашел процесс, в котором 3 (три) раза подряд вызывается одна и та же функция.
3. Можем оценить результат оптимизации, сравнив время выполнения процесса до и после, прям как на фотках рекламы средств для похудения.

Сам процесс внедрения такого логгирования крайне прост — обертываем в скобки «Старт-Финиш» все критичные процессы, перезапускаем систему, наливаем кофе и следим за логом. Каждый найдет для себя массу интересного :)

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

Текущая версия — 0.5, скачать можно здесь — «Productivity Logger (RU)».

Замечания, здоровая критика и прочая — приветствуются :) Пишите на mailbox@naviart.ru

Инджой!