강좌 & 팁
strace 와 관련된 2번째 글 입니다.
지난번에 이야기 하였듯이 strace는 bin 파일에서, system call 함수를 추적해 볼 수 있는 툴 입니다.
시스템 콜에서 주로 사용하는 옵션에 대하여 알아 보도록 하겠 습니다.
-------------------------------------
-c 각각의 시스템 콜에 대한 시간, 콜 개수, 에러 카운트
# strace -c /bin/ls
COPYING README config_20120308 fs mm serial_msg_ok_config usr
CREDITS REPORTING-BUGS config_crespo include net serial_msg_ok_config2 virt
Documentation arch crypto init patch-linux-2.6-samsung-2.6.35-samsung-73a7976-2011.04.17-full serial_msg_ok_config3
Kbuild block drivers ipc samples sound
MAINTAINERS build.sh falinux-patch.txt kernel scripts tags
Makefile config_20120302 firmware lib security tools
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
86.07 0.001427 1427 1 execve
13.93 0.000231 23 10 mprotect
0.00 0.000000 0 9 read
0.00 0.000000 0 6 write
0.00 0.000000 0 11 open
0.00 0.000000 0 13 close
0.00 0.000000 0 9 9 access
0.00 0.000000 0 3 brk
0.00 0.000000 0 2 ioctl
0.00 0.000000 0 3 munmap
0.00 0.000000 0 1 uname
0.00 0.000000 0 2 rt_sigaction
0.00 0.000000 0 1 rt_sigprocmask
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 24 mmap2
0.00 0.000000 0 11 fstat64
0.00 0.000000 0 2 getdents64
0.00 0.000000 0 1 fcntl64
0.00 0.000000 0 2 1 futex
0.00 0.000000 0 1 set_thread_area
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 statfs64
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.001658 116 10 total
-p pid 프로세스 아이디를 지정 한다.
# ps auxw | grep smb
root 433 0.0 0.2 17108 2392 ? Ss 09:50 0:00 smbd -F
root 537 0.0 0.1 17108 1100 ? S 09:50 0:00 smbd -F
root 30570 0.5 0.4 17408 4224 ? S 12:13 0:03 smbd -F
root 30635 0.0 0.0 4156 860 pts/0 S+ 12:24 0:00 grep --color=auto smb
# strace -p 30570
Process 30570 attached - interrupt to quit
select(34, [6 8 29 33], [], NULL, {19, 681092}) = 1 (in [29], left {16, 353723})
gettimeofday({1331781859, 79347}, NULL) = 0
read(29, "\0\0\0T", 4) = 4
read(29, "\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\1\0l\4\0\0\3\310"..., 84) = 84
fcntl64(23, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=416, len=1}, 0xbfe2d308) = 0
fcntl64(23, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=416, len=1}, 0xbfe2d368) = 0
fcntl64(23, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=416, len=1}, 0xbfe2d308) = 0
fcntl64(23, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=416, len=1}, 0xbfe2d368) = 0
geteuid32() = 0
getegid32() = 0
setgroups32(1, [65534]) = 0
setregid32(-1, 65534) = 0
getegid32() = 65534
setreuid32(-1, 65534) = 0
geteuid32() = 65534
stat64("dev", {st_mode=S_IFDIR|0755, st_size=4080, ...}) = 0
getcwd("/", 4096) = 2
lstat64("/dev", {st_mode=S_IFDIR|0755, st_size=4080, ...}) = 0
fcntl64(14, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=14672, len=1}, 0xbfe2d148) = 0
fcntl64(14, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=14672, len=1}, 0xbfe2d1a8) = 0
... ( 생략 ) ...
-r 각 시스템 콜에 대한 엔트리 상의 관련 타임 스탬프를 출력 한다. 이는 성공한 시스템 콜들이 시작된 시간 사이의 시간차를 기록 한다.
# strace -t -r /bin/ls
0.000000 execve("/bin/ls", ["/bin/ls"], [/* 15 vars */]) = 0
0.007983 brk(0) = 0x8d23000
0.001686 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.001442 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78fc000
0.001841 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000803 open("/etc/ld.so.cache", O_RDONLY) = 3
0.000884 fstat64(3, {st_mode=S_IFREG|0644, st_size=17524, ...}) = 0
0.001616 mmap2(NULL, 17524, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb78f7000
0.000372 close(3) = 0
0.000905 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000884 open("/lib/i386-linux-gnu/libselinux.so.1", O_RDONLY) = 3
0.000682 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300>\0\0004\0\0\0"..., 512) = 512
0.001753 fstat64(3, {st_mode=S_IFREG|0644, st_size=104116, ...}) = 0
0.001195 mmap2(NULL, 109440, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb49000
0.000377 mmap2(0xb62000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18) = 0xb62000
0.000749 close(3) = 0
0.001361 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000570 open("/lib/i386-linux-gnu/librt.so.1", O_RDONLY) = 3
0.000643 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\30\0\0004\0\0\0"..., 512) = 512
0.000705 fstat64(3, {st_mode=S_IFREG|0644, st_size=30684, ...}) = 0
0.001379 mmap2(NULL, 33364, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xfab000
0.000379 mmap2(0xfb2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6) = 0xfb2000
0.001575 close(3) = 0
0.000471 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000689 open("/lib/i386-linux-gnu/libacl.so.1", O_RDONLY) = 3
0.001073 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\23\0\0004\0\0\0"..., 512) = 512
0.001136 fstat64(3, {st_mode=S_IFREG|0644, st_size=26124, ...}) = 0
0.001137 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78f6000
0.000488 mmap2(NULL, 28964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x947000
0.000413 mmap2(0x94d000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5) = 0x94d000
0.001777 close(3) = 0
... ( 중간 생략 ) ...
0.000888 close(1) = 0
0.000369 munmap(0xb78fb000, 4096) = 0
0.000471 close(2) = 0
0.000967 exit_group(0) = ?
-t 각 라인에 시간을 출력 한다.
# strace -t /bin/echo
12:19:03 execve("/bin/echo", ["/bin/echo"], [/* 15 vars */]) = 0
12:19:03 brk(0) = 0x865e000
12:19:03 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12:19:03 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7771000
12:19:03 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
12:19:03 open("/etc/ld.so.cache", O_RDONLY) = 3
12:19:03 fstat64(3, {st_mode=S_IFREG|0644, st_size=17524, ...}) = 0
12:19:03 mmap2(NULL, 17524, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb776c000
12:19:03 close(3) = 0
12:19:03 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12:19:03 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
12:19:03 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220o\1\0004\0\0\0"..., 512) = 512
12:19:03 fstat64(3, {st_mode=S_IFREG|0755, st_size=1434180, ...}) = 0
12:19:03 mmap2(NULL, 1444360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x717000
12:19:03 mprotect(0x871000, 4096, PROT_NONE) = 0
12:19:03 mmap2(0x872000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15a) = 0x872000
12:19:03 mmap2(0x875000, 10760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x875000
12:19:03 close(3) = 0
12:19:03 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb776b000
12:19:03 set_thread_area({entry_number:-1 -> 6, base_addr:0xb776b8d0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
12:19:03 mprotect(0x872000, 8192, PROT_READ) = 0
12:19:03 mprotect(0x804d000, 4096, PROT_READ) = 0
12:19:03 mprotect(0xcb0000, 4096, PROT_READ) = 0
12:19:03 munmap(0xb776c000, 17524) = 0
12:19:03 brk(0) = 0x865e000
12:19:03 brk(0x867f000) = 0x867f000
12:19:03 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
12:19:03 fstat64(3, {st_mode=S_IFREG|0644, st_size=2781408, ...}) = 0
12:19:03 mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb756b000
12:19:03 close(3) = 0
12:19:03 fstat64(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 0), ...}) = 0
12:19:03 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7770000
12:19:03 write(1, "\n", 1
) = 1
12:19:03 close(1) = 0
12:19:03 munmap(0xb7770000, 4096) = 0
12:19:03 close(2) = 0
12:19:03 exit_group(0) = ?
-e 특정 시스템 콜을 지정하여 출력 한다.
# strace -e trace=open /bin/echo
open("/etc/ld.so.cache", O_RDONLY) = 3
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
-c -S sortby 옵션과 함께 사용되며 특정 컬럼을 정렬할 수 있다. 특정 컬럼값에는 time, calls, name 등으로 가능하다.
# strace -c -S name /bin/echo
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.00 0.000000 0 3 3 access
0.00 0.000000 0 3 brk
0.00 0.000000 0 5 close
90.66 0.002999 2999 1 execve
0.00 0.000000 0 4 fstat64
0.00 0.000000 0 8 mmap2
9.34 0.000309 77 4 mprotect
0.00 0.000000 0 2 munmap
0.00 0.000000 0 3 open
0.00 0.000000 0 1 read
0.00 0.000000 0 1 set_thread_area
0.00 0.000000 0 1 write
------ ----------- ----------- --------- --------- ----------------
100.00 0.003308 36 3 total
# strace -c -S time /bin/echo
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
90.32 0.002369 2369 1 execve
9.68 0.000254 127 2 munmap
0.00 0.000000 0 1 read
0.00 0.000000 0 1 write
0.00 0.000000 0 3 open
0.00 0.000000 0 5 close
0.00 0.000000 0 3 3 access
0.00 0.000000 0 3 brk
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 8 mmap2
0.00 0.000000 0 4 fstat64
0.00 0.000000 0 1 set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00 0.002623 36 3 total
