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