使用DTrace对FreeBSD内核进行性能分析

问题描述

我希望通过FreeBSD缩短接口销毁时间。在运行from scipy.stats import t as tdist def welch_ttest(m1,m2,s1,s2,n1,n2): numerator = m1 - m2 denominator = np.sqrt((s1 ** 2) / n1 + (s2 ** 2) / n2) t = numerator / denominator dof_numerator = ((s1 ** 2) / n1 + (s2 ** 2) / n2) ** 2 dof_denominator = ((s1 ** 4) / (n1 ** 2) / (n1 - 1) + (s2 ** 4) / (n2 ** 2) / (n2 - 1)) dof = dof_numerator / dof_denominator p_half = tdist.cdf(t,dof) if p_half > 0.5: p_final = 2 * (1 - p_half) else: p_final = 2 * p_half return t,p_final # returning t to check the validity of the function 的测试计算机上，销毁数千个接口需要花费几分钟，而且-诚然-我的用例可能是不寻常的，我想了解长时间使用该系统的情况。

根据我的初步观察，我能够确定大部分时间都花在了-CURRENT内部。因此，为了分析此功能，我想出了以下DTrace脚本：

if_detach_internal()

通过挂接#!/usr/sbin/dtrace -s #pragma D option quiet #pragma D option dynvarsize=256m fbt:kernel:if_detach_internal:entry { self->traceme = 1; t[probefunc] = timestamp; } fbt:kernel:if_detach_internal:return { dt = timestamp - t[probefunc]; @ft[probefunc] = sum(dt); t[probefunc] = 0; self->traceme = 0; } fbt:kernel::entry /self->traceme/ { t[probefunc] = timestamp; } fbt:kernel::return /self->traceme/ { dt = timestamp - t[probefunc]; @ft[probefunc] = sum(dt); t[probefunc] = 0; } 和entry fbt探针，我希望得到return调用的每个函数的函数名称和累积执行时间的列表（无论堆栈深度），然后过滤掉其他任何内容。

但是，我得到的是这样的（破坏了250个接口）：

  callout_when                                                   1676
  sched_load                                                     1779
  if_rele                                                        1801
[...]
  rt_unlinkrte                                            10296062843
  sched_switch                                            10408456866
  rt_checkdelroute                                        11562396547
  rn_walktree                                             12404143265
  rib_walk_del                                            12553013469
  if_detach_internal                                      24335505097
  uma_zfree_arg                                        25045046322788
  intr_event_schedule_thread                           58336370701120
  swi_sched                                            83355263713937
  spinlock_enter                                      116681093870088
[...]
  spinlock_exit                                      4492719328120735
  cpu_search_lowest                                 16750701670277714

为至少某些功能命名信息似乎是有道理的，但是我希望if_detach_internal()是列表中的最后一个条目，而花费的时间不会更长，因为该功能位于列表的顶部。我正在尝试分析的调用树。

显然不是这样，因为我也正在用看似疯狂的执行时间来获取其他功能（if_detach_internal()，uma_zfree_arg()等）的度量。这些结果完全消除了我对DTrace在这里告诉我的一切一切的信任。

我想念什么？这种方法听起来很合理吗？

解决方法

我将在我的评论之前加上以下事实：我没有在FreeBSD上使用DTrace，仅在macOS / OS X上使用过。所以这里可能存在一些我不知道的特定于平台的东西。顺便说一句：

• 我对您使用全局关联数组t感到有些不安。您可能希望使该线程成为本地线程（self->t，因为就目前而言，如果同时从多个线程中调用if_detach_internal，您的代码可能会产生垃圾结果。
• 您对全局dt变量的使用同样危险且线程不安全。 确实应该this->dt无处不在（子句局部变量）。
• 需要注意的另一件事是，fbt:kernel::entry /self->traceme/动作将为{ {1}}本身。这是因为后一个函数当然与通配符匹配，和操作按照它们在脚本中出现的顺序执行，因此到通配符if_detach_internal操作的谓词为选中时，非通配符操作将设置entry两次设置这样的时间戳应该不会造成不良影响，但是从编写代码的方式来看，您可能没有意识到这实际上是什么这样做会导致问题，如果您进一步修改该行。

不幸的是，DTrace范围规则非常不直观，因为默认情况下，所有内容都是全局的且线程不安全。是的，即使编写了大量的DTrace脚本代码，这仍然时不时地困扰着我。

我不知道遵循上述建议是否可以完全解决您的问题；如果不是，请相应地更新您的问题，然后在下面给我留言，我会再看一遍。

,

这是一个非常简单但非常有用的dTrace脚本的另一种变体，我经常使用它来查找任何内核实际上在其大部分时间上都在哪里：

#!/usr/sbin/dtrace -s

profile:::profile-1001hz
/arg0/
{
    @[ stack() ] = count();
}

这将分析内核的堆栈跟踪，并且当脚本通过CTRL-C或其他方法退出时，它将打印如下内容：

             .
             .
             .
          unix`z_compress_level+0x9a
          zfs`zfs_gzip_compress+0x4e
          zfs`zfs_compress_data+0x8c
          zfs`zio_compress+0x9f
          zfs`zio_write_bp_init+0x2b4
          zfs`zio_execute+0xc2
          genunix`taskq_thread+0x3ad
          unix`thread_start+0x8
          703

          unix`deflate_slow+0x8a
          unix`z_deflate+0x75a
          unix`z_compress_level+0x9a
          zfs`zfs_gzip_compress+0x4e
          zfs`zfs_compress_data+0x8c
          zfs`zio_compress+0x9f
          zfs`zio_write_bp_init+0x2b4
          zfs`zio_execute+0xc2
          genunix`taskq_thread+0x3ad
          unix`thread_start+0x8
         1708

          unix`i86_mwait+0xd
          unix`cpu_idle_mwait+0x1f3
          unix`idle+0x111
          unix`thread_start+0x8
        86200

这是一个示例堆栈跟踪集以及该堆栈跟踪被采样的次数。请注意，它会最后打印最频繁的堆栈跟踪。

因此，您可以立即查看采样频率最高的堆栈跟踪-这将是内核花费大量时间的地方。

还请注意，堆栈轨迹以您认为相反的顺序打印-最外面的最上面的调用最后打印。