Linux trace introduction- 1 strace command

Linux provides system admin quite a few useful tools for troubleshooting. Strace is one of the tools which can provide the details of syscalls including parameters, values, and the consumed time.

Strace is a very complicated command with quite a few options; we need to understand some common options for daily usage:

-c -- count time, calls, and errors for each syscall and report summary

-f -- follow forks, -ff -- with output into separate files

-r -- print relative timestamp, -t -- absolute timestamp, -tt -- with usecs

-e expr -- a qualifying expression: option=[!]all or option=[!]val1[,val2]...

   options: trace, abbrev, verbose, raw, signal, read, or write

-o file -- send trace output to FILE instead of stderr

-p pid -- trace process with process id PID, may be repeated

Some examples

Try to ls a non-existing file

[root@X001 tmp]# strace ls notexisting

execve("/bin/ls", ["ls", "notexisting"], [/* 29 vars */]) = 0

brk(0)                                  = 0x1b7b000

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5b87f51000

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=38923, ...}) = 0

mmap(NULL, 38923, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5b87f47000

close(3)                                = 0

-----omitted-----

ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0

ioctl(1, TIOCGWINSZ, {ws_row=63, ws_col=237, ws_xpixel=0, ws_ypixel=0}) = 0

stat("notexisting", 0x1b7c0e0)          = -1 ENOENT (No such file or directory)

lstat("notexisting", 0x1b7c0e0)         = -1 ENOENT (No such file or directory)

open("/usr/share/locale/locale.alias", O_RDONLY) = 3

fstat(3, {st_mode=S_IFREG|0644, st_size=2512, ...}) = 0

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5b87f50000

read(3, "# Locale name alias data base.\n#"..., 4096) = 2512

read(3, "", 4096)                       = 0

close(3)                                = 0

exit_group(2)                           = ?

try to open an non-listening port only with network syscall enabled

[root@X001 tmp]# strace -e trace=network telnet localhost 9999

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=2395, groups=00000000}, [12]) = 0

sendto(3, "\24\0\0\0\26\0\1\3\342\346\vS\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\342\346\vS[\t\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\342\346\vS[\t\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) = 128

recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\342\346\vS[\t\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, IPPROTO_IP) = 3

connect(3, {sa_family=AF_INET, sin_port=htons(9999), sin_addr=inet_addr("127.0.0.1")}, 16) = 0

getsockname(3, {sa_family=AF_INET, sin_port=htons(33896), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0

socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 3

connect(3, {sa_family=AF_INET6, sin6_port=htons(9999), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0

getsockname(3, {sa_family=AF_INET6, sin6_port=htons(57576), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0

Trying ::1...

socket(PF_INET6, SOCK_STREAM, IPPROTO_TCP) = 3

connect(3, {sa_family=AF_INET6, sin6_port=htons(9999), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = -1 ECONNREFUSED (Connection refused)

telnet: connect to address ::1: Connection refused

Trying 127.0.0.1...

socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3

setsockopt(3, SOL_IP, IP_TOS, [16], 4)  = 0

connect(3, {sa_family=AF_INET, sin_port=htons(9999), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 ECONNREFUSED (Connection refused)

telnet: connect to address 127.0.0.1: Connection refused

[root@X001 tmp]#

try to get the summary of the syscalls
[root@X001 tmp]# strace -c -e trace=network telnet localhost 9999
Trying ::1...
telnet: connect to address ::1: Connection refused
Trying 127.0.0.1...
telnet: connect to address 127.0.0.1: Connection refused
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.022996        3285         7           socket
  0.00    0.000000           0         6         4 connect
  0.00    0.000000           0         1           sendto
  0.00    0.000000           0         3           recvmsg
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         3           getsockname
  0.00    0.000000           0         1           setsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.022996                    22         4 total
[root@X001 tmp]#
 

to understand the output of strace, we need to have a brief idea about the linux internal and syscalls