深入研究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方法有一些非常奇怪的地方.我向哈德利提出了以下修正案.(您可能希望在您的示例中尝试此操作.)

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 形成鲜明对比，它们都有线路分析器。

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

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

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

"C" "B" "A"

这意味着函数 A 调用 B，然后函数 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 这样的线路分析器，因此处理这个问题的最简单方法就是只检测代码。