DTrace

很少有人听过 DTrace，它是隐藏在 OS 中的小宝藏。DTrace 是强大的 debug 工具 - 因为它拥有极其灵活的特性，并且因为与其它工具差异很大而可能相对不那么有名。

许多时候你的 app 的真正的用户或测试人员会看到一些意外的行为。DTrace 可以让你无需重启 app 就能够在生产版本上回答关于 app 的任何问题。

动态追踪

大概 10 年前，Sun Microsystems 创建了 DTrace，它的名字是 Dynamic Trace 的缩写。2007 年底，苹果公司将它集成在自己的 操作系统 中。

DTrace 是一个提供了 zero disable cost 的动态追踪框架，也就是说当代码中的探针关闭时，不会有额外的资源消耗 - 即使在生产版本中我们也可以将探针留在代码中。只有使用的时候才产生消耗。

DTrace 是动态的，也就是说我们可以将它附加在一个已经在运行的程序上，也可以不打断程序将它剥离。不需要重新编译或启动。

本文我们将重点介绍如何使用 DTrace 检查我们的程序，但值得注意的是 DTrace 是系统级的: 例如，一个单独的脚本可以观察到系统中所有进程的内存分配操作。可以查看 /usr/share/examples/DTTk 来深入了解一些非常好的例子。

OS X vs. iOS

正如你现在可能已经猜到的，DTrace 只能在 OS X 上运行。苹果也在 iOS 上使用 DTrace，用以支持像 Instruments 这样的工具，但对于第三方开发者，DTrace 只能运行于 OS X 或 iOS 模拟器。

在 Wire，即使我们被限制仅能在 iOS 模拟器上使用 DTrace，它也在 iOS 开发中非常有用。如果你读到本文并且认为在 iOS 设备上支持 DTrace 是个好提议，请提交 enhancement request 给苹果。

探针和脚本

DTrace 有两部分：DTrace 探针，及附加在上面的 DTrace 脚本。

探针

你可以将内置 (所谓静态的) 探针加入代码中。IA 探针看起来和普通的 C 函数非常相似。在 Wire，我们的同步代码有一个内部状态机器，我们定义了如下两个探针：

provider syncengine_sync {
    probe strategy_go_to_state(int);
}

探针被分组成所谓的 providers。参数 int 是正要进入的状态。在我们的 Objective-C (或 Swift) 代码中，简单的插入以下代码即可：

- (void)goToState:(ZMSyncState *)state
{
    [self.currentState didLeaveState];
    self.currentState = state;
    SYNCENGINE_SYNC_STRATEGY_GO_TO_STATE(state.identifier);
    [self.currentState didEnterState];
}

我们后面会讨论如何整合并且把流程说清楚一些。

脚本

现在我们可以编写一个 DTrace 小脚本来展示状态转变：

syncengine_sync*:::strategy_go_to_state
{
    printf("Transitioning to state %d\n", arg0);
}

(后面我们会详细展示 DTrace 脚本如何工作。)

如果将 DTrace 保存进 state.d，接下来我们可以使用 dtrace(1) 命令行工具 来运行它：

% sudo dtrace -q -s state.d

我们可以看到:

Transitioning to state 1
Transitioning to state 2
Transitioning to state 5

正如我们所预期的，并没什么让人激动的。最后使用 ^C 可以退出 DTrace。

一个定时例子

因为 DTrace 消耗非常小，所以非常适合用来测试性能 - 即使需要测试的时间非常短。DTrace 中的时间单位是纳秒。

如果扩展上面的小例子，我们可以输出每个状态所花费的时间:

uint64_t last_state;
uint64_t last_state_timestamp;

dtrace:::BEGIN
{
    syncState[4] = "EventProcessing";
    syncState[5] = "QuickSync1";
    syncState[6] = "QuickSync2";
}

syncengine_sync*:::strategy_go_to_state
/ last_state_timestamp != 0 /
{
    t = (walltimestamp - last_state_timestamp) / 1000000;
    printf("Spent %d ms in state %s\n", t, syncState[last_state]);
}

syncengine_sync*:::strategy_go_to_state
{
    printf("Transitioning to state %s\n", syncState[arg0]);
    last_state = arg0;
    last_state_timestamp = walltimestamp;
}

这些代码会输出:

Transitioning to state QuickSync1
Spent 2205 ms in state QuickSync1
Transitioning to state QuickSync2
Spent 115 ms in state QuickSync2
Transitioning to state EventProcessing

脚本中有些新东西。dtrace:::BEGIN 语句在脚本开始时运行。脚本退出时有一个相应的 END。

我们还给第一个探针增加了一个断言 (predicate)，/ last_state_timestamp != 0 /。

最后我们使用全局变量来追踪最后的状态，以及什么时候进入该状态。

内置的 walltimestamp 变量返回当前时间相对于 Unix epoch 时间以来的纳秒数。

还有一个虚拟的单位为纳秒的时间戳变量，vtimestamp。它表示当前的线程在 CPU 上运行的时间减去在 DTrace 上花费的时间。最后，machtimestamp 对应 mach_absolute_time()。

对于上面的脚本，执行的顺序非常重要。我们有两个所谓的语句对应同一个探针，(syncengine_sync*:::strategy_go_to_state)。它们会按照在 D 程序中出现的顺序执行。

结合系统探针

操作系统，尤其是 kernel，提供了数以千计的探针，被分成不同的提供者 (provider) 组。其中的很多在 Oracle 的 DTrace 文档中可以找到。

通过下面的脚本，我们可以用 ip 提供者中的 send 探针来检查转换到下一个状态之前通过网络发送了多少字节：

uint64_t bytes_sent;

syncengine_sync$target:::strategy_go_to_state
{
    printf("Transitioning to state %d\n", arg0);
    printf("Sent %d bytes in previous state\n", bytes_sent);
    bytes_sent = 0;
}

ip:::send
/ pid == $target /
{
    bytes_sent += args[2]->ip_plength;
}

这次我们的目标为某个特定的进程 - ip:::send 会匹配系统的所有进程，而我们只对 Wire 进程感兴趣。我们运行如下的脚本：

sudo dtrace -q -s sample-timing-3.d -p 198

这里 198 是进程标识 (亦称 PID)。我们可以在活动监视器这个 app 中找到这个数字，或者使用 ps(1) 命令行工具。

我们会得到:

Transitioning to state 6
Sent 2043 bytes in previous state
Transitioning to state 4
Sent 581 bytes in previous state