Книга: Программирование для Linux. Профессиональный подход

А.3.3. Отображение профильных данных

А.3.3. Отображение профильных данных

Получив имя исполняемого файла, утилита gprof проверяет файл gmon.out и отображает информацию о том, сколько времени заняло выполнение каждой функции. Давайте проанализируем ход выполнения операции 1787 ? 13 - 1918 в нашей программе-калькуляторе, создав простой профиль.

Flat profile:
Each sample counts as 0.01 seconds.
% cumulative    self            self    total
time seconds seconds    calls ms/call ms/call name
26.07   1.76    1.76 20795463    0.00    0.00 decrement_number
24.44   3.41    1.65     1787    0.92    1.72 add
19.85   4.75    1.34 62413059    0.00    0.00 zerop
15.11   5.77    1.02     1792    0.57    2.05 destroy_number
14.37   6.74    0.97 20795463    0.00    0.00 add_one
 0.15   6.75    0.01     1788    0.01    0.01 copy_number
 0.00   6.75    0.00     1792    0.00    0.00 make_zero
 0.00   6.75    0.00       11    0.00    0.00 empty_stack

Вычисление функции decrement_number() и всех вызываемых в ней функций заняло 26,07% общего времени выполнения программы. Эта функция вызывалась 20795463 раза. Каждый вызов выполнялся 0,00 с, т.е. столь малое время, что его не удалось замерить. Функция add() вызывалась 1787 раз, очевидно для вычисления произведения. Каждый проход по функции занимал 0,92 секунды. Функция copy_number() вызывалась почти столько же раз — 1788, но на ее выполнение ушло всего 0.15% общего времени работы программы. Иногда в отчете присутствуют функции mcount() и profil(), используемые профайлером.

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

index % time  self children called name
                                      <spontaneous>
[1]     100.0 0.00 6.75              main [1]
              0.00 6.75     2/2       apply_binary_function [2]
              0.00 0.00     1/1792    destroy_number [4]
              0.00 0.00     1/1       number_to_unsigned_int [10]
              0.00 0.00     3/3       string_to_number [12]
              0.00 0.00     3/5       push_stack [16]
              0.00 0.00     1/1       create_stack [16]
              0.00 0.00     1/11      empty_stack [14]
              0.00 0.00     1/5       pop_stack [15]
              0.00 0.00     1/1       clear_stack [17]
--------------------------------------
              0.00 6.75     2/2       main [1]
[2]     100.0 0.00 6.75     2        apply_binary_function [2]
              0.00 6.74     1/1       product [3)
              0.00 0.01     4/1792    destroy_number [4]
              0.00 0.00     1/1       subtract [11]
              0.00 0.00     4/11      empty_stack [14]
              0.00 0.00     4/5       pop_stack [15]
              0.00 0.00     2/5       push_stack [16]
--------------------------------------
              0.00 6.74     1/1       apply_binary_function [2]
[3]      99.6 0.00 6.74     1        product [3]
              1.02 2.65 1767/1792     destroy_number [4]
              1.65 1.43 1767/1767     add [5]
              0.00 0.00 1760/62413059 zerop [7]
              0.00 0.00    1/1792     make_zero [13]

В первой секции сообщается о том, что на выполнение функции main() и всех ее дочерних функций ушло 100% времени (6.75 секунд). Функцию main() вызвал некто <spontaneous>: это означает, что профайлер не смог определить, как был осуществлен вызов. В функции main() дважды вызывалась функция apply_binary_function() (всего таких вызовов в программе было тоже два). В третьей секции сообщается о том, что выполнение функции product() и ее дочерних функций заняло 98% времени. Эта функция вызывалась только один раз из функции apply_binary_function().

По схеме вызовов несложно определить время работы той или иной функции. Однако рекурсивные функции требуют особого подхода. Например, функция even() вызывает функцию odd(), а та — снова функцию even(). Самому длинному из таких циклов присваивается номер и выделяется отдельная секция отчета. Следующий фрагмент профильных данных получен в результате проверки того, является ли результат операции 1787 ? 13 ? 3 четным:

--------------------------------------
              0.00 0.02    1/1        main [1]
[9]       0.1 0.00 0.02    1         apply_unary_function [9]
              0.01 0.00    1/1        even <cycle 1> [13]
              0.00 0.00    1/1806     destroy_number [5]
              0.00 0.00    1/13       empty_stack [17]
              0.00 0.00    1/6        pop_stack [16]
              0.00 0.00    1/6        push_stack [19]
--------------------------------------
[10]       0.1 0.01 0.00   1+69993   <cycle 1 as a whole> [10]
               0.00 0.00 34647        even <cycle 1> [13]
--------------------------------------
                         34847        even <cycle 1> [13]
[11]       0.1 0.01 0.00 34847       odd <cycle 1> [11]
               0.00 0.00 34847/186997954 zerop [7]
               0.00 0.00   1/1806     make_zero [16]
                         34846        even <cycle 1> [13]

Выражение 1+69693 в секции 10 сообщает о том что цикл 1 выполнялся один раз и в нем насчитывается 69693 обращений к функциям. Первой в цикле вызывалась функция even(), а из нее — функция odd. Обе функции вызывались по 34847 раз.

Утилита gprof располагает рядом полезных опций.

? При задании опции -s будут суммироваться результаты нескольких запусков программы.

? С помощью опции -c можно узнать, какие дочерние функции могли быть, но так и не были вызваны

? При задании опции -l отображается построчная профильная информация.

? При задании опции -A будет отображен исходный текст программы, сопровождаемый процентными показателями времени выполнения.

Оглавление книги