深入研究 R 分析信息

Question

我正在尝试优化一些代码，对来自summaryRprof() 的信息感到困惑。特别是，似乎对外部 C 程序进行了多次调用，但我无法确定 哪个 C 程序，来自哪个 R 函数。我计划通过对代码进行大量切片和切块来解决这个问题，但想知道我是否忽略了一些更好的方法来解释分析数据。

消耗最高的函数是.Call，这显然是对C代码调用的通用描述；下一个主要功能似乎是赋值操作：

$by.self
                             self.time self.pct total.time total.pct
".Call"                        2281.0    54.40     2312.0     55.14
"[.data.frame"                  145.0     3.46      218.5      5.21
"initialize"                    123.5     2.95      217.5      5.19
"$<-.data.frame"                121.5     2.90      121.5      2.90
"as.vector"                     110.5     2.64      416.0      9.92

我决定关注.Call，看看这是如何产生的。我查看了分析文件以在调用堆栈中找到那些带有.Call 的条目，以下是调用堆栈中的顶部条目（按出现次数计数）：

13640 "eval"
11252 "["
7044 "standardGeneric"
4691 "<Anonymous>"
4658 "tryCatch"
4654 "tryCatchList"
4652 "tryCatchOne"
4648 "doTryCatch"

这个列表一清二楚：我有<Anonymous> 和standardGeneric。

我相信这是由于调用了 Matrix 包中的函数，但那是因为我正在查看代码，而该包似乎是唯一可能的 C 代码来源。但是，这个包中调用了很多来自 Matrix 的不同函数，而且这次似乎很难确定 哪个 函数正在消耗。

所以，我的问题是非常基本的：是否有某种方法可以以其他方式破译和归因这些调用（例如.Call、<Anonymous> 等）？考虑到所涉及的函数数，此代码的调用图绘制起来相当棘手。

我看到的后备策略是 (1) 注释掉代码位（并修改代码以使其与此一起工作）以查看时间消耗发生在哪里，或者 (2) 将某些操作包装在其他操作中函数并查看这些函数何时出现在调用堆栈上。后者是不优雅的，但它似乎是向调用堆栈添加标签的最佳方式。前者令人不快，因为运行代码需要相当长的时间，并且反复取消注释代码并重新运行令人不快。

Answer 1

我建议您使用profr 包。这是另一个哈德利魔法。它是Rprof 的包装器，并提供调用堆栈和时间的可视化。

我发现profr 非常易于使用和解释。例如，这里是一些ddply 示例代码的配置文件和生成的profr 图：

library(profr)
p <- profr(
    ddply(baseball, .(year), "nrow"),
    0.01
)
plot(p)

您可以立即看到以下内容：

• ddply 如何调用ldply、llply 和loop_apply。
• 在loop_apply 内部有一个.Call 函数。

您可以通过阅读loop_apply的源代码来确认这一点：

> plyr:::loop_apply
function (n, f, env = parent.frame()) 
{
    .Call("loop_apply", as.integer(n), f, env)
}
<environment: namespace:plyr>

---

编辑。 ggplot.profr 方法有些奇怪。我已向 Hadley 提出以下修复方案。 （您可能希望在您的示例中尝试此操作。）

ggplot.profr <- function (data, ..., minlabel = 0.1, angle = 0){
  if (!require("ggplot2", quiet = TRUE)) 
    stop("Please install ggplot2 to use this plotting method")
  data$range <- diff(range(data$time))
  ggplot(as.data.frame(data), aes(y=level)) + 
      geom_rect(
          #aes(xmin=(level), xmax=factor(level)+1, ymin=start, ymax=end),  
          aes(ymin=level-0.5, ymax=level+0.5, xmin=start, xmax=end),  
          #position = "identity", stat = "identity", width = 1, 
          fill = "grey95", 
          colour = "black", size = 0.5) + 
      geom_text(aes(label = f, x = start + range/60), 
          data = subset(data, time > max(time) * minlabel), size = 4, angle = angle, vjust=0.5, hjust = 0) + 
      scale_x_continuous("time") + 
      scale_y_continuous("level")
}

