Mostly Harmless

truss -d -u on syscall stubs

Using truss -d (or -D) gives timing information which may help identify where delays are occurring in a process. However, it does not timestamp both the exit and entry points on a system call so it is not always obvious if the delay is really in the system call or in the program's cogitations.

Dtrace or TNF probes with microstate accounting will get accurate per-system call duration information, but there is also a cheap and cheerful way using truss itself where these other methods are not available or appropriate and where you don't mind the relatively high probe effect of truss.

Since system calls are made from within libc stubs you can use the library call tracing facility of truss to trace entry and exit of the stub. So for open[64](), close() and various read flavours you could use:

truss -d -u "libc::*_open*,*_close,*_*read*" command_or_-p_PID

$ truss -d -u "libc::*_open*,*_close,*_*read*" wc -l /etc/group

Base time stamp:  1163198817.8709  [ Fri Nov 10 15:46:57 MST 2006 ]
16824:   0.0000 execve("/usr/bin/wc", 0xFFBFF144, 0xFFBFF154)  argc = 3
16824:   argv: wc -l /etc/group
16824:   0.0097 resolvepath("/usr/bin/wc", "/usr/bin/wc", 1023) = 11
16824:   0.0099 resolvepath("/usr/lib/ld.so.1", "/usr/lib/ld.so.1", 1023) = 16
16824:   0.0101 stat("/usr/bin/wc", 0xFFBFEF18)                 = 0
...
16824:   0.0496 -> libc:_open64(0xffbff296, 0x0, 0x1b6, 0x0)
16824:   0.0500   -> libc:__open64(0xffbff296, 0x0, 0x1b6, 0x0)
16824:   0.0504 open64("/etc/group", O_RDONLY)                  = 3
16824:   0.0505   <- libc:__open64() = 3
16824:   0.0508 <- libc:_open64() = 3
16824:   0.0511 fstat64(3, 0xFFBFEF10)                          = 0
16824:   0.0512 brk(0x00024AC8)                                 = 0
16824:   0.0513 brk(0x00026AC8)                                 = 0
16824:   0.0514 fstat64(3, 0xFFBFEDB8)                          = 0
16824:   0.0515 ioctl(3, TCGETA, 0xFFBFEE9C)                    Err#25 ENOTTY
16824:   0.0516 -> libc:_read(0x3, 0x23b44, 0x2000, 0xff28b5f4)
16824:   0.0520 read(3, " r o o t : : 0 : r o o t".., 8192)     = 8192
16824:   0.0521 <- libc:_read() = 8192
...

Posted at 10:58PM Nov 10, 2006 by John Alderson in Code  |  Comments[0]