跳过导航链接 | |
退出打印视图 | |
DTrace 用户指南 Oracle Solaris 10 8/11 Information Library (简体中文) |
本节重点介绍了用于跟踪用户进程活动的 DTrace 工具,并提供了示例来说明其用途。
DTrace 探测器在 Solaris 内核中执行。探测器使用 copyin() 或 copyinstr() 子例程将用户进程数据复制到内核的地址空间中。
请考虑下面的 write() 系统调用:
ssize_t write(int fd, const void *buf, size_t nbytes);
下面的 D 程序显示了一个试图输出传递给 write 系统调用的字符串内容的错误尝试:
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 变量是一个地址,它引用正在执行系统调用的进程中的内存。请使用 copyinstr() 子例程来读取位于该地址的字符串。使用 printf() 操作来记录结果:
syscall::write:entry { printf("%s", copyinstr(arg1)); /* correct use of arg1 */
该脚本的输出将显示传递给 write 系统调用的所有字符串。
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 中的地址有效。不过,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 系统调用的每个调用,将会产生级联输出。对 write() 函数的每个调用都会导致 dtrace 命令在显示输出时调用 write() 函数。此反馈循环是一个有关 dtrace 命令如何干扰所需数据的较好示例。您可以使用一个简单的谓词来避免此行为,如下例所示:
syscall::write:entry /pid != $pid/ { printf("%s", stringof(copyin(arg1, arg2))); }
$pid 宏变量扩展为已启用探测器的进程的进程标识符。pid 变量包含其线程正在触发了探测器的 CPU 上运行的进程的进程标识符。谓词 /pid != $pid/ 可确保脚本不跟踪与该脚本自身的运行相关的任何事件。
通过 syscall 提供器,可以跟踪每个系统调用的进入和返回。可以使用 prstat(1M) 命令来查看 examine 进程行为。
$ 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() 函数的大量系统调用。您可以使用 syscall 提供器,进一步检查所有 write() 系统调用的起因:
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(); }' 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() 系统调用中,打开多个文件的某个进程偶尔失败,则可使用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 命令行上指定的第一个操作数的值:
# 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 命令通过查看进程的符号表将那些 PC 值解析为符号名称。dtrace 命令输出无法解析为十六进制整数的 PC 值。
如果进程在 ustack() 数据针对输出进行格式化之前退出或者被终止,则 dtrace 命令可能无法将栈跟踪中的 PC 值转换为符号名称。在这种情况下,dtrace 命令将这些值显示为十六进制整数。为绕过此限制,请使用 dtrace 的 -c 或 -p 选项指定需关注的进程。如果事先不知道进程 ID 或命令,可使用以下 D 程序示例来绕过限制:示例使用了 open 系统调用探测器,但此方法可以用于使用 ustack 操作的任何脚本。
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。
使用 pid 提供器,可以跟踪进程中的任何指令。与大多数其他提供器不同,pid 探测器是基于 D 程序中的探测器说明按需创建的。
对于 pid 提供器,最简单的操作模式是作为与 fbt 提供器类似的用户空间。以下示例程序将跟踪通过单个函数产生的所有函数进入和返回。$1 宏变量扩展为命令行上的第一个操作数。该宏变量是要跟踪的进程的进程 ID。$2 宏变量扩展为命令行上的第二个操作数。该宏变量是从其中跟踪所有函数调用的函数的名称。
示例 4-3 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 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 提供器只能用于已在运行的进程。利用 dtrace 工具,可以使用 $target 宏变量以及 dtrace 选项 -c 和 -p 来创建和检测需关注的进程。下面的 D 脚本用于确定由某个特定的主题进程对 libc 进行的函数调用的分布:
pid$target:libc.so::entry { @[probefunc] = count(); }
要确定由 date(1) 命令执行的此类调用的分布,请执行以下命令:
# 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 提供器根据需要为函数中的每条指令创建探测器。每个探测器的名称即函数中与其对应的,以十六进制整数表示的指令的偏移量。在 PID 为 123 的进程中,要启用 bar.so 模块的 foo 函数中与偏移量 0x1c 处的指令关联的探测器,可使用以下命令。
# dtrace -n pid123:bar.so:foo:1c
要启用函数 foo 中的所有探测器(包括每条指令的探测器),可使用以下命令:
# dtrace -n pid123:bar.so:foo:
下面的示例说明了如何组合使用 pid 提供器与推理跟踪来跟踪函数中的每条指令。
示例 4-4 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