使用 DTrace 分析 FreeBSD 内核

Question

我希望通过 FreeBSD 来改进界面破坏时间。在我的运行 -CURRENT 的测试机器上销毁数千个接口需要几分钟时间，虽然 - 不可否认 - 我的用例可能是一个不寻常的用例，但我想了解是什么让系统花费了这么长时间。

根据我最初的观察，我能够确定大部分时间都花在了 if_detach_internal() 内部的某个地方等待。所以为了分析这个函数，我想出了下面的 DTrace 脚本：

#!/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 和return fbt 探针，我期望获得if_detach_internal() 调用的每个函数的函数名称和累积执行时间列表（无论堆栈深度如何），并过滤其他的。

然而，我得到的是这样的（破坏 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 [...] 自旋锁退出 4492719328120735 cpu_search_lowest 16750701670277714

至少一些函数的时间信息似乎是有意义的，但我希望if_detach_internal() 是列表中的最后一个条目，没有什么比这更长的时间了，因为这个函数位于调用的顶部我正在尝试分析的树。

显然，情况并非如此，因为我还在以看似疯狂的执行时间测量其他功能（uma_zfree_arg()、swi_sched() 等）。这些结果完全摧毁了我对 DTrace 在这里告诉我的其他一切的信任。

我错过了什么？这种方法听起来好吗？

Answer 1

这是一个非常简单但非常有用的 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

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

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

还请注意，堆栈跟踪以您可能认为的相反顺序打印 - 最外面的最顶层调用最后打印。

Answer 2

我会在我的 cmets 前面加上一个事实，即我没有在 FreeBSD 上使用 DTrace，只在 macOS/OS X 上使用过。所以这里可能存在一些我不知道的特定于平台的东西。顺便说一句：

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

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

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