第 33 章 用户进程跟踪
DTrace 是一款功能非常强大的、用于了解用户进程行为的工具。调试、分析性能问题或简单了解复杂应用程序的行为时，DTrace 的作用不可估量。本章重点介绍与跟踪用户进程活动有关的 DTrace 工具，并提供用于说明其用途的示例。
copyin() 和 copyinstr() 子例程
与大多数传统调试器或观察工具相比，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
|
消除 dtrace(1M) 干扰
如果跟踪对 write(2) 系统调用的所有调用，将会产生层叠输出。当其显示输出时，对 write() 的每次调用都会导致 dtrace(1M) 命令调用 write()。此反馈循环是一个有关 dtrace 命令如何干扰所需数据的较好示例。您可以使用一个简单的谓词来防止跟踪这些不需要的数据：
syscall::write:entry
/pid != $pid/
{
printf("%s", stringof(copyin(arg1, arg2)));
}
$pid 宏变量扩展为已启用探测器的进程的进程标识符。pid 变量包含其线程正在触发了探测器的 CPU 上运行的进程的进程标识符。因此，通过谓词 /pid != $pid/，可确保脚本不会跟踪与此脚本本身运行相关的任何事件。
syscall 提供器
通过 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() 操作
通常，在激活特定探测器时对进程线程的栈进行跟踪，可以更详细地检查问题。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[] 数组
通过 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 提供器，可以跟踪进程中的任何指令。与大多数其他提供器不同，pid 探测器是基于 D 程序中的探测器说明根据需要创建的。因此，除非您亲自启用，否则 dtrace -l 输出中不会列出任何 pid 探测器。
用户函数边界跟踪
对于 pid 提供器，最简单的操作模式是作为与 fbt 提供器类似的用户空间。以下示例程序将跟踪通过单个函数产生的所有函数进入和返回。$1 宏变量（命令行中的第一个操作数）是要跟踪的进程的进程 ID。$2 宏变量（命令行中的第二个操作数）是要从中跟踪所有函数调用的函数的名称。
示例 33–1 userfunc.d：跟踪用户函数的进入和返回
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 章）进行结合，以便通过跟踪函数中的每条指令来解决该问题。
示例 33–2 errorpath.d：跟踪用户函数调用错误路径
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 |
- © 2010, Oracle Corporation and/or its affiliates