5. Анализ производительности программ

В этом разделе рассматриваются инструменты для анализа производительности кода на платформе «Эльбрус».

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

  • с точностью до процедуры;
  • с точностью до линейных участков;
  • с точностью до отдельных команд;
  • с точностью до состояния конвейера при исполнении отдельных команд.

Профиль можно получать с помощью:

  • симулятора / модели процессора;
  • инструментирующих профилировщиков:
  • сэмплинговых профилировщиков:

Рассмотрим две утилиты для сбора сэмплов в ОС «Эльбрус Линукс»:

  • dprof (разработан в АО «МЦСТ»);
  • perf (поддержана утилита и подсистема в ядре ОС).

Сэмпл - информация о состоянии программы в момент регулярно-случайной остановки. Минимальная информация в сэмпле - IP адрес текущей команды.

Профилировщик dprof запускает программу в качестве ptrace-наблюдаемой и перехватывает прерывания для сбора/сброса сэмпла. При этом каждое прерывание приводит к смене контекста «программа»/dprof для того, чтобы dprof сбросил сэмпл. Профилировщик perf имеет поддержку в ядре ОС, и смены контекста в этом случае не происходит - сбор и сброс сэмпла выполняются при обработке прерывания в ядре ОС.

Рассмотрим примеры использования профилировщиков. В обзоре будут представлены не все возможности, а лишь активно используемые на платформе Эльбрус для сбора информации о потреблении ресурсов.

5.1. Утилита perf

Для записи сэмплов надо использовать команду:

perf record

Следом за ней указывается тип события, по которому будет происходить сбор. Оптимальным для платформы Эльбрус является тип task-clock. Потом через параметр -F указывается необходимая частота срабатывания: сколько раз в секунду программа останавливается для сбора информации о выполняемой функции. Рекомендации по выбору числа для -F могут быть следующими:

  • при времени выполнения программы несколько минут и более: -F10 -F100
  • при выполнении программы менее одной минуты: -F1000
  • при выполнении программы менее одной секунды: -F10000.

Так можно собрать сэмплы для программы a.O3:

perf record -e task-clock -F10000 ./a.O3

Выдача:

