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