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