[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.340 MB perf.data (8818 samples)

Стоит следить за тем, чтобы количество собранных сэмплов не было слишком маленьким.

Чтобы посмотреть собранный профиль, необходимо выполнить команду:

perf report

Профиль имеет вид:

Samples: 8K of event 'task-clock', Event count (approx.): 881800000
Overhead       Samples  Command  Shared Object      Symbol
99,65%          8787 a.O3     a.O3               [.] sample
0,09%             8  a.O3     a.O3               [.] main
0,02%             2  a.O3     [kernel.kallsyms]  [k] page_add_file_rmap
0,02%             2  a.O3     [kernel.kallsyms]  [k] release_pages
0,02%             2  a.O3     [kernel.kallsyms]  [k] zap_pte_range
0,01%             1  a.O3     [kernel.kallsyms]  [k] __flush_icache_pag

Два раза нажимая Enter на имени конкретной функции, мы можем посмотреть дизассемблер. Для возврата к профилю нужно нажать “q”. В данном примере видно, что дольше всех работает функция sample, соответственно ее и стоит анализировать для повышения производительности.

5.2. Утилита dprof

Рассмотрим профилировщик dprof.

dprof -o IP_raw ${exe} params...

В файле IP_raw будет находиться список адресов Instruction Pointer-ов (IP), полученный с интервалами 10ms. Частоту можно менять опцией -d.

[14684] 0000455555786910
[14684] 0000000000036d38
[14684] 000000000007c968

По опции -b можно сбрасывать не только IP, но и весь стек адресов возврата. Это позволит в дальнейшем получить профиль с учетом графа вызовов.

[14716] 0000000000011400
[14716] DPROF-BACKTRACE EVENT timer:10 (depth=12): 0000000000011400 0000000000063898 0000000000038d00 0000000000039258 000000000003b778 000000000002faa8 0000000000030f80 0000000000071298 0000000000070100 000045555560e758
[14716] 0000000000059408
[14716] DPROF-BACKTRACE EVENT timer:10 (depth=9):  0000000000059408 000000000003b818 000000000002faa8 0000000000030f80 0000000000071298 0000000000070100 000045555560e758

Для получения текстового профиля из IP_raw можно использовать команды:

dprof2ptrace.sh IP_raw >${exe}.ptrace
ldis -P ${exe}

Пример вывода от команд выше:

.symtab:
%time      %summ      time    calls  time/call  name
25.81%     25.81%       24        1       24    mrglist
12.90%     38.71%       12        1       12    addlist
6.45%     45.16%        6        1        6    getefflibs
3.23%     48.39%        3        1        3    lupdate

Для визуализации профиля с использованием информации о графе вызовов можно использовать формат callgrind/cachegrind:

dprof2callgrind.sh ${exe} IP_raw >callgrind.out

С помощью сэмплинговых профилировщиков можно получать доступ к информации о блокировках и их причинах.

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

Примеры:

  • TICKS – все такты
  • EXEC – исполненные команды
  • BUB_B – блокировки конвейера на стадии B
  • BUB_E2 – блокировки конвейера на стадии E2
  • IB_NO_COMMAND – блокировки конвейера на стадии подкачки кода
  • L2_QUERY – запросы в L2$
  • L2_HIT – попадания в L2$

Для сбора профиля по событиям нужно задать событие и частоту выработки прерываний SAV (Sample After Value):

dprof -o IP_raw_exec -e EXEC:10000000  ${exe} params...

Прерывания будут вырабатываться аппаратурой через каждые 10^7 выполненных команд.

Можно задать до 4 событий одновременно, каждое из них будет вырабатывать прерывания с собственным отличительным маркером.

Рассмотрим пример работы программы bc, которая вычисляет математическое выражение.

hostname /export/minis/Dprof # time -p echo 2^218839%2 | bc

0
real 1.00
user 1.00
sys 0.00

Для удобства числа подобраны так, чтобы время выполнения равнялось одной секунде. Так как машина, на которой выполняется выражение, работает с тактовой частотой 1200MHz, это значит, что за одну секунду будет выполнено миллиард двести миллионов тактов, часть из которых пойдет на полезные вычисления, часть на задержки.

Рассмотрим профиль выполнения примера:

echo 2^218839%2 | dprof -o IP_raw -b -f /usr/bin/bc

-- child 9530 attached
0
-- child 9530 exited with code

dprof2ptrace.sh IP_raw >bc.ptrace
cp /usr/bin/bc .
ldis -P ./bc
./bc:

.symtab:
%time      %summ      time    calls  time/call  name
46.00%     46.00%       46        1       46    _bc_simp_mul
37.00%     83.00%       37        1       37    _bc_shift_addsub
 7.00%     90.00%        7        1        7    (*) external unknown
 4.00%     94.00%        4        1        4    _bc_do_sub
 2.00%     96.00%        2        1        2    _bc_rec_mul
 1.00%     97.00%        1        1        1    bc_new_num
 1.00%     98.00%        1        1        1    bc_free_num
 1.00%     99.00%        1        1        1    free@plt
 1.00%    100.00%        1        1        1    memset@plt

Если мы сравним этот профиль с полученным командой perf:

45,73%          4749  bc       bc                 [.] _bc_shift_addsub
42,43%          4407  bc       bc                 [.] _bc_simp_mul
 3,76%           390  bc       bc                 [.] _bc_do_sub
 1,65%           171  bc       bc                 [.] _bc_rec_mul
 1,45%           151  bc       libc-2.29.so       [.] cfree@GLIBC_2.2
 1,15%           119  bc       bc                 [.] bc_free_num
 0,87%            90  bc       libc-2.29.so       [.] malloc
 0,51%            53  bc       libc-2.29.so       [.] memset

то видим, что профили различаются, но не существенно. Две самые тяжелые функции в обоих профилировщиках одни и те же.

Посмотрим, сколько тактов ушло на различные события при выполнении примера. Узнаем общее количество потраченных тактов:

echo 2^218839%2 | /opt/mcst/bin/dprof -m TICKS /usr/bin/bc

-- child 9566 attached
0
-- child 9566 exited with code 0
[9566] event TICKS (2): 1195620487

Рассмотрим, какую долю этих тактов выполнялся код:

echo 2^218839%2 | /opt/mcst/bin/dprof -m EXEC /usr/bin/bc

-- child 9569 attached
0
-- child 9569 exited with code 0
[9569] event EXEC (2): 82864377

Т.е. 1195620487 - 828643773 = 366976714 тактов потрачено на обслуживание вычислений – отсутствие кода и другие задержки.

Рассмотрим другие счётчики. На отсутствие команд пришлось порядка 5 миллионов тактов.

echo 2^218839%2 | /opt/mcst/bin/dprof -m IB_NO_COMMAND /usr/bin/bc

-- child 9582 attached
0
-- child 9582 exited with code 0
[9582] event IB_NO_COMMAND (2): 5252756

На задержки от BUB_E2 ушло порядка 55 миллионов тактов:

echo 2^218839%2 | /opt/mcst/bin/dprof -m BUB_E2 /usr/bin/bc

-- child 9588 attached
0
-- child 9588 exited with code 0
[9588] event BUB_E2 (2): 55073991

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

dprof -mlist

5.3. Функции gcc

Компилятор gcc предоставляет опцию -gline, которая позволяет получить информацию о ходе выполнения программы.

Пример:

! function 'sample', entry = 68, value = 0x0105a0, size = 0x228, sect = ELF_TEXT num = 13
0000<0000000105a0> sample:
                    addd,1 0x14, 0x0, %dg16                   ! t.c : 18
                    addd,2 0x0, 0x0, %dg17                    ! t.c : 18
                    addd,3 0x0, _f64,_lts2 0xbf847ae147ae147b, %dr7 ! t.c : 18
                    scld,4 0x5, 0x5, %dr12                    ! t.c : 14
                    return %ctpr3                             ! t.c : 14
                    setwd wsz = 0x7, nfx = 0x1, dbl = 0x0

0001<0000000105d0> :
                    addd,0 %dr0, _f16s,_lts1lo 0x80, %dr11    ! t.c : 18
                    addd,1 %dr0, _f16s,_lts1hi 0x60, %dr10    ! t.c : 18
                    addd,2 %dr0, _f32s,_lts2 0x40, %dr9       ! t.c : 18
                    addd,3 %dr0, _f32s,_lts3 0x20, %dr8       ! t.c : 18
                    disp %ctpr1, M_106b0                      ! t.c : 14
                    setwd wsz = 0x18, nfx = 0x1, dbl = 0x0
                    setbn rsz = 0x10, rbs = 0x7, rcur = 0x0

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