Answer 2

似乎简短的回答是“不”，而长的回答是“是的，但你不会喜欢这个。”即使回答这个问题也需要一些时间（所以坚持下去，我可能会更新它）。

在 R 中使用分析时，有几件基本的事情需要了解：

首先，有许多不同的方式来考虑分析。从调用堆栈的角度考虑是很典型的。在任何给定的时刻，这是一系列活动的函数调用，基本上是相互嵌套的（如果你愿意的话，是子例程）。这对于理解评估的状态、函数将返回的位置以及许多其他对于计算机/解释器/操作系统可能看到的事物很重要的事情非常有用。 Rprof 确实调用堆栈分析。

其次，从不同的角度来看，我有一堆代码，而一个特定的调用需要很长时间：我的代码中的哪一行导致了该调用？这是线路分析。据我所知，R 没有线路分析。这与 Python 和 Matlab 形成对比，两者都有线分析器。

第三，从行到调用的映射是满射的，但不是双射的：给定一个特定的调用堆栈，我们不能保证我们可以将它映射回代码。事实上，调用堆栈分析通常会完全脱离整个堆栈的上下文来总结调用（即，无论调用发生在所有不同堆栈的哪个位置，都会报告累积时间）。

第四，即使我们有这些限制，我们也可以戴上统计帽子，仔细分析调用堆栈数据，看看我们能做些什么。调用堆栈信息是data，我们喜欢数据，不是吗？ :)

只是对调用堆栈的快速介绍。让我们假设我们的调用堆栈如下所示：

"C" "B" "A"

这意味着函数 A 调用 B 然后调用 C（顺序颠倒），调用堆栈深度为 3 级。在我的代码中，调用堆栈的深度多达 41 级。由于堆栈可以很深并且以相反的顺序呈现，因此软件比人类更容易解释。自然地，我们开始清理和转换这些数据。 :)

现在，我们的数据看起来像这样：

".Call" "subCsp_cols" "[" "standardGeneric" "[" "eval" "eval" "callGeneric"
"[" "standardGeneric" "[" "myFunc2" "myFunc1" "eval" "eval" "doTryCatch"
"tryCatchOne" "tryCatchList" "tryCatch" "FUN" "lapply" "mclapply"
"<Anonymous>" "%dopar%"

很惨，不是吗？它甚至有像eval 这样的东西的重复，有些人叫<Anonymous> - 可能是一些该死的黑客。 （顺便说一句，匿名是军团。:-)）

将其转换为有用的第一步是拆分Rprof() 输出的每一行并反转条目（通过strsplit 和rev）。前 12 个条目（如果您查看原始调用堆栈，则为最后 12 个，而不是rev 后的版本）对于每一行都是相同的（其中大约有 12000 个，采样间隔为 0.5 秒 - 所以大约 100分钟的分析），这些可以被丢弃。

请记住，我们仍然想知道是哪一行导致了.Call，这花了很多时间。在我们回答这个问题之前，我们设置了我们的统计上限：分析报告，例如来自summaryRprof、profr、ggplot 等，仅反映给定呼叫或给定呼叫下的呼叫所花费的累积时间。这些累积的信息没有告诉我们什么？ Bingo：该调用是多次还是几次，以及该调用的所有调用所花费的时间是否恒定，或者是否存在一些异常值。一个特定的函数可能会被执行 100 次或 100K 次，但所有的开销都可能来自一次调用（它不应该，但是直到我们查看数据才知道）。

这只是描述乐趣的开始。 A->B->C 的例子并没有反映事物可能真正出现的方式，例如 A->B->C->D->B->E。现在，“B”可能会被计算几次。更重要的是，假设很多时间都花在了 C 级别，但我们从来没有在那个级别进行精确采样，只在堆栈中看到它的子调用。我们可能会看到“total.time”的时间相当长，但“self.time”却没有。如果 C 下有很多不同的子调用，我们可能会忽略要优化的内容 - 我们应该完全取出 C 还是调整子 B、D 和 E？

