Strace (linux trace system calls and signals)

1.Strace ?

strace는 Linux상에서 실행프로그램에 호출되거나 받은 시스템콜을 추적 하는 디버깅 툴이다.

python, luby 등과 같은 스크립트 언어들은 사람이 직관적으로 소스를 보면서 문제점을 파악하기 쉽지만

소스코드가 없고 프로그램 실행만 되어 있는 프로그램의 호출되거나 받은 시스템콜을 추적 하여 문제점을 파악하기 위한

좋은 정보를 얻을 수 있다.

실제로 실무에서 응용프로그램에 대하여 strace 로, 네트워크 상으로는 tcpdump(or tshrark ) 를 이용하여 문제점을 추적하는데 

소요되는 시간을 줄일 수 있었다.

2.Strace 사용 방법 

아래와 같이 특정 명령어(binary)를 실행 하면 해당 system call 과정을 추적 할 수 있다.

간단하게 구조를 보면 execve,mmap,open 등 과 같은 call 을 확인 가능 하다.

[root@CY2 ~]# strace whoami
execve("/usr/bin/whoami", ["whoami"], [/* 29 vars */]) = 0
brk(0)                                  = 0x135c000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f36000
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=27683, ...}) = 0
mmap(NULL, 27683, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7febd9f2f000
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\0000\356\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1923352, ...}) = 0
mmap(NULL, 3750184, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7febd9984000
mprotect(0x7febd9b0e000, 2097152, PROT_NONE) = 0
mmap(0x7febd9d0e000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18a000) = 0x7febd9d0e000
mmap(0x7febd9d14000, 14632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7febd9d14000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f2e000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f2d000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f2c000
arch_prctl(ARCH_SET_FS, 0x7febd9f2d700) = 0
mprotect(0x7febd9d0e000, 16384, PROT_READ) = 0
mprotect(0x7febd9f37000, 4096, PROT_READ) = 0
munmap(0x7febd9f2f000, 27683)           = 0
brk(0)                                  = 0x135c000
brk(0x137d000)                          = 0x137d000
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=99160384, ...}) = 0
mmap(NULL, 99160384, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7febd3af2000
close(3)                                = 0
geteuid()                               = 0
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
open("/etc/nsswitch.conf", O_RDONLY)    = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=1688, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f35000
read(3, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1688
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7febd9f35000, 4096)            = 0
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=27683, ...}) = 0
mmap(NULL, 27683, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7febd9f2f000
close(3)                                = 0
open("/lib64/libnss_files.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360!\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=65960, ...}) = 0
mmap(NULL, 2151824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7febd38e4000
mprotect(0x7febd38f1000, 2093056, PROT_NONE) = 0
mmap(0x7febd3af0000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xc000) = 0x7febd3af0000
close(3)                                = 0
mprotect(0x7febd3af0000, 4096, PROT_READ) = 0
munmap(0x7febd9f2f000, 27683)           = 0
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fstat(3, {st_mode=S_IFREG|0644, st_size=1194, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f35000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1194
close(3)                                = 0
munmap(0x7febd9f35000, 4096)            = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7febd9f35000
write(1, "root\n", 5root
)                   = 5
close(1)                                = 0
munmap(0x7febd9f35000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

특정 프로그램의 pid 를 확인 하여서 trace 가능 하다.

아래는 tail 로 특정 로그를 화면에 출력하는 프로세스를 strace 로 확인 하는 것으로 특정 하일을 지속적으로 read/write 하는 과정을 

확인 할 수 있다.

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

root@CY2 ~]# ps aux | grep tail
root      18010  0.0  0.0   4212   300 pts/1    S+   Oct06   0:59 tail -f /pinpoint/quickstart/logs/quickstart.web.log

[root@CY2 ~]# strace -p 18010   
Process 18010 attached
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
fstat(3, {st_mode=S_IFREG|0644, st_size=148229767, ...}) = 0
read(3, "2017-10-08 05:49:50 [INFO ](o.a."..., 8192) = 197
write(1, "2017-10-08 05:49:50 [INFO ](o.a."..., 197) = 197
read(3, "", 8192)                       = 0
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
fstat(3, {st_mode=S_IFREG|0644, st_size=148230353, ...}) = 0
read(3, "2017-10-08 05:49:50 [WARN ](o.a."..., 8192) = 586
write(1, "2017-10-08 05:49:50 [WARN ](o.a."..., 586) = 586
read(3, "", 8192)                       = 0
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
fstat(3, {st_mode=S_IFREG|0644, st_size=148230544, ...}) = 0
read(3, "2017-10-08 05:49:50 [INFO ](o.a."..., 8192) = 191
write(1, "2017-10-08 05:49:50 [INFO ](o.a."..., 191) = 191

또한 -e  expr 옵션을 통하여 특정signal 이나 함수만 보여 줄 수 있다.

아래는 tail 로 로그를 읽는 프로세스에서 read 부분만 화면에 출력 해준다.

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

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

[root@CY2 ~]# strace  -e read -p 18010
Process 18010 attached
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
read(3, "2017-10-08 05:53:41 [INFO ](o.a."..., 8192) = 715
read(3, "", 8192)                       = 0
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
read(3, "2017-10-08 05:53:41 [INFO ](o.a."..., 8192) = 197

여러개 지정시 아래와 같이 설정하여 출력이 가능 하다.

[root@CY2 ~]# strace   -e trace=write,read  -p 18010            
Process 18010 attached
read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
read(3, "2017-10-08 06:12:19 [INFO ](o.a."..., 8192) = 191
write(1, "2017-10-08 06:12:19 [INFO ](o.a."..., 191) = 191
read(3, "2017-10-08 06:12:19 [WARN ](o.a."..., 8192) = 586

특정 프로세스 디버깅시 가장 잘 봐야 할 부분이 특정 system call 의 발생 시간인데,

timestamp 를 기록 하기 위해서는 -t,-tt,-ttt 옵션을 통하여 확인 할 수 있다.

일반적인 시간 포맷은 -t ,microseconds 까지 나타내기 위해서는 -tt , unixtime 으로 확인 하기 위해서는 -ttt 옵션을 이용 한다.

#-t          Prefix each line of the trace with the time of day.

#-tt         If given twice, the time printed will include the microseconds.

#-ttt        If given thrice, the time printed will include the microseconds and the leading portion will be printed as the

                   number of seconds since the epoch.

[root@CY2 ~]# strace -p 18010 -t      
14:55:44 read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
14:55:44 fstat(3, {st_mode=S_IFREG|0644, st_size=148959620, ...}) = 0
[root@CY2 ~]# strace -p 18010 -tt
14:55:50.083869 read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
14:55:50.367701 fstat(3, {st_mode=S_IFREG|0644, st_size=148970095, ...}) = 0
[root@CY2 ~]# strace -p 18010 -ttt
1507442152.313022 read(4, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 61) = 16
1507442152.372698 fstat(3, {st_mode=S_IFREG|0644, st_size=148975372, ...}) = 0

strace  기본적으로 single-threaded 에 대하여 디버깅 한다. 그렇기 때문에 fork 등으로 자식 프로세스를 갖는 경우에 -f

옵션을 통하여 multi-threaded 되고 있는 프로세스에 대하여 디버깅 가능 하다.

-f 를 줄 경우 출력 앞부분에  multi-threaded로  인하여 다른 pid 번호와 함께 출력이 된다.

#-f          Trace child processes as they are created by currently traced processes as a result of the  fork(2),  vfork(2)

                   and clone(2) system calls. Note that -p PID -f will attach all threads of process PID if it is multi-threaded,

                   not only thread with thread_id = PID.

[root@CY2 ~]# strace -p 121110
Process 121110 attached
futex(0x7f79b234b9d0, FUTEX_WAIT, 7413, 
[root@CY2 ~]# strace -p 121110 -f
Process 121110 attached with 222 threads
[pid 30205] futex(0x2120854, FUTEX_WAIT_PRIVATE, 1265, NULL <unfinished ...>
[pid 30204] futex(0x7f7978001a54, FUTEX_WAIT_PRIVATE, 1241, NULL <unfinished ...>
[pid 30191] futex(0x7f7978015154, FUTEX_WAIT_PRIVATE, 1399, NULL <unfinished ...>
[pid 30190] futex(0x7f796c0a6b54, FUTEX_WAIT_PRIVATE, 325, NULL <unfinished ...>
...

레포트 형태로 summary 해서 출력 하기 위해서 -c 옵션으로 통하여 확인 가능 하다

일정 시간이 지난뒤 ctrl+c 를  SIGINT signal을 발생 하면 아래와 같은 결과를 확인 할 수 있다.

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

[root@CY2 ~]# strace   -c -p 18010                   
Process 18010 attached
^CProcess 18010 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0        15           read
  0.00    0.000000           0         5           write
  0.00    0.000000           0         5           fstat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    25           total

Ref : http://www.thegeekstuff.com/2011/11/strace-examples/

Ref : https://www.joinc.co.kr/w/Site/Development/Env/strace