Ускорение кода при помощи GNU-профайлера

Мартин Ханифорд

Введение

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

Другие приложения (например, кодирование видеоинформации), выполняющие длительные операции, лучше использовать в пакетном режиме, когда вы запускаете программу и оставляете ее работать в фоновом режиме, занимаясь в это время чем-нибудь еще. Хотя эти типы приложений не имеют таких жестких ограничений по производительности, увеличение производительности все равно дает преимущества, например, способность кодировать большее количество видеоинформации за определенный промежуток времени или способность кодировать с более высоким качеством за то же время.

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

К сожалению, большинство усилий, затрачиваемых на попытки ускорить приложение, проходит даром, поскольку разработчики часто оптимизируют свои программы на микроуровне без полного исследования их функционирования на макроуровне. Например, вы можете потратить много времени на ускорение работы определенной функции в два раза, что конечно правильно, но если эта функция вызывается редко (скажем при открытии файла), то уменьшение времени ее выполнения с 200 мс до 100 мс существенно не скажется на общем времени выполнения программы.

Более эффективным использованием вашего времени была бы оптимизация тех участков программы, которые вызываются наиболее часто. Например, если приложение тратит 50% времени на функции обработки строк, и вы можете оптимизировать эти функции на 10%, то это даст 5%-ное улучшение общей производительности приложения.

Следовательно, очень важно иметь точную информацию о том, где именно расходуется время в вашем приложении (и для реальных входных данных ), если вы хотите действительно эффективно его оптимизировать. Такие действия называются профилированием кода . Эта статья знакомит с программой профилирования, предоставляемой вместе с набором инструментальных средств проекта GNU для компилирования, называемой GNU-профайлером (gprof).

Спасительный gprof

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

Корректность работы программного обеспечения. Это всегда главная цель разработки. Вообще нет смысла писать очень быстрое приложение, если оно не делает то, что должно делать! Очевидно, что корректность - это что-то вроде "серой зоны"; видеопроигрыватель, работающий с 99% ваших файлов, или проигрывающий видео со случайными сбоями, все-таки можно использовать, но вообще-то, корректность более важна, чем скорость.
Удобство в обслуживании программного обеспечения. Это, фактически, подцель первой цели. В общем случае, если приложение не написано для удобного обслуживания, то даже если оно вначале работает, рано или поздно вы (или кто-нибудь еще) оставите попытки исправить опечатки или добавить новые функции.
Скорость работы программного обеспечения. Вот здесь и нужен профайлер. Если программное приложение работает корректно, начните профилирование для ускорения его работы.

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

gprof может профилировать приложения, написанные на языках C, C++, Pascal и Fortran 77. Приведенные здесь примеры используют C.

Листинг 1. Пример долго выполняющегося приложения

#include <stdio.h>

int a(void) {
  int i=0,g=0;
  while(i++<100000)
  {
     g+=i;
  }
  return g;
}
int b(void) {
  int i=0,g=0;
  while(i++<400000)
  {
    g+=i;
  }
  return g;
}

int main(int argc, char** argv)
{
   int iterations;

   if(argc != 2)
   {
      printf("Usage %s <No of Iterations>\n", argv[0]);
      exit(-1);
   }
   else
      iterations = atoi(argv[1]);

   printf("No of iterations = %d\n", iterations);

   while(iterations--)
   {
      a();
      b();
   }
}

Как видно из этого кода, это очень простое приложение содержит две функции, a и b, обе из которых выполняют длительные циклы, расходуя процессорное время. Функция main просто содержит цикл, в котором вызывает по очереди эти функции. Во второй функции, b, цикл работает в четыре раза дольше, чем в a, поэтому при профилировании кода мы ожидаем, что 20% времени программа будет тратить на функцию a, и 80% на b. Давайте разрешим профилирования и посмотрим, подтверждаются ли эти ожидания.

Для разрешения профилирования просто добавьте параметр -pg при вызове компилятора gcc. Выполните компилирование следующим образом:

gcc example1.c -pg -o example1 -O2 -lc

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

./example1 50000

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

Использование результатов

Прежде всего, просмотрите "простой профиль" (flat profile), который вы получаете при выполнении команды gprof со следующими параметрами: сам исполняемый файл и файл gmon.out:

gprof example1 gmon.out -p

Результаты работы таковы:

Листинг 2. Простой профиль

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 80.24     63.85    63.85    50000     1.28     1.28  b
 20.26     79.97    16.12    50000     0.32     0.32  a

Из полученной информации вы можете увидеть, что, как и ожидалось, примерно в четыре раза больше времени тратится на функцию b, чем на функцию a. Реальные цифры не очень полезны; они могут быть очень не точными из-за ошибок округления.

