DTrace 是一款功能非常强大的、用于了解用户进程行为的工具。调试、分析性能问题或简单了解复杂应用程序的行为时,DTrace 的作用不可估量。本章重点介绍与跟踪用户进程活动有关的 DTrace 工具,并提供用于说明其用途的示例。
与大多数传统调试器或观察工具相比,DTrace 与进程之间的交互略有不同。这类工具多数可能会在进程范围内执行,从而使用户可直接取消对指向程序变量的指针的引用。DTrace 探测器在 Solaris 内核中执行,而不是在进程内或作为进程的一部分执行。为访问进程数据,探测器需要使用 copyin() 或 copyinstr() 子例程,以便将用户进程数据复制到该内核的地址空间中。
例如,可以考虑下面的 write(2) 系统调用:
ssize_t write(int fd, const void *buf, size_t nbytes);
以下 D 程序说明试图列显传递给 write(2) 系统调用的字符串内容的尝试不正确:
syscall::write:entry { printf("%s", stringof(arg1)); /* incorrect use of arg1 */ }
如果尝试运行此脚本,DTrace 将生成与以下示例类似的错误消息:
dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \ invalid address (0x10038a000) in action #1 |
arg1 变量(该变量包含 buf 参数的值)是一个引用执行系统调用的进程内存的地址。要读取该地址中的字符串,请使用 copyinstr() 子例程,并借助 printf() 操作记录其结果:
syscall::write:entry { printf("%s", copyinstr(arg1)); /* correct use of arg1 */
此脚本输出将显示传递给 write(2) 系统调用的所有字符串。不过,有时也可能会显示类似以下的异常输出:
0 37 write:entry mada��� |
copyinstr() 子例程对输入参数进行操作,该参数是以 Null 结尾的 ASCII 字符串的用户地址。但是,传递给 write(2) 系统调用的缓冲区可能会引用二进制数据,而非 ASCII 字符串。要仅列显调用方指定数量的字符串,请使用 copyin() 子例程,该子例程将大小作为其第二个参数:
syscall::write:entry { printf("%s", stringof(copyin(arg1, arg2))); }
请注意,为使 DTrace 将通过 copyin() 检索的用户数据正确转换为字符串,必须使用 stringof 运算符。使用 copyinstr() 时,无需使用 stringof,因为此函数返回的类型始终为 string。
copyin() 和 copyinstr() 子例程无法从尚未访问的用户地址读取,因此,如果包含某个地址的页面没有得到访问,则即使该地址有效也可能会产生错误。以下面的示例为例:
# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }' dtrace: description 'syscall::open:entry' matched 1 probe CPU ID FUNCTION:NAME dtrace: error on enabled probe ID 2 (ID 50: syscall::open:entry): invalid address (0x9af1b) in action #1 at DIF offset 52 |
在以上示例输出中,该应用程序运行正常,且 arg0 的地址是有效的,但其引用了尚未被对应进程访问的页面。为解决此问题,请在跟踪前等待内核或应用程序使用相应数据。例如,您可以等到系统调用返回时再应用 copyinstr(),如以下示例所示:
# dtrace -n syscall::open:entry'{ self->file = arg0; }' \ -n syscall::open:return'{ trace(copyinstr(self->file)); self->file = 0; }' dtrace: description 'syscall::open:entry' matched 1 probe CPU ID FUNCTION:NAME 2 51 open:return /dev/null |
如果跟踪对 write(2) 系统调用的所有调用,将会产生层叠输出。当其显示输出时,对 write() 的每次调用都会导致 dtrace(1M) 命令调用 write()。此反馈循环是一个有关 dtrace 命令如何干扰所需数据的较好示例。您可以使用一个简单的谓词来防止跟踪这些不需要的数据:
syscall::write:entry /pid != $pid/ { printf("%s", stringof(copyin(arg1, arg2))); }
$pid 宏变量扩展为已启用探测器的进程的进程标识符。pid 变量包含其线程正在触发了探测器的 CPU 上运行的进程的进程标识符。因此,通过谓词 /pid != $pid/,可确保脚本不会跟踪与此脚本本身运行相关的任何事件。
通过 syscall 提供器,可以跟踪每个系统调用的进入和返回。系统调用是了解进程行为的良好开端,尤其是在执行进程可能会占用大量时间,或在内核阻塞了进程的情况下。您可以使用 prstat(1M) 命令查看进程在哪些地方消耗时间:
$ prstat -m -p 31337 PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6 |
此示例表明该进程占用了大量系统时间。对该行为的一种可能的解释是,进程正在执行大量系统调用。可以使用在命令行中指定的简单 D 程序,查看哪些系统调用出现的频率最高:
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }' dtrace: description 'syscall:::entry' matched 215 probes ^C open 1 lwp_park 2 times 4 fcntl 5 close 6 sigaction 6 read 10 ioctl 14 sigprocmask 106 write 1092 |
该报告显示了调用频率最高的系统调用,在此示例中即 write(2) 系统调用。您可以使用 syscall 提供器,进一步检查所有 write() 系统调用的起因:
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }' dtrace: description 'syscall::write:entry' matched 1 probe ^C value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1037 2 |@ 3 4 | 0 8 | 0 16 | 0 32 |@ 3 64 | 0 128 | 0 256 | 0 512 | 0 1024 |@ 5 2048 | 0 |
以上输出表明,该进程正在执行多个数据量相对较少的 write() 系统调用。该比例可能是造成此特定进程性能问题的起因。本示例介绍了一种用于调查系统调用行为的常规方法。
通常,在激活特定探测器时对进程线程的栈进行跟踪,可以更详细地检查问题。ustack() 操作可跟踪用户线程的栈。例如,如果打开多个文件的进程在 open(2) 系统调用中偶尔出现故障,则可使用 ustack() 操作来搜索执行出现故障的 open() 的代码路径:
syscall::open:entry /pid == $1/ { self->path = copyinstr(arg0); } syscall::open:return /self->path != NULL && arg1 == -1/ { printf("open for '%s' failed", self->path); ustack(); }
此脚本还说明了 $1 宏变量的用法,该变量将采用在 dtrace(1M) 命令行中指定的第一个操作数的值:
# dtrace -s ./badopen.d 31337 dtrace: script './badopen.d' matched 2 probes CPU ID FUNCTION:NAME 0 40 open:return open for '/usr/lib/foo' failed libc.so.1`__open+0x4 libc.so.1`open+0x6c 420b0 tcsh`dosource+0xe0 tcsh`execute+0x978 tcsh`execute+0xba0 tcsh`process+0x50c tcsh`main+0x1d54 tcsh`_start+0xdc |
ustack() 操作将记录栈的程序计数器 (PC) 值,dtrace(1M) 则通过查找进程符号表,将这些 PC 值解析为符号名。如果 dtrace 无法将 PC 值解析为符号,便会将该值列显为十六进制整数。
如果在设置 ustack() 数据输出格式之前退出或中止进程,dtrace 可能无法将栈跟踪内的 PC 值转换为符号名,并且会强制将其显示为十六进制整数。为处理此限制,请使用 dtrace 的 -c 或 -p 选项指定所关注的进程。有关这些选项和其他选项的详细信息,请参见第 14 章。如果事先不了解进程 ID 或命令,可使用以下 D 程序示例来处理限制:
/* * This example uses the open(2) system call probe, but this technique * is applicable to any script using the ustack() action where the stack * being traced is in a process that may exit soon. */ syscall::open:entry { ustack(); stop_pids[pid] = 1; } syscall::rexit:entry /stop_pids[pid] != 0/ { printf("stopping pid %d", pid); stop(); stop_pids[pid] = 0; }
如果对以上脚本的进程中的线程应用 ustack() 操作,则以上脚本将在该进程退出之前停止它。此方法可确保 dtrace 命令将 PC 值解析为符号名。请注意,在使用 stop_pids[pid] 清除动态变量之后,其值将设置为 0。请记住使用 prun(1) 命令设置重新运行已停止进程,否则系统中将聚集许多已停止进程。
通过 uregs[] 数组,可以访问各个用户寄存器。下表列出了与每个支持的 Solaris 系统体系结构对应的 uregs[] 数组索引。
表 33–1 SPARC uregs[] 常量
常量 |
寄存器 |
---|---|
R_G0..R_G7 |
%g0..%g7 全局寄存器 |
R_O0..R_O7 |
%o0..%o7 输出寄存器 |
R_L0..R_L7 |
%l0..%l7 本地寄存器 |
R_I0..R_I7 |
%i0..%i7 输入寄存器 |
R_CCR |
%ccr 条件代码寄存器 |
R_PC |
%pc 程序计数器 |
R_NPC |
%npc 下一个程序计数器 |
R_Y |
%y 乘/除寄存器 |
R_ASI |
%asi 地址空间标识符寄存器 |
R_FPRS |
%fprs 浮点寄存器状态 |
表 33–2 x86 uregs[] 常量
常量 |
寄存器 |
---|---|
R_CS |
%cs |
R_GS |
%gs |
R_ES |
%es |
R_DS |
%ds |
R_EDI |
%edi |
R_ESI |
%esi |
R_EBP |
%ebp |
R_EAX |
%eax |
R_ESP |
%esp |
R_EAX |
%eax |
R_EBX |
%ebx |
R_ECX |
%ecx |
R_EDX |
%edx |
R_TRAPNO |
%trapno |
R_ERR |
%err |
R_EIP |
%eip |
R_CS |
%cs |
R_ERR |
%err |
R_EFL |
%efl |
R_UESP |
%uesp |
R_SS |
%ss |
在 AMD64 平台上,uregs 数组的内容与其在 x86 平台上的内容相同,另外还包括下表中列出的附加元素:
表 33–3 amd64 uregs[] 常量
常量 |
寄存器 |
---|---|
R_RSP |
%rsp |
R_RFL |
%rfl |
R_RIP |
%rip |
R_RAX |
%rax |
R_RCX |
%rcx |
R_RDX |
%rdx |
R_RBX |
%rbx |
R_RBP |
%rbp |
R_RSI |
%rsi |
R_RDI |
%rdi |
R_R8 |
%r8 |
R_R9 |
%r9 |
R_R10 |
%r10 |
R_R11 |
%r11 |
R_R12 |
%r12 |
R_R13 |
%r13 |
R_R14 |
%r14 |
R_R15 |
%r15 |
下表中列出的别名可用于所有平台:
表 33–4 公用的 uregs[] 常量
常量 |
寄存器 |
---|---|
R_PC |
程序计数器寄存器 |
R_SP |
栈指针寄存器 |
R_R0 |
第一个返回码 |
R_R1 |
第二个返回码 |
使用 pid 提供器,可以跟踪进程中的任何指令。与大多数其他提供器不同,pid 探测器是基于 D 程序中的探测器说明根据需要创建的。因此,除非您亲自启用,否则 dtrace -l 输出中不会列出任何 pid 探测器。
对于 pid 提供器,最简单的操作模式是作为与 fbt 提供器类似的用户空间。以下示例程序将跟踪通过单个函数产生的所有函数进入和返回。$1 宏变量(命令行中的第一个操作数)是要跟踪的进程的进程 ID。$2 宏变量(命令行中的第二个操作数)是要从中跟踪所有函数调用的函数的名称。
pid$1::$2:entry { self->trace = 1; } pid$1::$2:return /self->trace/ { self->trace = 0; } pid$1:::entry, pid$1:::return /self->trace/ { }
键入以上示例脚本,并将其保存在名为 userfunc.d 的文件中,然后通过 chmod 将其转换为可执行文件。此脚本生成的输出与以下示例类似:
# ./userfunc.d 15032 execute dtrace: script './userfunc.d' matched 11594 probes 0 -> execute 0 -> execute 0 -> Dfix 0 <- Dfix 0 -> s_strsave 0 -> malloc 0 <- malloc 0 <- s_strsave 0 -> set 0 -> malloc 0 <- malloc 0 <- set 0 -> set1 0 -> tglob 0 <- tglob 0 <- set1 0 -> setq 0 -> s_strcmp 0 <- s_strcmp ... |
pid 提供器只能用于已在运行的进程。您可以使用 $target 宏变量(请参见第 15 章)以及 dtrace -c 和 -p 选项来创建和抓取所关注的进程,并使用 DTrace 对其进行检测。例如,以下 D 脚本可用于确定通过特定主题进程对 libc 执行的函数调用的分布:
pid$target:libc.so::entry { @[probefunc] = count(); }
要确定由 date(1) 命令执行的此类调用的分布,请将脚本保存在名为 libc.d 的文件中并执行以下命令:
# dtrace -s libc.d -c date dtrace: script 'libc.d' matched 2476 probes Fri Jul 30 14:08:54 PDT 2004 dtrace: pid 109196 has exited pthread_rwlock_unlock 1 _fflush_u 1 rwlock_lock 1 rw_write_held 1 strftime 1 _close 1 _read 1 __open 1 _open 1 strstr 1 load_zoneinfo 1 ... _ti_bind_guard 47 _ti_bind_clear 94 |
您可以使用 pid 提供器跟踪用户函数中的任何指令。pid 提供器将根据需要,为函数中的每条指令创建探测器。每个探测器的名称即函数中与其对应的,以十六进制整数表示的指令的偏移量。例如,要启用与 bar.so 模块的 foo 函数中的偏移量为 0x1c 的指令(位于 PID 为 123 的进程中)关联的探测器,可使用以下命令:
# dtrace -n pid123:bar.so:foo:1c |
要启用函数 foo 中的所有探测器(包括每条指令的探测器),可使用以下命令:
# dtrace -n pid123:bar.so:foo: |
此命令展示了一种功能非常强大的、用于调试和分析用户应用程序的方法。由于很难重现不经常发生的错误,因此对其进行调试可能并不容易。通常,您可以在出现故障后确定问题,但这对于重构代码路径已太迟。以下示例演示了如何将 pid 提供器与推理跟踪(请参见第 13 章)进行结合,以便通过跟踪函数中的每条指令来解决该问题。
pid$1::$2:entry { self->spec = speculation(); speculate(self->spec); printf("%x %x %x %x %x", arg0, arg1, arg2, arg3, arg4); } pid$1::$2: /self->spec/ { speculate(self->spec); } pid$1::$2:return /self->spec && arg1 == 0/ { discard(self->spec); self->spec = 0; } pid$1::$2:return /self->spec && arg1 != 0/ { commit(self->spec); self->spec = 0; }
执行 errorpath.d 将会生成与以下示例类似的输出:
# ./errorpath.d 100461 _chdir dtrace: script './errorpath.d' matched 19 probes CPU ID FUNCTION:NAME 0 25253 _chdir:entry 81e08 6d140 ffbfcb20 656c73 0 0 25253 _chdir:entry 0 25269 _chdir:0 0 25270 _chdir:4 0 25271 _chdir:8 0 25272 _chdir:c 0 25273 _chdir:10 0 25274 _chdir:14 0 25275 _chdir:18 0 25276 _chdir:1c 0 25277 _chdir:20 0 25278 _chdir:24 0 25279 _chdir:28 0 25280 _chdir:2c 0 25268 _chdir:return |