很少有人听过 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,我们的同步代码有一个内部状态机器,我们定义了如下两个探针:
1 2 3 |
provider syncengine_sync { probe strategy_go_to_state(int); } |
探针被分组成所谓的 providers。参数 int 是正要进入的状态。在我们的 Objective-C (或 Swift) 代码中,简单的插入以下代码即可:
1 2 3 4 5 6 7 |
- (void)goToState:(ZMSyncState *)state { [self.currentState didLeaveState]; self.currentState = state; SYNCENGINE_SYNC_STRATEGY_GO_TO_STATE(state.identifier); [self.currentState didEnterState]; } |
我们后面会讨论如何整合并且把流程说清楚一些。
脚本
现在我们可以编写一个 DTrace 小脚本来展示状态转变:
1 2 3 4 |
syncengine_sync*:::strategy_go_to_state { printf("Transitioning to state %d\n", arg0); } |
(后面我们会详细展示 DTrace 脚本如何工作。)
如果将 DTrace 保存进 state.d,接下来我们可以使用 dtrace(1) 命令行工具 来运行它:
1 |
% sudo dtrace -q -s state.d |
我们可以看到:
1 2 3 |
Transitioning to state 1 Transitioning to state 2 Transitioning to state 5 |
正如我们所预期的,并没什么让人激动的。最后使用 ^C 可以退出 DTrace。
一个定时例子
因为 DTrace 消耗非常小,所以非常适合用来测试性能 – 即使需要测试的时间非常短。DTrace 中的时间单位是纳秒。
如果扩展上面的小例子,我们可以输出每个状态所花费的时间:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
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; } |
这些代码会输出:
1 2 3 4 5 |
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 探针来检查转换到下一个状态之前通过网络发送了多少字节:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
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 进程感兴趣。我们运行如下的脚本:
1 |
sudo dtrace -q -s sample-timing-3.d -p 198 |
这里 198 是进程标识 (亦称 PID)。我们可以在活动监视器这个 app 中找到这个数字,或者使用 ps(1) 命令行工具。
我们会得到:
1 2 3 4 |
Transitioning to state 6 Sent 2043 bytes in previous state Transitioning to state 4 Sent 581 bytes in previous state |
D 语言
注意:这不是W. Bright 和 A. Alexandrescu 的 D 语言。
D 语言的大部分跟 C 语言都非常相似,但总体架构是不同的。每一个 Dtrace 脚本由多个所谓的探针语句组成。
在上面的例子中,我们已经看到了一些这种探针语句。它们都符合如下的形式:
1 2 3 4 5 |
probe descriptions / predicate / { action statements } |
断言 (predicate) 和动作语句 (action statement) 部分都是可选的。
探针描述
探针描述定义了语句匹配什么探针。所有的部分都可以省略,形式如下:
1 |
provider:module:function:name |
例如,syscall::: 匹配所有 syscall 提供者的探针。我们可以使用 * 匹配任何字符串,例如 syscall::*lwp*:entry 匹配所有syscall 提供者的 entry,并且函数名字包含 lwp 的探针。
一个探针描述可以包含多个探针,例如:
1 2 3 4 |
syscall::*lwp*:entry, syscall::*sock*:entry { trace(timestamp); } |
断言
当动作语句开始运行时我们可以使用断言来限制。当触发特定的探针时断言会被计算。如果断言结果为非 0,action statements 将会运行,这和 C 语言中的 if 语句类似。
我们可以使用不同的断言来判断同一个探针多次。如果有多个匹配,它们将会按照在 D 程序中的出现的顺序执行。
动作
动作包含在花括号中。D 语言是轻量,精悍而且简单的语言。
D 不支持控制流,比如循环和分支。我们不能定义任何用户函数。变量定义也是可选的。
这限制了我们能做的事情。但是一旦知道了一些常见的模式,这种简单也给了我们很多灵活性,我们将在下一节详细讨论。在 D Programming Language 的指南中可以查看更多的细节。
常见 D 语言模式
下面的例子会给让我们认识一些我们能做的事情。
这个例子统计了 App Store 应用在 syscall (也就是一个系统调用,或对 kernel 中进行的调用) 中累计使用的时间。