Проницательные читатели заметят, что многие вызовы функций (например printf) не включены в результат. Это происходит потому, что они находятся в библиотеке времени исполнения C (libc.so), которая (в данном случае) не была откомпилирована с параметром -pg и, следовательно, информация профилирования не собирается ни для какой функции из этой библиотеки. Я вернусь к этой теме позже.

Затем вы, возможно, захотите увидеть "граф вызовов" (call graph), который можно получить следующим образом:

gprof example1 gmon.out -q

Результаты работы таковы:

Листинг 3. Граф вызовов

                     Call graph (explanation follows)
granularity: each sample hit covers 2 byte(s) for 0.01% of 79.97 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00   79.97                 main [1]
               63.85    0.00   50000/50000       b [2]
               16.12    0.00   50000/50000       a [3]
-----------------------------------------------
               63.85    0.00   50000/50000       main [1]
[2]     79.8   63.85    0.00   50000         b [2]
-----------------------------------------------
               16.12    0.00   50000/50000       main [1]
[3]     20.2   16.12    0.00   50000         a [3]
-----------------------------------------------

Наконец, вы можете получить листинг "аннотированный исходный код" (annotated source), в котором выводится исходный код приложения с отметками о количестве вызовов каждой функции.

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

gcc example1.c -g -pg -o example1 -O2 -lc

Снова выполните приложение:

./example1 50000

Команда gprof:

gprof example1 gmon.out -A

Результаты работы:

Листинг 4. Аннотированный исходный код

*** File /home/martynh/profarticle/example1.c:
                #include <stdio.h>

       50000 -> int a(void) {
                  int i=0,g=0;
                  while(i++<100000)
                  {
                     g+=i;
                  }
                  return g;
                }
       50000 -> int b(void) {
                  int i=0,g=0;
                  while(i++<400000)
                  {
                    g+=i;
                  }
                  return g;
                }

                int main(int argc, char** argv)
       ##### -> {
                   int iterations;

                   if(argc != 2)
                   {
                      printf("Usage %s <No of Iterations>\n", argv[0]);
                      exit(-1);
                   }
                   else
                      iterations = atoi(argv[1]);

                   printf("No of iterations = %d\n", iterations);

                   while(iterations--)
                   {
                      a();
                      b();
                   }
                }



Top 10 Lines:

     Line      Count

        3      50000
       11      50000
Execution Summary:

        3   Executable lines in this file
        3   Lines executed
   100.00   Percent of the file executed

   100000   Total number of line executions
 33333.33   Average executions per line

Поддержка разделяемых библиотек

Как я уже упоминал ранее, поддержка профилирования добавляется компилятором, поэтому, если вы хотите получить информацию для профилирования из любой разделяемой библиотеки, включая библиотеку C (libc.a), вы должны тоже откомпилировать ее с параметром -pg. К счастью, многие дистрибутивы поставляются с уже откомпилированными для поддержки профилирования версиями библиотек C (libc_p.a).

В используемом мной дистрибутиве, gentoo, необходимо добавить "profile" в флаги USE и пересобрать glibc. После этого вы должны увидеть, что создалась библиотека /usr/lib/libc_p.a. Для тех дистрибутивов, которые не поставляются с библиотекой libc_p в стандартном варианте, вы должны проверить, можно ли установить ее отдельно, либо загрузить исходный код glibc и скомпоновать ее самостоятельно.

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

gcc example1.c -g -pg -o example1 -O2 -lc_p

Если вы опять запустите приложение и получите простой профиль или граф вызовов, то должны увидеть множество функций времени исполнения C, включая printf (ни одна из которых не является важной для нашей тестовой программы).

Пользовательское время или время ядра

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

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

Если вы немного измените листинг 1, то сможете более четко увидеть эту проблему:

Листинг 5. Добавление системных вызовов в листинг 1

#include <stdio.h>

int a(void) {
  sleep(1);
  return 0;
}
int b(void) {
  sleep(4);
  return 0;
}

int main(int argc, char** argv)
{
   int iterations;

   if(argc != 2)
   {
      printf("Usage %s <No of Iterations>\n", argv[0]);
      exit(-1);
   }
   else
      iterations = atoi(argv[1]);

   printf("No of iterations = %d\n", iterations);

   while(iterations--)
   {
      a();
      b();
   }
}

Я изменил код таким образом, что вместо выполнения циклов функции a и b вызывают функцию библиотеки времени исполнения sleep для задержки работы на 1 и 4 секунды соответственно.

Откомпилируйте это приложение:

gcc example2.c -g -pg -o example2 -O2 -lc_p

и выполните его с 30-ю итерациями:

./example2 30

Вы получите следующий простой профиль:

