13.7 Пример профайлера

Ниже приведен краткий пример сессии профайлера. См. Профилирование для подробной документации функций профайлера. Рассмотрим код:

global N A;

N = 300;
A = rand (N, N);

function xt = timesteps (steps, x0, expM)
  global N;

  if (steps == 0)
    xt = NA (N, 0);
  else
    xt = NA (N, steps);
    x1 = expM * x0;
    xt(:, 1) = x1;
    xt(:, 2 : end) = timesteps (steps - 1, x1, expM);
  endif
endfunction

function foo ()
  global N A;

  initial = @(x) sin (x);
  x0 = (initial (linspace (0, 2 * pi, N)))';

  expA = expm (A);
  xt = timesteps (100, x0, expA);
endfunction

function fib = bar (N)
  if (N <= 2)
    fib = 1;
  else
    fib = bar (N - 1) + bar (N - 2);
  endif
endfunction

Если мы выполним две основные функции, получим:

tic; foo; toc;
⇒ Elapsed time is 2.37338 seconds.

tic; bar (20); toc;
⇒ Elapsed time is 2.04952 seconds.

Но это не даёт много информации о том, где тратится это время; например, является ли единственный вызов expm более дорогим или рекурсивное вычисление шагов само по себе. Для получения более подробной картины можно использовать профайлер.

profile on;
foo;
profile off;

data = profile ("info");
profshow (data, 10);

Это выводит таблицу, похожую на:

#  Function Attr     Time (s)        Calls
---------------------------------------------
   7      expm             1.034            1
   3  binary *             0.823          117
  41  binary \             0.188            1
  38  binary ^             0.126            2
  43 timesteps    R        0.111          101
  44        NA             0.029          101
  39  binary +             0.024            8
  34      norm             0.011            1
  40  binary -             0.004          101
  33   balance             0.003            1

Элементы — это отдельные исполненные функции (только 10 наиболее важных), вместе с некоторой информацией для каждой из них. Элементы типа «binary *» обозначают операторы, а другие элементы — обычные функции. Они включают как встроенные функции, такие как expm, так и наши собственные процедуры (например, timesteps). Из этого профиля мы можем сразу определить, что expm использует наибольшую долю времени обработки, даже несмотря на то, что оно вызывается только один раз. Вторая по затратности операция — это умножение матрицы на вектор в процедуре timesteps. ⁶

Однако время — это не единственная информация, доступная из профиля. Столбец атрибутов показывает нам, что timesteps вызывает себя рекурсивно. В этом примере это может быть и не так замечательно (поскольку это очевидно), но может быть полезно в более сложной ситуации. Что касается вопроса о том, почему в выводе есть «binary \», мы можем легко прояснить это. Обратите внимание, что data — это массив структур (Массивы структур), который содержит поле FunctionTable. Это хранит исходные данные для показанного профиля. Число в первом столбце таблицы указывает индекс, под которым в нём можно найти соответствующую функцию. Если мы найдём data.FunctionTable(41), получим:

scalar structure containing the fields:

    FunctionName = binary \
    TotalTime =  0.18765
    NumCalls =  1
    IsRecursive = 0
    Parents =  7
    Children = [](1x0)

Здесь мы видим информацию из таблицы снова, но с дополнительными полями Parents и Children. Оба они являются массивами, которые содержат индексы функций, которые непосредственно вызвали интересующую функцию (в данном случае запись 7, expm) или были вызваны ею (нет функций). Следовательно, оператор обратного слэша был использован внутри expm.

Теперь давайте взглянем на bar. Для этого мы начнём новую сессию профилирования (profile on делает это; старые данные удаляются перед перезапуском профайлера):

profile on;
bar (20);
profile off;

profshow (profile ("info"));

Это даёт:

#            Function Attr     Time (s)        Calls
-------------------------------------------------------
   1                 bar    R        2.091        13529
   2           binary <=             0.062        13529
   3            binary -             0.042        13528
   4            binary +             0.023         6764
   5             profile             0.000            1
   8               false             0.000            1
   6              nargin             0.000            1
   7           binary !=             0.000            1
   9 __profiler_enable__             0.000            1

Как и следовало ожидать, bar также является рекурсивным. Оно было вызвано 13 529 раз в ходе рекурсивного вычисления числа Фибоначчи не оптимальным способом, и большая часть времени была потрачена на bar само по себе.

Наконец, предположим, что мы хотим профилировать выполнение как foo, так и bar вместе. Поскольку мы уже имеем данные времени выполнения, собранные для bar, мы можем перезапустить профайлер без очистки имеющихся данных и собрать недостающую статистику о foo. Это делается так:

profile resume;
foo;
profile off;

profshow (profile ("info"), 10);

Как вы можете видеть в таблице ниже, теперь у нас есть оба профиля вместе.

#  Function Attr     Time (s)        Calls
---------------------------------------------
   1       bar    R        2.091        13529
  16      expm             1.122            1
  12  binary *             0.798          117
  46  binary \             0.185            1
  45  binary ^             0.124            2
  48 timesteps    R        0.115          101
   2 binary <=             0.062        13529
   3  binary -             0.045        13629
   4  binary +             0.041         6772
  49        NA             0.036          101