Caché: профилируем программу

Для профилирования программы в Cache' версии 5.0.4 появилась утилита ^%MONLBL. Эта утилита предоставляет интерфейс к механизму сбора статистики выполнения программ. Для ее использования следует

• запустить утилиту профилирования
• выполнить профилируемый код
• остановить профилирование и вывести результаты

Запуск утилиты.

Следует в терминале выполнить вызов

USER>d ^%MONLBL

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

После ввода имен рутин монитор запрашивает список статистик, которые он должен собрать. Выбор альтернативы 3 показывает полный список статистик, которые может собрать монитор. Это

1.) GloRef: global refs
2.) GloSet: global sets
3.) GloKill: global kills
4.) DirBlkRd: directory block reads
5.) UpntBlkRd: upper pointer block reads
6.) BpntBlkRd: bottom pointer block reads
7.) DataBlkRd: data block reads
8.) RouBlkRd: routine block reads
9.) MapBlkRd: map block reads
10.) OthBlkRd: other block reads
11.) DirBlkWt: directory block writes
12.) UpntBlkWt: upper pointer block writes
13.) BpntBlkWt: bottom pointer block write
14.) DataBlkWt: data block writes
15.) RouBlkWt: routine block writes
16.) MapBlkWt: map block writes
17.) OthBlkWt: other block writes
18.) DirBlkBuf: directory block requests satisfied from a global
19.) UpntBlkBuf: upper pointer block requests satisfied from
       a global buffer
20.) BpntBlkBuf: bottom pointer block requests satisfied from
       a global buffer
21.) DataBlkBuf: data block requests satisfied from a 
       global buffer
22.) RouBlkBuf: routine block requests satisfied from a 
       global buffer
23.) MapBlkBuf: map block requests satisfied from a 
       global buffer
24.) OthBlkBuf: other block requests satisfied from a 
       global buffer
25.) JrnEntry: journal entries
26.) BlkAlloc: blocks allocated
27.) NetGloRef: network global refs
28.) NetGloSet: network set s
29.) NetGloKill: network kills
30.) NetReqSent: network requests sent
31.) NCacheHit: network cache hits
32.) NCacheMiss: network cache misses
33.) NetLock: network locks
34.) RtnLine: M commands
35.) RtnLoad: routine loads
36.) RtnFetch: routine fetches
37.) LockCom: lock commands
38.) LockSucc: successful lock commands
39.) LockFail: failed lock commands
40.) TermRead: terminal reads
41.) TermWrite: terminal writes
42.) TermChRd: terminal read chars
43.) TermChWrt: terminal write chars
44.) SeqRead: sequential reads
45.) SeqWrt: sequential writes
46.) IJCMsgRd: local IJC messages read
47.) IJCMsgWt: local IJC messages written
48.) IJCNetMsg: network IJC messages written
49.) Retransmit: network retransmits
50.) BuffSent: network buffers sent
51.) Time: elapsed time on wall clock
52.) TotalTime: total time used (including sub-routines)

Список довольно объемный и позволяет отследить множество нюансов работы программы. Выберем статистики 34, 51 и 52. Для демонстрации сделаем небольшую рутину следующего содержания:

rtn1 ; проверяем профилирование кода
 q
func1(val=12)
 n i
 f i=1:1:val d
 . w "i = ",i,", i^2 = ",i*i,!
 . w " fact(",i,") = ",$$fact(i),!
 q
fact(n)
 q:n=0 1
 q:n=1 1
 q n*$$fact(n-1)

Здесь просто демонстрируем некоторое выполнение с циклом и вызовом функции.
После ввода номеров статистик монитор запрашивает идентификаторы процессов, за которыми он должен следить.

Select which PID(s) to monitor
  1.) Monitor All PIDs
  2.) Monitor Current Process Only
  3.) Enter list of PIDs

В нашем случае оставим вторую альтернативу. После запуска монитора мы может его остановить, приостановить и в приостановленном состоянии продолжить, очистить все счетчики и вывести накопленную статистику. Выполним нашу программу. Для выхода из утилиты монитора просто нажать enter. Сам монитор будет продолжать работать и вернуться к управлению им можно, снова вызвав d ^%MONLBL.

Выполнение профилируемого кода.

Выполним нашу профилируемую программу.

USER>d func1^rtn1()
i = 1, i^2 = 1
 fact(1) = 1
i = 2, i^2 = 4
 fact(2) = 2
i = 3, i^2 = 9
 fact(3) = 6
i = 4, i^2 = 16
 fact(4) = 24
i = 5, i^2 = 25
 fact(5) = 120
i = 6, i^2 = 36
 fact(6) = 720
i = 7, i^2 = 49
 fact(7) = 5040
i = 8, i^2 = 64
 fact(8) = 40320
i = 9, i^2 = 81
 fact(9) = 362880
i = 10, i^2 = 100
 fact(10) = 3628800
i = 11, i^2 = 121
 fact(11) = 39916800
i = 12, i^2 = 144
 fact(12) = 479001600

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

Получение результатов профилирования.

Выполнив нашу функцию, снова обратимся к монитору статистики.

d ^%MONLBL

Получить текущие значения статистики можно, выбрав пункт

6.) Report LBL Statistics

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

Enter the number of your choice: 6
1.) rtn1
Routine (Enter for all rtns):
FileName: c:\temp\rtn1stat.txt

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

Routine ^rtn1 ...

Line RtnLine    Time  TotalTime
1        0   0          0        rtn1
2        0   0          0         q
3        1   0.000035   0.000035 func1(val=12)
4        1   0.000005   0.000005  n i
5        1   0.000046   0.000046  f i=1:1:val d
6       12   0.000080   0.000080  . w "i = ",i,", i^2 = ",i*i,!
7       12   0.002149   0.003409  . w " fact(",i,") = ",$$fact(i),!
8        1   0.000009   0.000009  q
9       78   0.000196   0.000196 fact(n)
10      78   0.000222   0.000222  q:n=0 1
11      78   0.000219   0.000219  q:n=1 1
12      66   0.000580   0.005054  q n*$$fact(n-1)

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

В нашем случае долго выполнялись строки, содержащие вызовы $$fact. Видно, что вызов функции для интерпретатора оказался тяжелой операцией.

Наличие такого монитора и его могучая функциональность мне нравятся и, на мой взгляд, версия Caché с монитором и отладчиком становится весьма серьезным инструментом программиста.