- ltrace is a tracing tool used for tracing the library function calls made by a running process.
- strace is a tracing tool used for tracing the system calls made by a running process and signals received by the process
Note : While monitoring a running process with these tracing tools, the performance is the process is greatly reduced. So these tracing tools shall be used only when we need to collect data.
Library and System function calls
Basically functions are divided into two categories
- Library function calls
- System function calls
The functions which are part of the programming language library are known as library functions. Say, for instance, in C language use of standard C library string manipulation functions like strcmp(), strlen() are examples of library function calls.
The system function calls are part of the OS and are executed in the system kernel. The functions which change the execution mode of the program from user mode to kernel mode of an OS are known as system function calls. These function calls are entry point into the kernel and therefore NOT linked into the program or code. These are not portable calls.
Because the system calls are part of the OS, the program has to make a context switch to the kernel, when a system call is made. The time used for executing the system call function is assigned to the OS and not the user program.
Library functions can be debugged easily using a debugger while System calls cannot be debugged as they are executed by the kernel.
Tracing system calls with strace
strace can either run a new command and trace its system calls, or you can attach strace to an already running command.
Each line of the strace command's output contains the system call name, followed by its arguments in parenthesis and its return value.
$ strace pwd
execve("/bin/pwd", ["pwd"], [/* 27 vars */]) = 0
brk(0) = 0x11cc000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74274c9000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=91089, ...}) = 0
mmap(NULL, 91089, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f74274b2000
close(3) = 0
open("/lib64/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355!M<\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1922112, ...}) = 0
mmap(0x3c4d200000, 3745960, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3c4d200000
mprotect(0x3c4d389000, 2097152, PROT_NONE) = 0
mmap(0x3c4d589000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x189000) = 0x3c4d589000
mmap(0x3c4d58e000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3c4d58e000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74274b1000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74274b0000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74274af000
arch_prctl(ARCH_SET_FS, 0x7f74274b0700) = 0
mprotect(0x3c4d589000, 16384, PROT_READ) = 0
mprotect(0x3c4d01f000, 4096, PROT_READ) = 0
munmap(0x7f74274b2000, 91089) = 0
brk(0) = 0x11cc000
brk(0x11ed000) = 0x11ed000
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=99158576, ...}) = 0
mmap(NULL, 99158576, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f742161e000
close(3) = 0
getcwd("/home/foo", 4096) = 11
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) = 0x7f74274c8000
write(1, "/home/foo\n", 11/home/foo
) = 11
close(1) = 0
munmap(0x7f74274c8000, 4096) = 0
close(2) = 0
exit_group(0) = ?
Attaching strace to a already running process
# strace -p 3126
Process 3126 attached - interrupt to quit
accept4(4, ^C <unfinished ...>
Process 3126 detached
# strace -p 1993
Process 1993 attached - interrupt to quit
select(0, NULL, NULL, NULL, {0, 553110}) = 0 (Timeout)
wait4(-1, 0x7fff99e4b67c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
wait4(-1, 0x7fff99e4b67c, WNOHANG|WSTOPPED, NULL) = 0
The -e option understands several sub-options and arguments.
$ strace -e poll,select,connect,recvfrom,sendto telnet localhost 80
sendto(3, "\24\0\0\0\26\0\1\3\10\f\363P\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
Trying 127.0.0.1...
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
Connected to localhost.
Escape character is '^]'.
select(4, [0 3], [], [3], {0, 0}) = 0 (Timeout)
select(4, [0 3], [], [3],
To trace network related system calls alone
$ strace -e trace=network nc -v -z google.com 80
socket(PF_NETLINK, SOCK_RAW, 0) = 3
bind(3, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
getsockname(3, {sa_family=AF_NETLINK, pid=6792, groups=00000000}, [12]) = 0
sendto(3, "\24\0\0\0\26\0\1\3\217\r\363P\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"0\0\0\0\24\0\2\0\217\r\363P\210\32\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\217\r\363P\210\32\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 192
recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\217\r\363P\210\32\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20
socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
sendto(3, "\323\211\1\0\0\1\0\0\0\0\0\0\6google\3com\0\0\1\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
sendto(3, "\251.\1\0\0\1\0\0\0\0\0\0\6google\3com\0\0\34\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
recvfrom(3, "\323\211\201\200\0\1\0\v\0\0\0\0\6google\3com\0\0\1\0\1\300\f\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 204
recvfrom(3, "\251.\201\200\0\1\0\1\0\0\0\0\6google\3com\0\0\34\0\1\300\f\0\34"..., 1844, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 56
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.199")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(45205), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.201")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(32846), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.196")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(34565), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.197")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(39205), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.206")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(58868), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.194")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(60579), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.192")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(58725), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.200")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(55188), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.198")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(43411), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.195")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(53734), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.193")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(57004), sin_addr=inet_addr("192.168.1.7")}, [16]) = 0
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "2404:6800:4007:803::1000", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = -1 ENETUNREACH (Network is unreachable)
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.236.199")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [5573484639458164736], [4]) = 0
socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
Connection to google.com 80 port [tcp/http] succeeded!
To trace all child processes of a process, use -f
# strace -f httpd
The -c calculates the time the kernel spent on each system call:
# strace -c pwd
/root
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
-nan 0.000000 0 1 read
-nan 0.000000 0 1 write
-nan 0.000000 0 3 open
-nan 0.000000 0 5 close
-nan 0.000000 0 4 fstat
-nan 0.000000 0 10 mmap
-nan 0.000000 0 3 mprotect
-nan 0.000000 0 2 munmap
-nan 0.000000 0 3 brk
-nan 0.000000 0 1 1 access
-nan 0.000000 0 1 execve
-nan 0.000000 0 1 getcwd
-nan 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.000000 36 1 total
Tracing Library Calls with ltrace
By default, ltrace uses /etc/ltrace.conf or ~/.ltrace.conf configuration files. However, an alternative configuration file can be specified with -F option.
# ltrace pwd
(0, 0, 0, 0x7f36de024000, 88) = 0x3c4d021160
__libc_start_main(0x401f60, 1, 0x7fff5fbca8a8, 0x404890, 0x404880 <unfinished ...>
getenv("POSIXLY_CORRECT") = NULL
strrchr("pwd", '/') = NULL
setlocale(6, "") = "en_US.UTF-8"
bindtextdomain("coreutils", "/usr/share/locale") = "/usr/share/locale"
textdomain("coreutils") = "coreutils"
__cxa_atexit(0x4029b0, 0, 0, 0x736c6974756572, 0x3c4d58eee8) = 0
getopt_long(1, 0x7fff5fbca8a8, "LP", 0x606040, NULL) = -1
getcwd(NULL, 0) = ""
puts("/root"/root
) = 6
free(0x1679030) = <void>
exit(0 <unfinished ...>
__fpending(0x3c4d58d780, 0, 0x3c4d58e330, 0x3c4d58e330, 0xffffffff) = 0
fclose(0x3c4d58d780) = 0
__fpending(0x3c4d58d860, 0, 0x3c4d58ee10, 0, 0x7f36de023700) = 0
fclose(0x3c4d58d860) = 0
+++ exited (status 0) +++
ltrace can also used to trace system calls with -S option. The system calls shall be specified with "SYS" in the output
# ltrace -S pwd
SYS_brk(NULL) = 0x1d5b000
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f5ed7259000
SYS_access(0x3c4ce1cb00, 4, 0x3c4ce00158, 0, 0) = -2
SYS_open("/etc/ld.so.cache", 0, 01) = 4
SYS_fstat(4, 0x7fffa4182e10, 0x7fffa4182e10, 0, 0xfefefefefefefeff) = 0
SYS_mmap(0, 91089, 1, 2, 4) = 0x7f5ed7242000
SYS_close(4) = 0
SYS_open("/lib64/libc.so.6", 0, 00) = 4
SYS_read(4, "\177ELF\002\001\001\003", 832) = 832
SYS_fstat(4, 0x7fffa4182e60, 0x7fffa4182e60, 4, 0x3c4d021188) = 0
SYS_mmap(0x3c4d200000, 0x3928a8, 5, 2050, 4) = 0x3c4d200000
SYS_mprotect(0x3c4d389000, 0x200000, 0, 1, 4) = 0
SYS_mmap(0x3c4d589000, 20480, 3, 2066, 4) = 0x3c4d589000
SYS_mmap(0x3c4d58e000, 18600, 3, 50, 0xffffffff) = 0x3c4d58e000
SYS_close(4) = 0
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f5ed7241000
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f5ed7240000
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f5ed723f000
SYS_arch_prctl(4098, 0x7f5ed7240700, 0x7f5ed723f000, 34, 0xffffffff) = 0
SYS_mprotect(0x3c4d589000, 16384, 1, 34, 32768) = 0
SYS_mprotect(0x3c4d01f000, 4096, 1, 34, 32768) = 0
(0, 0, 0, 0x7f5ed7241000, 88) = 0x3c4d021160
SYS_munmap(0x7f5ed7242000, 91089) = 0
__libc_start_main(0x401f60, 1, 0x7fffa4183808, 0x404890, 0x404880 <unfinished ...>
getenv("POSIXLY_CORRECT") = NULL
strrchr("pwd", '/') = NULL
setlocale(6, "" <unfinished ...>
SYS_brk(NULL) = 0x1d5b000
SYS_brk(0x1d7c000) = 0x1d7c000
SYS_open("/usr/lib/locale/locale-archive", 0, 011526160020) = 4
SYS_fstat(4, 0x3c4d58e040, 0x3c4d58e040, 5, 4) = 0
SYS_mmap(0, 0x5e90a30, 1, 2, 4) = 0x7f5ed13ae000
SYS_close(4) = 0
<... setlocale resumed> ) = "en_US.UTF-8"
bindtextdomain("coreutils", "/usr/share/locale") = "/usr/share/locale"
textdomain("coreutils") = "coreutils"
__cxa_atexit(0x4029b0, 0, 0, 0x736c6974756572, 0x3c4d58eee8) = 0
getopt_long(1, 0x7fffa4183808, "LP", 0x606040, NULL) = -1
getcwd(NULL, 0 <unfinished ...>
SYS_getcwd("/root", 4096) = 6
<... getcwd resumed> ) = ""
puts("/root" <unfinished ...>
SYS_fstat(1, 0x7fffa41835d0, 0x7fffa41835d0, 4096, 0x3c4d58d780) = 0
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f5ed7258000
SYS_write(1, "/root\n", 6/root
) = 6
<... puts resumed> ) = 6
free(0x1d5c030) = <void>
exit(0 <unfinished ...>
__fpending(0x3c4d58d780, 0, 0x3c4d58e330, 0x3c4d58e330, 0xffffffff) = 0
fclose(0x3c4d58d780 <unfinished ...>
SYS_close(1) = 0
SYS_munmap(0x7f5ed7258000, 4096) = 0
<... fclose resumed> ) = 0
__fpending(0x3c4d58d860, 0, 0x3c4d58ee10, 0, 0x7f5ed7240700) = 0
fclose(0x3c4d58d860 <unfinished ...>
SYS_close(2) = 0
<... fclose resumed> ) = 0
SYS_exit_group(0 <no return ...>
+++ exited (status 0) +++
No comments:
Post a Comment