探查器示例 (GNU Octave(版本11.1.0))

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

脚注

(6)

我们只知道它是二元乘法运算符，但幸运的是，该运算符在代码中只出现了一处，因此我们知道是哪个位置占用了这么多时间。如果有多个位置，我们就必须使用层次分析来找出占用时间的确切位置，但这在本例中没有涉及。