跟踪 UNIX 应用程序的解决方案

使用 truss 和 strace

在 Solaris 和 AIX 上可以使用 truss 工具，它能够跟踪应用程序中的系统调用和信号。可以在 Linux? 上使用的 strace 工具提供相似的功能。在不同的系统上，还有提供相似信息的其他工具，包括 ktrace (FreeBSD) 和 trace。

truss/strace 概述

truss 和 strace 工具提供相似的信息，但是命令行选项稍有差异。使用这两种工具的标准方法都是把工具名放在要执行的命令前面。

例如，清单 3 给出 truss 对于本教程前面提到的 ageindays 程序的输出。

清单 3. truss 的输出

$ truss ./ageindays 24/1/1980 26/3/2009 execve("ageindays", 0x08047BBC, 0x08047BCC) argc = 3 mmap(0x00000000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFEFB0000 resolvepath("/usr/lib/ld.so.1", "/lib/ld.so.1", 1023) = 12 getcwd("/root", 1013) = 0 resolvepath("/root/ageindays", "/root/ageindays", 1023) = 15 xstat(2, "/root/ageindays", 0x08047880) = 0 open("/var/ld/ld.config", O_RDONLY) = 3 fxstat(2, 3, 0x08047760) = 0 mmap(0x00000000, 144, PROT_READ, MAP_SHARED, 3, 0) = 0xFEFA0000 close(3) = 0 sysconfig(_CONFIG_PAGESIZE) = 4096 xstat(2, "/usr/lib/libc.so.1", 0x08046FA0) = 0 resolvepath("/usr/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14 open("/usr/lib/libc.so.1", O_RDONLY) = 3 mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) = 0xFEF90000 mmap(0x00010000, 1413120, PROT_NONE, MAP_PRIVATE|MAP_NORESERVE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEE30000 mmap(0xFEE30000, 1302809, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_TEXT, 3, 0) = 0xFEE30000 mmap(0xFEF7F000, 30862, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED| MAP_INITDATA, 3, 1306624) = 0xFEF7F000 mmap(0xFEF87000, 4776, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANON, -1, 0) = 0xFEF87000 munmap(0xFEF6F000, 65536) = 0 memcntl(0xFEE30000, 187632, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0 close(3) = 0 mmap(0x00010000, 24576, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEE20000 munmap(0xFEF90000, 32768) = 0 getcontext(0x080475D0) getrlimit(RLIMIT_STACK, 0x080475C8) = 0 getpid() = 15691 [15690] lwp_private(0, 1, 0xFEE22A00) = 0x000001C3 setustack(0xFEE22A60) sysi86(SI86FPSTART, 0xFEF879BC, 0x0000133F, 0x00001F80) = 0x00000001 ioctl(1, TCGETA, 0x08046C20) = 0 fstat64(1, 0x08046B80) = 0 You have been alive 10654 days write(1, " Y o u h a v e b e e".., 31) = 31 You were born on 24/1/1980 which is a Thursday write(1, " Y o u w e r e b o r".., 47) = 47 _exit(134511508)

 

清单 4 给出 Linux 上 strace 的输出。

清单 4. strace 的输出

$ strace ./ageindays 24/1/1980 26/3/2009 execve("./ageindays", ["./ageindays", "24/1/1980", "26/3/2009"], [/* 50 vars */]) = 0 brk(0) = 0x602000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f47db185000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f47db184000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) open("/usr/lib/tls/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib/tls/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib/tls", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/lib/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib", {st_mode=S_IFDIR|0755, st_size=53248, ...}) = 0 open("/usr/local/lib/tls/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/lib/tls/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/lib/tls", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/lib/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/lib/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/lib", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 open("/usr/local/qt/lib/tls/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/qt/lib/tls/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/qt/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/qt/lib/tls", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/qt/lib/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/qt/lib/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/local/qt/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/qt/lib", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/X11R6/lib/tls/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/X11R6/lib/tls/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/X11R6/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/X11R6/lib/tls", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/X11R6/lib/x86_64/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/X11R6/lib/x86_64", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/usr/X11R6/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/X11R6/lib", 0x7fffe31858f0) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=85050, ...}) = 0 mmap(NULL, 85050, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f47db16f000 close(3) = 0 open("/lib/libc.so.6", O_RDONLY) = 3 read(3, "177ELF211?????????3?>1???3003451?????@"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=1330352, ...}) = 0 mmap(NULL, 3437208, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f47dac24000 mprotect(0x7f47dad63000, 2093056, PROT_NONE) = 0 mmap(0x7f47daf62000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13e000) = 0x7f47daf62000 mmap(0x7f47daf67000, 17048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f47daf67000 close(3) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f47db16e000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f47db16d000 arch_prctl(ARCH_SET_FS, 0x7f47db16d6f0) = 0 mprotect(0x7f47daf62000, 16384, PROT_READ) = 0 mprotect(0x600000, 4096, PROT_READ) = 0 mprotect(0x7f47db186000, 4096, PROT_READ) = 0 munmap(0x7f47db16f000, 85050) = 0 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f47db183000 write(1, "You have been alive 10654 days "..., 31You have been alive 10654 days ) = 31 write(1, "You were born on 24/1/1980 which "..., 47You were born on 24/1/1980 which is a Thursday ) = 47 exit_group(0)

 

在这两个输出中，每个输出行对应于应用程序执行的一个函数调用，其中显示函数的参数和函数调用的返回值。与调试示例不同，列出的每个函数调用都是系统或系统库中的函数，因此表示调用的函数的更低层接口。例如，在应用程序中可能使用 C 或 C++ 中的 de<fpopen()de< 函数打开文件，但是这个函数实际上是更低层的 de<open()de< 函数的包装器。

了解应用程序正在执行的操作并不需要了解每个函数的情况。输出中的许多行与操作系统为装载和执行程序所做的初始化相关。这两个跟踪输出的基本结构是相同的：

• 调用 de<execve()de< 函数以启动一个新程序。
• 装载程序所需的库。在 Solaris 输出中，首先使用 de<resolvepath()de< 寻找库，然后使用 de<open()de< 打开库。对于 Linux，使用 de<stat()de< 检查库是否存在，然后使用 de<open()de< 打开它。
• 为进程保留和分配一些内存。其中一部分内存是为应用程序保留的堆栈空间，一部分用来保存程序，其他内存保存程序使用的变量。
• 最后，执行程序，调用 de<write()de< 函数输出年龄和生日信息。

如果执行跟踪并希望了解每个步骤的具体情况，可以使用 man 命令访问每个函数的手册页。

 

识别应用程序启动问题

在启动应用程序时的一个典型问题是，程序无法正确地初始化，但是在终止时给出一个不完整或导致误解的消息。对应用程序运行跟踪常常可以揭示这个问题的根源。例如，清单 5 显示一个测试应用程序运行失败了。

清单 5. 应用程序失败

$ ./errnoacc ERROR: Application failed to initialize

 

错误消息并没有提供关于应用程序为什么会启动失败的具体信息。在这里，问题是故意引入的，但是您使用的任何命令或应用程序都可能出现相同的问题，而错误消息没什么帮助，有时候甚至没有错误消息。

对应用程序运行跟踪可能会提供一些线索（见清单 6）。

清单 6. 运行跟踪

$ truss ./errnoacc execve("errnoacc", 0x08047B20, 0x08047B28) argc = 1 mmap(0x00000000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFEFB0000 resolvepath("/usr/lib/ld.so.1", "/lib/ld.so.1", 1023) = 12 getcwd("/export/home/mc", 1014) = 0 resolvepath("/export/home/mc/errnoacc", "/export/home/mc/errnoacc", 1023) = 24 xstat(2, "/export/home/mc/errnoacc", 0x080477E4) = 0 open("/var/ld/ld.config", O_RDONLY) = 3 fxstat(2, 3, 0x080476C4) = 0 mmap(0x00000000, 144, PROT_READ, MAP_SHARED, 3, 0) = 0xFEFA0000 close(3) = 0 sysconfig(_CONFIG_PAGESIZE) = 4096 xstat(2, "/usr/lib/libc.so.1", 0x08046F04) = 0 resolvepath("/usr/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14 open("/usr/lib/libc.so.1", O_RDONLY) = 3 mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) = 0xFEF90000 mmap(0x00010000, 1413120, PROT_NONE, MAP_PRIVATE|MAP_NORESERVE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEE30000 mmap(0xFEE30000, 1302809, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_TEXT, 3, 0) = 0xFEE30000 mmap(0xFEF7F000, 30862, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED| MAP_INITDATA, 3, 1306624) = 0xFEF7F000 mmap(0xFEF87000, 4776, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANON, -1, 0) = 0xFEF87000 munmap(0xFEF6F000, 65536) = 0 memcntl(0xFEE30000, 187632, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0 close(3) = 0 mmap(0x00010000, 24576, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEE20000 munmap(0xFEF90000, 32768) = 0 getcontext(0x08047534) getrlimit(RLIMIT_STACK, 0x0804752C) = 0 getpid() = 15727 [15726] lwp_private(0, 1, 0xFEE22A00) = 0x000001C3 setustack(0xFEE22A60) sysi86(SI86FPSTART, 0xFEF879BC, 0x0000133F, 0x00001F80) = 0x00000001 open("/etc/shadow", O_RDONLY) Err#13 EACCES [file_dac_read] ioctl(1, TCGETA, 0x08046BB0) = 0 fstat64(1, 0x08046B10) = 0 ERROR: Application failed to initialize write(1, " E R R O R : A p p l i".., 40) = 40 _exit(0)

 

问题出现在这一行上：de<open("/etc/shadow", O_RDONLY) Err#13 EACCES [file_dac_read]de<。

在这里，应用程序试图打开一个文件，但是因为有文件权限保护这个文件，运行应用程序的用户没有访问权。因为无法打开这个文件，应用程序终止并在进程中写错误消息。

 

跟踪正在运行的应用程序

希望跟踪应用程序常常是因为应用程序已经启动，而您希望查明应用程序为什么不工作了。与初始化示例一样，应用程序提供的错误消息或其他信息常常没有准确地指出问题。

试图锁定或访问另一个进程正在使用的资源会使应用程序看起来冻结了，没有响应。

strace 和 truss 都能够 “连接” 到正在运行的进程。连接到进程的跟踪与从命令行运行进程的跟踪相似，也产生程序正在执行的系统函数的列表。实际的跟踪从跟踪启动时执行的函数开始；对于在执行期间 “挂起” 的程序，跟踪应该会显示程序正在等待的函数。

要想跟踪正在运行的程序，需要指定要跟踪的进程的进程 ID (PID)。例如，在清单 6 中，跟踪的程序已经停止，但是没有报告错误。这里使用 ps 工具列出正在运行的进程（见清单 7）。

清单 7. 使用 ps 工具列出正在运行的进程

$ ps -ef|grep errlock mc 15779 15747 0 18:26:59 pts/2 0:00 ./errlock mc 15742 680 0 18:26:36 pts/3 0:00 ./errlock mc 15817 15784 0 18:28:44 pts/4 0:00 grep errlock mc 15734 680 0 18:25:00 pts/3 0:01 /usr/bin/emacs-nox errlock.c $ truss -p 15779 fcntl(3, F_SETLKW, 0x08047AC4) (sleeping...)

 

在输出中可以看到，已经调用了 de<fcntl()de< 函数，它要在一个文件上设置锁。在这里，这个函数会一直等待到成功地设置锁，然后才继续运行。不幸的是，另一个进程已经锁住了这个文件，所以第二个应用程序必须等待第一个应用程序使用完文件并释放锁。

对 于这种情况，truss 有点儿局限性：它无法指出要锁住哪个文件，也无法指出当前锁住了哪个文件，从而阻碍了第二个程序的执行。这是因为跟踪过程是在已经调用了打开文件的函数之 后启动的。truss 和 strace 只跟踪在它们执行期间调用的函数；它们无法查明已经调用的函数。

 

获取堆栈跟踪

可以看出，truss 对于监视整个程序很有用，但是对于监视已经启动的程序可能有点儿局限性。如果使用基于 SVR4 的 UNIX，比如 Solaris 或 AIX，那么 pstack 命令可能有帮助。

pstack 命令实际上属于一组进程检查命令，这些命令输出正在运行的进程的相关信息。其他工具包括 pfiles（输出进程使用的文件的列表）和 psig（显示信号和信号处理函数的列表）。

在使用这些命令时，需要指定进程的 PID。pstack 命令输出一个正在运行的进程的调用堆栈，显示在进程到达当前函数之前调用的函数。例如，对正在等待被锁住的文件的进程使用 pstack，会产生清单 8 中的输出。

清单 8. 对正在等待被锁住的文件的进程使用 pstack

$ pstack 15828 15828: ./errlock feef0877 fcntl (3, 7, 8047ac4) feedcd49 fcntl (3, 7, 8047ac4, 8050e74) + 91 08050f10 main (1, 8047b24, 8047b2c) + d8 08050cdc _start (1, 8047c08, 0, 8047c12, 8047c7d, 8047c8e) + 80

 

在这里，它没有提供我们需要的信息。现在试试 pfiles（见清单 9）。

清单 9. 使用 pfiles

$ pfiles 15856 15856: ./errlock Current rlimit: 256 file descriptors 0: S_IFCHR mode:0620 dev:292,0 ino:989038936 uid:101 gid:7 rdev:24,3 O_RDWR|O_NOCTTY|O_LARGEFILE /dev/pts/3 1: S_IFCHR mode:0620 dev:292,0 ino:989038936 uid:101 gid:7 rdev:24,3 O_RDWR|O_NOCTTY|O_LARGEFILE /dev/pts/3 2: S_IFCHR mode:0620 dev:292,0 ino:989038936 uid:101 gid:7 rdev:24,3 O_RDWR|O_NOCTTY|O_LARGEFILE /dev/pts/3 3: S_IFREG mode:0666 dev:182,65545 ino:198 uid:101 gid:10 size:0 O_RDWR advisory write lock set by process 15828 /export/home/mc/lockdemo

 

这些输出就比较有用了。可以看到进程已经打开的文件称为 lockdemo ，因为 truss 显示正在等待文件锁，所以可能是这个文件导致了问题。

truss 和 strace 都是被动的跟踪。可以查看正在执行的函数，但是无法了解关于正在发生的情况的详细信息，也无法更有针对性地指定要跟踪的东西和跟踪时要输出的信息。