为什么NYTProf的逐行统计不符合总数？

Question

我有一个需要大约30分钟运行的Perl脚本，所以我当然运行Devel :: NYTProf。很棒的配置文件。对于我的很多潜艇，我收到了一些对我无意义的数据。

我使用默认的NYTProf设置在Linux上运行perl 5.10.0。

在HTML输出中，每个子文件都有一个摘要部分，说明在子文件及其子文件中花费了多少时间，然后继续为我提供行信息。

行统计信息不会累加到函数中花费的总数。是什么赋予了？

例如，我有一个报告使用233s（57 + 166）的函数。逐行数字报告有一行使用20s，另一行使用4，另一行使用2.其他行是< 1s，功能不那么长。

我该怎么办才能解决这个不匹配问题？

我可以转移到Perl 5.12，但这需要一些工作来安装依赖关系。我很高兴以较慢的模式运行它。有没有办法提高采样频率？在较慢的机器上运行？

点击这里取样：my NYTProf output。在这种情况下，报告使用225秒，但添加所有数字将产生56秒。这让人们对他的优化关闭：

setenv NYTPROF optimize=0:file=nytprof.optout 

更新我使用findcaller = 1个选项标志用Perl 5.12重新运行与或多或少相同的结果建议。 （我在不同的数据集上运行）

更新 Tim B是对的。我已经改变了一些我的关键子缓存来做缓存，而不是使用记忆，NYTProf结果再次有用。谢谢蒂姆。

Answer 1

我刚刚加入这个到NYTProf文档：

= HEAD2如果声明和子程序时序不匹配

NYTProf有两个剖析：这是时调用语句 分析器perl的从一个Perl的声明 移动到另一个 和子程序探查 其所调用时Perl的呼叫或从子程序 回报。

子例程的单个语句定时通常小于 ，小于 子例程的排他时间。这是因为子程序调用的 处理和 返回的开销包含在子程序的专用时间 中。该 差异可能只是一个新的 微秒，但有可能成为 引人注目的是 叫几十万次的子程序。

声明探查器跟踪 多少时间是如何花费的开销，像 书面陈述文件数据到磁盘 。子程序探查 减去所积累进入和离开 子程序以 给出一个更准确的轮廓之间 的开销。 语句分析器通常非常快，因为大多数写入操作都会缓存 以进行zip压缩，因此每个语句的分析器开销 往往是非常小的，通常是一个“滴答”。 的结果是累积的开销是相当嘈杂。对于 被频繁调用的子例程而言，这变得更加显着，并且也快速地为 。这可能是另一个更小的 贡献差异 之间的声明时间和独家 次。

这可能解释了语句时间列的总和（31.7s）和子例程（57.2s）报告的排他时间之间的差异。这个差异大约为每次通话100微秒（这似乎有点高，但并非不合理）。

语句分析器会记录在开销上花了多少时间，如将语句概要文件数据写入磁盘。子程序分析器减去进入和离开子程序之间的开销差异，以便给出更精确的分布图。

语句分析器通常非常快，因为大多数写操作都是通过zip压缩进行缓冲的，因此每个语句的分析器开销通常非常小，通常是单个“滴答”。结果是积累的开销很嘈杂。对于频繁调用的子程序来说，这变得更加重要，并且速度也很快（在这种情况下，250303呼叫的呼叫时间为899μs）。所以我怀疑这是另一个更小的对声明时间和独占时间之间差异的贡献。

更重要的是，我还添加了本节：

= HEAD2如果标题子程序时序不匹配，调用替补

总体子程序次报告 与像一个标题“花10s（2 + 8） ......“。在这个例子中，在 子程序（“包含时间”）内花费了10秒钟， 秒钟，在这个子程序调用的 子程序中花费了8秒钟。即 由于在子程序代码本身（ “专用时间”，有时也被称为“自我时间”，有时也被称为 ）花费的时间为2秒。

该报表显示子程序的源代码 。将调用 到其他子程序的行标注为 ，并详细说明在这些调用中花费的时间。

有时倍的用于通过的代码行，在 子程序制成 呼叫的总和小于在 报道的标题的 包容排他性时间（10-2 = 8秒内 上面的例子） 。

这里发生的事情是，调用 其他子程序被提出，但 NYTProf不能正确地确定 调用位置，这样的 调用不会在报告中 正确的位置出现。

使用旧版本的Perl是一个 原因（see below）。另一个是调用 子程序，通过“goto & sub”退出;“ - 在AUTOLOAD子系统中经常遇到 ，并使用Memoize 模块进行编码。

一般而言整体子程序 定时是准确的，并应是 可信比语句 或嵌套的子呼叫定时的总和。

Memoize模块主要是导致报告中出现差异的原因。对Memoize::__ANON__[...]的调用执行由Memoize生成的子部分，该部分看起来像sub { unshift @_, $cref; goto &_memoizer; }。那goto &_memoizer是由perl实现的，作为一种返回给调用者的函数，然后调用指定的子函数，这就是NYTProf描述它的方式。

这种混淆是由是，虽然add_bit_to_map被记录为_memoizer所以在呼叫中的时间被添加到add_bit_to_map呼叫者，呼叫的文件和行号的位置被记录为的位置处的事实引起goto。

在将来的版本中可能会改进这一点。

感谢您提示我调查此问题并改进文档。蒂姆·邦斯（Tim Bunce）：

Tim Bunce。

p.s.我建议在mailing list上提问关于NYTProf的问题。

Answer 2

尝试禁用perl的优化器。从CPAN's Devel::NYTProf docs：

优化= 0

禁用perl的优化器。

默认情况下，NYTProf允许perl的 优化器启用。这可以让您更精确地确定整个配置文件的时间，但 可能导致 单独的一组行发生奇怪的语句计数。这是 ，因为perl的窥孔优化器 已有效地重写了 语句，但您无法看到重写版本的外观。

例如：

1  if (...) { 
2   return; 
3  } may be rewritten as 

1 return if (...) 

所以轮廓 不会显示在你的源代码行 2声明计数，因为 回报被合并到如果 声明前行。

使用optimize = 0选项会禁用 优化程序，因此您将获得较低的 整体性能，但会有更多 准确分配的语句计数。

如果您发现对NYTProf输出 的 效果优化的任何其它例子（除性能，很明显） 请让我们知道。