Листинг 6. Простой профиль, показывающий сиcтемные вызовы

Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total
 time   seconds   seconds    calls  Ts/call  Ts/call  name
  0.00      0.00     0.00      120     0.00     0.00  sigprocmask
  0.00      0.00     0.00       61     0.00     0.00  __libc_sigaction
  0.00      0.00     0.00       61     0.00     0.00  sigaction
  0.00      0.00     0.00       60     0.00     0.00  nanosleep
  0.00      0.00     0.00       60     0.00     0.00  sleep
  0.00      0.00     0.00       30     0.00     0.00  a
  0.00      0.00     0.00       30     0.00     0.00  b
  0.00      0.00     0.00       21     0.00     0.00  _IO_file_overflow
  0.00      0.00     0.00        3     0.00     0.00  _IO_new_file_xsputn
  0.00      0.00     0.00        2     0.00     0.00  _IO_new_do_write
  0.00      0.00     0.00        2     0.00     0.00  __find_specmb
  0.00      0.00     0.00        2     0.00     0.00  __guard_setup
  0.00      0.00     0.00        1     0.00     0.00  _IO_default_xsputn
  0.00      0.00     0.00        1     0.00     0.00  _IO_doallocbuf
  0.00      0.00     0.00        1     0.00     0.00  _IO_file_doallocate
  0.00      0.00     0.00        1     0.00     0.00  _IO_file_stat
  0.00      0.00     0.00        1     0.00     0.00  _IO_file_write
  0.00      0.00     0.00        1     0.00     0.00  _IO_setb
  0.00      0.00     0.00        1     0.00     0.00  ____strtol_l_internal
  0.00      0.00     0.00        1     0.00     0.00  ___fxstat64
  0.00      0.00     0.00        1     0.00     0.00  __cxa_atexit
  0.00      0.00     0.00        1     0.00     0.00  __errno_location
  0.00      0.00     0.00        1     0.00     0.00  __new_exitfn
  0.00      0.00     0.00        1     0.00     0.00  __strtol_internal
  0.00      0.00     0.00        1     0.00     0.00  _itoa_word
  0.00      0.00     0.00        1     0.00     0.00  _mcleanup
  0.00      0.00     0.00        1     0.00     0.00  atexit
  0.00      0.00     0.00        1     0.00     0.00  atoi
  0.00      0.00     0.00        1     0.00     0.00  exit
  0.00      0.00     0.00        1     0.00     0.00  flockfile
  0.00      0.00     0.00        1     0.00     0.00  funlockfile
  0.00      0.00     0.00        1     0.00     0.00  main
  0.00      0.00     0.00        1     0.00     0.00  mmap
  0.00      0.00     0.00        1     0.00     0.00  moncontrol
  0.00      0.00     0.00        1     0.00     0.00  new_do_write
  0.00      0.00     0.00        1     0.00     0.00  printf
  0.00      0.00     0.00        1     0.00     0.00  setitimer
  0.00      0.00     0.00        1     0.00     0.00  vfprintf
  0.00      0.00     0.00        1     0.00     0.00  write

Анализируя этот результат, вы можете увидеть, что хотя профайлер и зарегистрировал правильно количество вызовов каждой функции, время работы этих функций (и, в конечном счете, всех функций) равно 0.00. Причина этого заключается в том, что функция sleep на самом деле делает вызов в пространство ядра для задержки приложения, затем прерывает выполнение и ожидает до тех пор, пока ядро не продолжит работу приложения. Поскольку суммарное время выполнения функции в пространстве пользователя очень мало по сравнению с временем ожидания в пространстве ядра, это время округляется до нуля. Программа gprof работает таким образом, что измерения ведутся фиксированными интервалами во время исполнения программы . Следовательно, когда программа не выполняется, никаких измерений не производится.

В этом есть как плюсы, так и минусы. С одной стороны, трудно оптимизировать приложения, тратящие большую часть времени в пространстве ядра, или работающие медленно из-за внешних факторов, таких как перегрузка подсистемы ввода/вывода операционной системы. С другой стороны, это означает, что профилирование не подвержено влиянию всех остальных происходящих в системе событий (например, если другой пользователь занимает много времени CPU).

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

Запустите программу, приведенную в листинге 2, следующим образом:

time ./example2 30

Вы получите следующий результат:

Листинг 7. Результат команды time

No of iterations = 30

real    2m30.295s
user    0m0.000s
sys     0m0.004s

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

Заключение

Несмотря на ограничения, отменные выше, gprof может быть очень полезным средством оптимизации вашего кода, особенно если ваш код работает в основном в пространстве пользователя. Обычно хорошей идеей является сначала запуск вашего приложения с командой time для определения того, выдаст ли gprof полезную информацию.

Если программа gprof не подходит для профилирования вашего приложения, существуют альтернативные программы, не имеющие ограничений gprof, включая OProfile и Sysprof.

С другой стороны (если предположить, что у вас установлен пакет gcc), одним из главных преимуществ gprof над альтернативными программами является то, что, вероятнее всего, она уже установлена на любой используемой вами системе Linux.