为了考虑所花费的时间，我获取了序列并通过digest 运行它们，通过hash 存储消化值的计数。我还拆分了序列，存储 {(A),(A,B), (A,B,C) 等}。这似乎不太有趣，但是从计数中删除单例有助于清理数据。我们还可以使用rle() 存储每次调用所花费的时间。这对于分析给定呼叫所花费的时间分布很有用。

我们仍然无法找到每行代码所花费的实际时间。我们永远不会从调用堆栈中获取代码行。一种更简单的方法是在整个代码中存储时间列表，其中存储了给定调用的proc.time() 的输出。取这些时间的差异可以揭示哪些代码行或代码段花费了很长时间。 （提示：这才是我们真正要寻找的，而不是实际的调用。）

但是，我们有这个调用堆栈，我们不妨做一些有用的事情。向上堆栈有点有趣，但是如果我们将配置文件信息倒退到稍早一点，我们可以发现哪些调用往往先于运行时间较长的调用。这使我们能够在调用堆栈中寻找地标——我们可以将调用绑定到特定代码行的位置。如果我们只有调用堆栈而不是检测代码，这使得将更多调用映射回代码变得更容易一些。 （正如我一直提到的：断章取义，没有 1:1 的映射，但在足够精细的粒度下，尤其是在独特的重复命中调用中，您可能能够在映射到代码的调用中找到地标.)

总而言之，我能够找出哪些调用花费了很多时间，无论是基于 1 个长间隔还是许多小间隔，花费的时间分布情况如何，并且通过一些努力，我能够将最重要和最耗时的调用映射回代码，并发现代码的哪些部分可以从重写或算法更改中获益最多。

调用堆栈的统计分析非常有趣，但是根据累积时间消耗来调查特定调用并不是一个很好的方法。调用消耗的累积时间是相对的信息，但它不能告诉我们这次是一个还是多个调用消耗，也不是调用在堆栈中的深度，也不是负责调用的代码部分.前两件事可以通过更多的 R 代码来解决，而后者最好通过插桩代码来解决。

由于 R 还没有像 Python 和 Matlab 这样的线分析器，因此处理这个问题的最简单方法就是检测自己的代码。

Answer 3

配置文件中的一行可能看起来像

"strsplit" ".parseTabix" ".readVcf" "readVcf" "standardGeneric" "readVcf" "system.time" 

表示，从右到左阅读，最外层的函数是 system.time，它调用了 readVcf，这是一个 S4 泛型，分派到 readVcf 方法，调用函数 .readVcf，它调用 .parseTabix，最后调用strsplit.

这里我们读入配置文件，对行进行排序，统计它们（使用rle -- 运行长度编码），然后选择配置文件中最常见的六个路径

r = rle(sort(readLines("readVcf.Rprof"))
o = order(r$lengths, decreasing=TRUE)
r$values[head(o)]

这个

r$lengths[head(o)]

告诉我们每个调用堆栈被采样了多少次。

有一些常见的模式可以帮助解释这一点。这是一个 S4 泛型被分派到它的方法

"readVcf" "standardGeneric" "readVcf"

lapply 迭代其函数

"FUN" "lapply"

还有一个 tryCatch 围绕着一个 .Call

".Call" "doTryCatch" "tryCatchOne" "tryCatchList" "tryCatch"

通常，人们会尝试分析相对较小的代码块，而不是整个脚本，其中小块的标识是通过交互方式逐步执行代码或对哪些部分可能会很慢做出一些有根据的猜测。 .Call 是最常见的采样函数这一事实并不令人鼓舞——它表明大部分时间已经花在 C 中了。可能你最好的选择是提出一个更好的整体算法，而不是说一种蛮力方法.