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