|
|
Еще одной возможностью, которая может помочь при отладке программ, является
встроенный профайлер. Вызов единственного метода в коде программы позволяет
собрать информацию о времени выполнения, количестве вызовов. В log-файле
эта информация представляется в форме, позволяющей оценить узкие места
в программе.
Метод для профилирования кода назван одним символом подчеркивания.
Надеюсь, Вы не называете так свои переменные и это имя не будет конфликтовать
с Вашим кодом. В любом случае, как и методы тестирования, можно вызывать
этот метод как член класса tests.
Любой блок кода, информацию по которому нужно получить, заключается в
вызовы этого метода. Для первого вызова задается единственный параметр -
имя блока, второй вызов без параметров. Лучше сразу заключать весь
код профайлера в директивы условной компиляции. Например:
pascal
(*$define profile*)
//.....................
{$ifdef profile}
_('proc_C_1');
{$endif}
//............................
// Профилируемый участок кода
//............................
{$ifdef profile}
_;
{$endif}
|
Вызовы профайлера лучше писать в одну строку с директивами компиляции.
Так эти вызовы не будут загромождать код и именно поэтому для вызова
выбрано такое короткое имя.
Если нужно получить информацию по всей процедуре, помещаем вызовы
профайлера в начале и в конце процедуры:
pascal
procedure proc_D;
begin
{$ifdef profile} _('proc_D'); {$endif}
sleep(10);
{$ifdef profile} _; {$endif}
end;
|
Кроме времени выполнения всей процедуры можно получить время выполнения
любой части кода этой процедуры. Часто бывает, что возврат из процедуры
выполняется в середине ее кода. Чтобы не просматривать каждый раз код
процедуры при добавлении вызовов профайлера, можно можно использовать
блок try … finally для гарантированного вызова метода в конце процедуры.
Например, в следующем коде для процедуры указаны три профилируемых
участка - вся процедура целиком и две ее части.
pascal
procedure proc_C;
begin
{$ifdef profile}
_('proc_C');
try
{$endif}
{$ifdef profile} _('proc_C_1'); {$endif}
sleep(5);
{$ifdef profile} _; {$endif}
{$ifdef profile} _('proc_C_2'); {$endif}
sleep(20);
{$ifdef profile} _; {$endif}
sleep(10);
{$ifdef profile}
finally
_;
end;
{$endif}
end;
|
Напишем еще несколько процедур, чтобы продемонстрировать возможности
профайлера. Например, пусть процедура B будет рекурсивной и, кроме того,
будет вызывать уже объявленные процедуры C и D:
pascal
procedure proc_B(P:integer);
begin
{$ifdef profile} _('proc_B'); try {$endif}
Sleep(10);
if P = 0
then proc_D
else proc_B(P-1);
proc_C;
{$ifdef profile} finally _; end; {$endif}
end;
|
Процедура A будет вызывать процедуру B, инициализируя рекурсию.
pascal
procedure proc_A;
begin
{$ifdef profile} _('proc_A'); try {$endif}
proc_B(2);
sleep(10);
{$ifdef profile} finally _; end; {$endif}
end;
|
Наконец, главная процедура, будет вызывать процедуру A и дополнительно
процедуру C. Процедура test_Profile; вызывается где-то в коде. В
тестовом примере - это единственный вызов при запуске программы.
pascal
procedure test_Profile;
begin
{$ifdef profile} _('proc_'); try {$endif}
proc_C;
proc_A;
sleep(15);
{$ifdef profile} finally _; end; {$endif}
end;
|
Вызовы процедуры _; это все, что нужно добавить в коде. Теперь выполним
тестовое приложение и заглянем в log-файл. Сразу после информации о всех
других тестах (если они есть) и перед записью об окончании программы,
мы увидим блок, добавленный профайлером:
output
Profiler info: ----------------------------------------------------
count |all time| clear | % |
-------------------------------------------------------------------
0 216,75ms *
1 216,75ms 15,53ms 7,2 |-proc_
1 164,94ms 10,67ms 4,9 |-proc_A
3 154,22ms 32,17ms 14,8 | |-proc_B
3 111,27ms 32,22ms 14,9 | |-proc_C
3 17,54ms 17,54ms 8,1 | | |-proc_C_1
3 61,51ms 61,51ms 28,4 | | |-proc_C_2
1 10,74ms 10,74ms 5,0 | |-proc_D
1 36,18ms 10,74ms 5,0 |-proc_C
1 4,95ms 4,95ms 2,3 |-proc_C_1
1 20,49ms 20,49ms 9,5 |-proc_C_2
|
В правой части таблицы показан стек вызовов. Обратите внимание, что
рекурсивные вызовы свернуты. Это позволяет оценить общее время сразу
всех уровней вложенности и уменьшает размер таблицы. Блоки внутри
процедуры считаются отдельными вызовами (proc_C_1, proc_C_2).
Блоки с одинаковыми именами, но разными местами вызова не объединяются.
Например, различается вызов proc_C из proc_ и из proc_B.
Первая колонка - количество вызовов. Например, proc_B вызывается три раза,
а proc_D - один - только на самом последнем уровне рекурсии.
Вторая колонка - общее время выполнения каждого отслеживаемого блока
с учетом времени вложенных блоков. Например, для proc_/proc_C - из 36ms
proc_C_1 выполнялась 5 ms, proc_C_2 - 20ms, остальное время в
неконтролируемом участке proc_C.
Третья колонка - чистое время выполнения блока без учета вложенных
в него блоков.
Наконец, последняя колонка - процент чистого времени к общему времени
выполнения. (В сумме это время чуть меньше 100% из-за накладных
расходов на вызовы измерений). По этой колонке можно определить узкое место.
В данном случае - это блок proc_C_2 - 28% от общего времени выполнения.
|