如何使用 dtrace 进行挂钟分析？或者，如何使用配置文件提供程序计算进程未运行的样本？

Posted 2023-03-06

【中文标题】如何使用 dtrace 进行挂钟分析？或者，如何使用配置文件提供程序计算进程未运行的样本？

【英文标题】：How to do wall-clock profiling with dtrace? Or, how to count process-not-running samples with profile provider?

【发布时间】：2014-02-01 01:28:06

【问题描述】：

我正在使用 C++ 为 OSX 上的第三方主机应用程序开发插件。它被编译为 .dylib。我希望在我的插件在宿主应用程序中运行时对其进行概要分析。

不幸的是，主机调用插件代码的速度取决于插件的（最后）执行时间。这意味着该过程的总时间相对于实时可能会有很大差异。因此，使用采样分析器，插件中的“花费时间”并没有真正基于任何有用的东西，因为它只是与属于该过程的堆栈帧进行比较。如果我改进了插件的性能，那么宿主执行插件的模式会相应地改变，并且很难衡量插件内部的改进。

我可以使用 Instruments，但据我所知，我只能获得相对于进程 CPU 时间的相对时间。

我已经使用 dtrace 来获取主机进程的用户堆栈直方图：

#!/usr/sbin/dtrace -s

#pragma ustackframes 100
#pragma D option quiet

/* $1 is pid  */
/* $2 is sample rate in Hz (e.g. 100)  */
/* $3 is duration (e.g. '20s')  */

profile-$2
/pid == $1 && arg1/

  @[ustack()] = count();


tick-$3

  exit(0);

这可行，但它仍然只提供相对于进程时间的样本，因为谓词只匹配然后进程在用户空间中。即使在进程的内核调用期间删除&& arg1 条件以触发它也无济于事。

我真正想知道的是有多少profile-n 样本导致进程根本没有运行。然后我可以将插件中的数字与样本总数进行比较，并为我的插件函数获取 absolute 样本值。这让我想知道 - 假设请求的 profile-n 采样率得到满足是否安全？我可以简单地花费时间*采样率并使用它来计算“关闭过程”时间吗？我假设在 1500Hz 时，它会丢弃样本并以其他未知的速率运行，但如果我可以确定它以 1500Hz 的频率进行采样，那么我可以从中计算出“关闭进程”时间。

或者，是否有一种已知的方法可以使用 dtrace 进行 wall-clock 分析？

【问题讨论】：

我会问Brendan Gregg。他是 DTrace 方面的专家，他展示了如何进行他所谓的堆栈分析，类似于 Random Pausing，除了他展示了如何“在 CPU 上”和“在 CPU 外”进行，但不是挂钟时间。如果有人知道怎么做，他应该知道。我会在如何分析堆栈样本方面与他不同。他进入了火焰图，我认为这很吸引人。恕我直言，应该仔细检查几个样本中的每一个，就好像它指向一个错误一样。

【参考方案1】：

这让我想知道 - 假设请求的 profile-n 采样率得到满足是否安全？

在 Solaris 上，它不能保证得到尊重：一些旧硬件缺乏对基于定时器的任意分辨率中断的必要支持。我会假设同样的理论限制适用于 OS X 的 DTrace。

无论如何，您都可以自己测试计时器分辨率。配置文件提供程序的documentation 包含一个适当的脚本，并且有更多关于该主题的内容。这是解决您的特定问题的另一个脚本：

bash-3.2# cat test.d
uint64_t last;

profile-1500
/cpu == 0/

    now = timestamp;
    @ = lquantize(now - last, 500000, 800000, 30000);
    last = now;
   

tick-1
/i++ == 10/

    exit(0);

bash-3.2# dtrace -qs test.d


           value  ------------- Distribution ------------- count    
          560000 |                                         0        
          590000 |@@@                                      1041     
          620000 |@@@@@@@@@@                               4288     
          650000 |@@@@@@@@@@@@@@                           5680     
          680000 |@@@@@@@@@@                               3999     
          710000 |@@@@                                     1451     
          740000 |                                         0        
          770000 |                                         0        
       >= 800000 |                                         1        

bash-3.2# 

请注意，在实践中，您应该以质数频率进行采样：这会阻止您与其他定期安排的系统活动同步。

根据 cmets 中的讨论，您可以通过以下方式测量在给定函数中花费的经过时间：

pid$target:mylib:myfunc:entry
/!self->depth/

    self->depth = ustackdepth;      /* beware recursion */
    self->start_time = timestamp;   /* for relative wall time calculations */
    self->start_vtime = vtimestamp; /* CPU time */      


pid$target:mylib:myfunc:return
/ustackdepth == self->depth/

    printf("%d ms (real) %d ms (CPU)\n",
        (timestamp - self->start_time) / 1000000,
        (vtimestamp - self->start_vtime) / 1000000);
    self->depth = 0;
   

如果函数被高频率调用，那么显然您可以维护经过时间的聚合，例如计算函数的平均成本。

完全可以对库中的所有函数执行类似的练习，尽管从递归和尾调用优化中消除虚假结果可能是一项相当繁重的任务。为了更有用，您可能还希望从函数的成本中排除调用堆栈所花费的时间；这使得工作更加困难（但并非不可能）。因此，有了上述方法来创建一个客观的基准，我会更倾向于坚持分析方法，可能类似于

# cat sample.d 
profile-997
/pid == $target && arg1 >= $1 && arg1 < $2/

    @[ufunc(arg1)] = count();


END

    trunc(@,5);
    exit(0);

#

这会捕获给定内存区域内五个最常见的函数。例如（并在 Solaris 上使用pmap 来定位libc），

# dtrace -qs sample.d -p `pgrep -n firefox` 0xfc090000 0xfc200000
^C

  libc.so.1`mutex_lock_impl                                        35
  libc.so.1`clear_lockbyte                                         46
  libc.so.1`gettimeofday                                           71
  libc.so.1`memset                                                 73
  libc.so.1`memcpy                                                170
# 

事实证明，这很好地说明了采样的好处：memcpy() 和 memset() 是在汇编中手工编码的 --- 即我们发现最耗时的功能已经得到优化。

【讨论】：

谢谢，在 OSX Mavericks 上，我在 650000 处获得了 13950/16451 计数。另一次运行得到 16114/16451 - 非常窄的分布。总数似乎总是在 16000 左右，通常是 16451。感谢您提供有关素数频率的提示。

这应该让您对采样充满信心：您正在以大约 1496 Hz 而不是 1500 Hz 进行分析，间隔分布很窄。我不太清楚你的其余问题是什么意思。挂钟分析到底是什么意思？您是否想测量特定进程在给定库中花费的挂钟时间（相对于 CPU 时间）的比例？如果是这样，您是否对该库中的函数何时出现在进程的调用堆栈上或进程的程序计数器何时出现在库的文本部分中感兴趣？

我想我正在寻找库性能的实时测量。 （我的）库代码将以固定速率调用，但主机的调用环境在每次调用之前和之后可能具有可变的 CPU 时间，因此比较库与主机的样本计数并不是很有用。我还使用 FlameGraph 进行绘图，它（当前）都是相对的。我的目标真的是弄清楚我的库中的改进是否真的是真正的改进。我发现在这种特殊情况下很难使用 Instruments 的相对测量值（以及我目前使用的 dtrace）。

但是，正如你所说，我现在对我的采样有了一些信心，所以我可以用它来计算在每个库函数中花费的绝对时间（只要这种采样技术允许这样的计算）。

好的，那么您对“库性能的实时测量”的定义是什么？每次调用库的经过时间（墙或 CPU）？每个功能的时间？还有什么？