1 straceコマンドとは?
プロセスが実行するシステムコールをトレースするコマンドです。なお、関数のトレースには、ltraceコマンドを使います。ltraceコマンドは、ltraceコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。
2 検証環境
CentOS版数は以下のとおりです。
[root@server ~]# cat /etc/redhat-release
CentOS Linux release 7.9.2009 (Core)
カーネル版数は以下のとおりです。
[root@server ~]# uname -r
3.10.0-1160.el7.x86_64
3 インストール方法
straceパッケージをインストールします。
[root@server ~]# yum -y install strace
版数を確認します。
[root@server ~]# strace -V
strace -- version 4.24
4 オプション一覧
[root@server ~]# strace -h
usage: strace [-CdffhiqrtttTvVwxxy] [-I n] [-e expr]...
[-a column] [-o file] [-s strsize] [-P path]...
-p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]
or: strace -c[dfw] [-I n] [-e expr]... [-O overhead] [-S sortby]
-p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]
Output format:
-a column alignment COLUMN for printing syscall results (default 40)
-i print instruction pointer at time of syscall
-k obtain stack trace between each syscall
-o file send trace output to FILE instead of stderr
-q suppress messages about attaching, detaching, etc.
-r print relative timestamp
-s strsize limit length of print strings to STRSIZE chars (default 32)
-t print absolute timestamp
-tt print absolute timestamp with usecs
-T print time spent in each syscall
-x print non-ascii strings in hex
-xx print all strings in hex
-X format set the format for printing of named constants and flags
-y print paths associated with file descriptor arguments
-yy print protocol specific information associated with socket file descriptors
Statistics:
-c count time, calls, and errors for each syscall and report summary
-C like -c but also print regular output
-O overhead set overhead for tracing syscalls to OVERHEAD usecs
-S sortby sort syscall counts by: time, calls, name, nothing (default time)
-w summarise syscall latency (default is system time)
Filtering:
-e expr a qualifying expression: option=[!]all or option=[!]val1[,val2]...
options: trace, abbrev, verbose, raw, signal, read, write, fault, inject, kvm
-P path trace accesses to path
Tracing:
-b execve detach on execve syscall
-D run tracer process as a detached grandchild, not as parent
-f follow forks
-ff follow forks with output into separate files
-I interruptible
1: no signals are blocked
2: fatal signals are blocked while decoding syscall (default)
3: fatal signals are always blocked (default if '-o FILE PROG')
4: fatal signals and SIGTSTP (^Z) are always blocked
(useful to make 'strace -o FILE PROG' not stop on ^Z)
Startup:
-E var remove var from the environment for command
-E var=val put var=val in the environment for command
-p pid trace process with process id PID, may be repeated
-u username run command as username handling setuid and/or setgid
Miscellaneous:
-d enable debug output to stderr
-v verbose mode: print unabbreviated argv, stat, termios, etc. args
-h print help message
-V print version
5.1 事前準備
straceの対象となるテストプログラムを作成します。
[root@master1 strace]# vi tp.c
[root@master1 strace]# cat tp.c
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <time.h>
#include <sys/stat.h>
int main(int argc, char *argv[])
{
int fd;
struct timespec req;
char str[] = "0123456789";
req.tv_sec = 2;
req.tv_nsec = 0;
for(;;) {
fd = open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
write(fd, str, (size_t)sizeof(str));
close(fd);
nanosleep(&req, NULL);
}
}
テストプログラムをコンパイルします。
[root@server ~]# gcc -Wall -o tp tp.c
実行ファイルを確認します。tpという名前の実行ファイルが作成されたことがわかります。
[root@server ~]# ls -l tp*
-rwxr-xr-x. 1 root root 8552 12月 26 09:11 tp
-rw-r--r--. 1 root root 425 12月 26 09:11 tp.c
5.2 実行結果
テストプログラムを実行します。
[root@server ~]# ./tp
もう１つターミナルを開きます。
テストプログラムのPIDを確認すると、PID=2357であることがわかります。
[root@server ~]# ps -C tp
PID TTY TIME CMD
2357 pts/0 00:00:00 tp
straceを実行します。-pはテストプログラムのPIDを指定します。
open,write,close,nanosleepの順にシステムコールを実行していることがわかります。
[root@server ~]# strace -p 2357
strace: Process 2357 attached
restart_syscall(<... resuming interrupted read ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, "0123456789\0", 11) = 11
close(3) = 0
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
6 時刻関連
6.1 システムコール実行時刻（秒単位）を表示する方法(-t)
-tはシステムコールの実行時刻を秒単位で表示（左端の時刻）するオプションです。
[root@server ~]# strace -t -p 2357
strace: Process 2357 attached
09:35:32 restart_syscall(<... resuming interrupted read ...>) = 0
09:35:33 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
09:35:33 write(3, "0123456789\0", 11) = 11
09:35:33 close(3) = 0
09:35:33 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
6.2 システムコール実行時刻（マイクロ秒単位）を表示する方法(-tt)
-ttはシステムコールの実行時刻をマイクロ秒単位で表示（左端の時刻）するオプションです。
[root@server ~]# strace -tt -p 2357
strace: Process 2357 attached
09:36:31.183463 restart_syscall(<... resuming interrupted read ...>) = 0
09:36:31.953965 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
09:36:31.958852 write(3, "0123456789\0", 11) = 11
09:36:31.960077 close(3) = 0
09:36:31.960550 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
6.3 システムコール実行時間を表示する方法(-T)
-Tはシステムコールを実行してから完了するまでの実行時間を表示するオプションです。右端の<>に囲まれた部分が、システムコールの実行時間を表していて、マイクロ秒単位の精度で表示されていることがわかります。また、nanosleepシステムコールは、スリープ時間に指定した2秒より少し時間がかかってシステムコールが完了していることがわかります(★印)。
[root@server ~]# strace -T -p 2357
strace: Process 2357 attached
restart_syscall(<... resuming interrupted read ...>) = 0 <0.656177>
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.002957>
write(3, "0123456789\0", 11) = 11 <0.000485>
close(3) = 0 <0.000868>
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0 ★<2.010235>
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.003676>
write(3, "0123456789\0", 11) = 11 <0.000451>
close(3) = 0 <0.000254>
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0 ★<2.003008>
-snip-
6.4 システムコールの実行間隔を表示する方法(-r)
-rはシステムコールの実行間隔を表示するオプションです。時刻T1と時刻T2にシステムコールを実行したとき、システムコールの実行間隔(T2-T1)を表示します。
[root@server ~]# strace -r -p 2357
strace: Process 2357 attached
0.000000 restart_syscall(<... resuming interrupted read ...>) = 0
0.493108 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
0.000888 write(3, "0123456789\0", 11) = 11
0.000647 close(3) = 0
0.000977 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
2.004976 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
0.005188 write(3, "0123456789\0", 11) = 11
0.000544 close(3) = 0
0.000317 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
2.003285 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
0.000197 write(3, "0123456789\0", 11) = 11
0.000096 close(3) = 0
0.000359 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
7 実行結果を絞り込む方法(-e trace)
openシステムコールだけを表示してみます。
[root@server ~]# strace -t -e trace=open -p 2357
strace: Process 2357 attached
10:33:39 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:33:41 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:33:43 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
-snip-
openシステムコールとcloseシステムコールを表示してみます。
[root@server ~]# strace -t -e trace=open,close -p 2357
strace: Process 2357 attached
10:34:49 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:34:49 close(3) = 0
10:34:51 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:34:51 close(3) = 0
-snip-
7.2 特定のシステムコールをstrace実行結果から除外する方法(-e 'trace=!システムコール名')
write以外のシステムコールを表示してみます。
[root@server ~]# strace -t -e 'trace=!write' -p 2357
strace: Process 2357 attached
10:36:31 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:36:31 close(3) = 0
10:36:31 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
10:36:33 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
10:36:33 close(3) = 0
10:36:33 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
7.3 複数のシステムコールをstrace実行結果から除外する方法(-e 'trace=!システムコール名,システムコール名')
openとclose以外のシステムコールを表示してみます。
[root@server ~]# strace -t -e 'trace=!open,close' -p 2357
strace: Process 2357 attached
10:38:03 restart_syscall(<... resuming interrupted read ...>) = 0
10:38:04 write(3, "0123456789\0", 11) = 11
10:38:04 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
10:38:06 write(3, "0123456789\0", 11) = 11
10:38:06 nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
7.4 ネットワーク関連のシステムコールを表示する方法(-e trace=%network)
digコマンドを使って、首相官邸のサーバにアクセスします。
socketやgetsockname等のネットワーク関連のシステムコールが表示されていることがわかります。
[root@server ~]# strace -e trace=%network dig www.kantei.go.jp +short
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 3
socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 3
getsockname(3, {sa_family=AF_INET6, sin6_port=htons(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0
socket(AF_UNIX, SOCK_STREAM, 0) = 3
13.33.9.26
13.33.9.75
13.33.9.99
13.33.9.45
--- SIGTERM {si_signo=SIGTERM, si_code=SI_TKILL, si_pid=3098, si_uid=0} ---
+++ exited with 0 +++
7.5 シグナルのシステムコールだけを表示する方法(-e trace=%signal)
sleepコマンドを実行します。
[root@server ~]# sleep 300&
[1] 1820
プロセスの状態を確認します。
[root@server ~]# ps -C sleep
PID TTY TIME CMD
1820 pts/0 00:00:00 sleep
シグナルのシステムコールだけを表示してみます。killシステムコールが実行されていることがわかります。
[root@server ~]# strace -e trace=%signal kill -9 1820
kill(1820, SIGKILL) = 0
+++ exited with 0 +++
[1]+ 強制終了 sleep 300
8 指定ファイルをアクセスしたときにトレースを表示する方法(-P)
8.1 事前準備
テストプログラムを作成します。
[root@server ~]# vi tp1.c
[root@server ~]# cat tp.c
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <time.h>
int main(int argc, char *argv[])
{
int fd;
struct timespec req;
req.tv_sec = 1;
req.tv_nsec = 0;
printf("path=%s\n", argv[1]);
for(;;) {
fd = open(argv[1], O_RDONLY, 0444);
close(fd);
nanosleep(&req, NULL);
}
}
テストプログラムのコンパイルします
[root@server ~]# gcc -Wall -o tp tp.c
作成したテストプログラムを確認します。
[root@server ~]# ls -l tp*
-rwxr-xr-x. 1 root root 8552 12月 26 11:04 tp
-rw-r--r--. 1 root root 343 12月 26 11:02 tp.c
上記で作成したテストプログラムが参照するテスト用ファイルを作成します。
[root@server ~]# touch /tmp/test.txt
8.2 実行結果
テストプログラムを実行します。このときアクセスするファイルは/tmp/test.txtを指定します。
[root@server ~]# ./tp /tmp/test.txt
path=/tmp/test.txt
もう1つターミナルを開いて、テストプログラムのPIDを確認します。
[root@server ~]# ps -C tp
PID TTY TIME CMD
1882 pts/0 00:00:00 tp
straceを実行します。このとき、-Pのパラメータとして、/tmp/test.txtを指定します。
/tmp/test.txtにアクセスするたびに、straceが実行結果を表示していることがわかる。
[root@server ~]# strace -t -P /tmp/test.txt -p 1882
strace: Process 1882 attached
11:10:43 open("/tmp/test.txt", O_RDONLY) = 3
11:10:43 close(3) = 0
11:10:44 open("/tmp/test.txt", O_RDONLY) = 3
11:10:44 close(3) = 0
11:10:45 open("/tmp/test.txt", O_RDONLY) = 3
11:10:45 close(3) = 0
-snip-
9 複数プロセス/スレッドに対してstraceを実行する方法
9.1 動作中の複数プロセス対するstrace実行方法(-p pid,pid,...)
httpdを起動します。
[root@server ~]# systemctl start httpd
psコマンドを実行すると、PID=5797が親プロセス、他は子プロセスであることがわかります。
[root@server ~]# ps -C httpd -o comm,pid,ppid
COMMAND PID PPID
httpd 5797 1
httpd 5798 5797
httpd 5799 5797
httpd 5800 5797
httpd 5801 5797
httpd 5802 5797
straceを実行します。
[root@server ~]# strace -t -p 5797,5798,5799,5800,5801,5802
strace: Process 5797 attached
strace: Process 5798 attached
strace: Process 5799 attached
strace: Process 5800 attached
strace: Process 5801 attached
strace: Process 5802 attached
httpdの80番ポートを開放します。
[root@server ~]# firewall-cmd --add-port=80/tcp
success
curlでhttpdにアクセスします。
[root@client ~]# curl -I http://192.168.2.100
親プロセスはselect,wait4を繰り返し実行しています。クライアントでcurlコマンドを実行すると、子プロセス(PID=5802)が"/var/www/html/index.html"を読み込んでいることがわかります。
[root@server ~]# strace -t -p 5797,5798,5799,5800,5801,5802
-snip-
[pid 5797] 20:56:06 select(0, NULL, NULL, NULL, {tv_sec=1, tv_usec=0}) = 0 (Timeout)
[pid 5797] 20:56:07 wait4(-1, 0x7ffda9db874c, WNOHANG|WSTOPPED, NULL) = 0
[pid 5797] 20:56:07 select(0, NULL, NULL, NULL, {tv_sec=1, tv_usec=0}) = 0 (Timeout)
[pid 5797] 20:56:08 wait4(-1, 0x7ffda9db874c, WNOHANG|WSTOPPED, NULL) = 0
[pid 5797] 20:56:08 select(0, NULL, NULL, NULL, {tv_sec=1, tv_usec=0} <unfinished ...>
[pid 5802] 20:56:09 <... accept4 resumed>{sa_family=AF_INET6, sin6_port=htons(36844), inet_pton(AF_INET6, "::ffff:192.168.2.105", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28], SOCK_CLOEXEC) = 9
[pid 5802] 20:56:09 getsockname(9, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:192.168.2.100", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28]) = 0
[pid 5802] 20:56:09 fcntl(9, F_GETFL) = 0x2 (flags O_RDWR)
[pid 5802] 20:56:09 fcntl(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 5802] 20:56:09 read(9, "HEAD / HTTP/1.1\r\nUser-Agent: cur"..., 8000) = 78
[pid 5802] 20:56:09 stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=24, ...}) = 0
[pid 5802] 20:56:09 stat("/var/www/html/index.html", {st_mode=S_IFREG|0644, st_size=12, ...}) = 0
[pid 5802] 20:56:09 open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 10
9.2 子プロセスもstraceの対象にする方法(-f)
-fオプションは、親プロセスから生成する子プロセスもstraceの対象にします。
ここでは、親プロセスから生成するスレッドをstraceの対象にしてみます。
1プロセスに2つのスレッドを生成するテストプログラムを作成します。
[root@server ~]# cat thread.c
#include <stdio.h>
#include <pthread.h>
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
void *threadFunc1(void)
{
int fd;
char str[] = "0123456789";
for(;;) {
fd = open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
write(fd, str, (size_t)sizeof(str));
close(fd);
sleep(3);
}
}
int main(int argc, char *argv[])
{
pthread_t t1;
void *res;
printf("PID=%d\n",getpid());
sleep(10);
pthread_create(&t1, NULL, (void *)&threadFunc1, NULL);
pthread_join(t1, &res);
_exit(0);
}
テストプログラムをコンパイルします。
[root@server ~]# gcc -Wall -pthread -o thread thread.c
作成したテストプログラムを確認します。
[root@server ~]# ls -l thread*
-rwxr-xr-x. 1 root root 8760 1月 8 21:29 thread
-rw-r--r--. 1 root root 632 1月 8 21:28 thread.c
テストプログラムを起動します。
[root@server ~]# ./thread
PID=10493
psコマンドを実行します。threadのPIDはともに10493 ですが、LWPはそれぞれ10493,10496となっていて、スレッドであることがわかります。
[root@server ~]# ps -LC thread
PID LWP TTY TIME CMD
10493 10493 pts/0 00:00:00 thread
10493 10496 pts/0 00:00:00 thread
実行結果を確認すると、親プロセスから起動したスレッドのstraceが表示されているのがわかります。
なお、実行結果のpidはpsコマンドのPIDではなくLWPを表していると思われます。
[root@server ~]# strace -f -p 10493
strace: Process 10493 attached
restart_syscall(<... resuming interrupted read ...>) = 0
mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f7cc7053000
brk(NULL) = 0x8d2000
brk(0x8f3000) = 0x8f3000
brk(NULL) = 0x8f3000
mprotect(0x7f7cc7053000, 4096, PROT_NONE) = 0
clone(child_stack=0x7f7cc7852fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f7cc78539d0, tls=0x7f7cc7853700, child_tidptr=0x7f7cc78539d0) = 10496
strace: Process 10496 attached
[pid 10493] futex(0x7f7cc78539d0, FUTEX_WAIT, 10496, NULL <unfinished ...>
[pid 10496] set_robust_list(0x7f7cc78539e0, 24) = 0
[pid 10496] open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[pid 10496] write(3, "0123456789\0", 11) = 11
[pid 10496] close(3) = 0
-snip-
10 表示する文字列数を調整する方法(-s)
-sはシステムコールの引数に指定する文字数を指定するオプションです。デフォルトは32文字です。
10.1 事前準備
5.1で作成したテストプログラムを改造します。改造部分は、char str[]に定義する文字列です。文字列を10文字から40文字に変更しました。
[root@server ~]# vi tp.c
[root@server ~]# cat tp.c
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <time.h>
#include <sys/stat.h>
int main(int argc, char *argv[])
{
int fd;
struct timespec req;
char str[] = "0123456789012345678901234567890123456789";
req.tv_sec = 2;
req.tv_nsec = 0;
for(;;) {
fd = open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
write(fd, str, (size_t)sizeof(str));
close(fd);
nanosleep(&req, NULL);
}
}
テストプログラムをコンパイルします。
[root@server ~]# gcc -Wall -o tp tp.c
作成したテストプログラムを確認します。
[root@server ~]# ls -l tp*
-rwxr-xr-x. 1 root root 8552 12月 26 11:21 tp
-rw-r--r--. 1 root root 456 12月 26 11:19 tp.c
10.2 実験結果
テストプログラムを実行します。
[root@server ~]# ./tp
もう１つターミナルを開きます。
テストプログラムのPIDを確認すると、PID=2029であることがわかります。
[root@server ~]# ps -C tp
PID TTY TIME CMD
2029 pts/1 00:00:00 tp
まずオプション(-s)指定なしてstraceを実行してみます。
writeシステムコールの第2引数は32バイトまでしか表示されていないことがわかります。
[root@server ~]# strace -p 2029
strace: Process 2029 attached
restart_syscall(<... resuming interrupted read ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, "01234567890123456789012345678901"..., 41) = 41
close(3) = 0
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
次に-sオプションを指定して、straceを実行してみます。
writeシステムコールの第2引数が省略されず、40バイト全て表示されていることがわかります。
[root@server ~]# strace -s 41 -p 2029
strace: Process 2029 attached
restart_syscall(<... resuming interrupted read ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, "0123456789012345678901234567890123456789\0", 41) = 41
close(3) = 0
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
11 strace実行結果をファイルに保存する方法(-o)
11.1 実行結果を1つにまとめる方法
テストプログラムを実行します。
[root@server ~]# ./tp
straceの対象となるプロセスのPIDを確認します。
[root@server ~]# ps -C tp
PID TTY TIME CMD
2510 pts/1 00:00:00 tp
-oオプションを指定して、straceを実行します。
[root@server ~]# strace -p 2510 -o strace.log
strace: Process 2510 attached
Ctrl+cを押下して、straceを終了します。そして、保存した結果を確認します。
[root@server ~]# cat strace.log
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, "01234567890123456789012345678901"..., 41) = 41
close(3) = 0
nanosleep({tv_sec=2, tv_nsec=0}, NULL) = 0
-snip-
11.2 実行結果をプロセス毎にわける方法(-ff)
httpdを起動します。
[root@server ~]# systemctl start httpd
httpdのPIDを確認します。
[root@server ~]# ps -C httpd
PID TTY TIME CMD
2418 ? 00:00:00 httpd
2419 ? 00:00:00 httpd
2420 ? 00:00:00 httpd
2421 ? 00:00:00 httpd
2422 ? 00:00:00 httpd
2423 ? 00:00:00 httpd
-oオプションを指定して、straceを実行します。
[root@server ~]# strace -ff -p 2418,2419,2420,2421,2422,2423 -o strace.log
strace: Process 2418 attached
strace: Process 2419 attached
strace: Process 2420 attached
strace: Process 2421 attached
strace: Process 2422 attached
strace: Process 2423 attached
Ctrl+cを押下して、straceを終了します。PID毎に実行結果が保存できたことがわかります。
[root@server ~]# ls -l strace.log.*
-rw-r--r--. 1 root root 1259 1月 6 21:29 strace.log.2418
-rw-r--r--. 1 root root 27 1月 6 21:29 strace.log.2419
-rw-r--r--. 1 root root 27 1月 6 21:29 strace.log.2420
-rw-r--r--. 1 root root 27 1月 6 21:29 strace.log.2421
-rw-r--r--. 1 root root 27 1月 6 21:29 strace.log.2422
-rw-r--r--. 1 root root 27 1月 6 21:29 strace.log.2423
[root@server ~]# cat strace.log.2418
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=414792}) = 0 (Timeout)
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
getsockopt(8, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(8, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = -1 EPERM (許可されていない操作です)
setsockopt(8, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
-snip-
12.1 事前準備
サーバ側のテストプログラムを作成します。
[root@server ~]# cat sv.c
#include <stdio.h>
#include <string.h>
#include <unistd.h>
#include <sys/socket.h>
#include <sys/un.h>
#define FILEPATH "/tmp/afunix_test"
#define BUF_SIZE 100
int main(int argc, char *argv[])
{
int sfd, cfd;
struct sockaddr_un addr;
ssize_t numRead;
char buf[BUF_SIZE];
sfd = socket(AF_UNIX, SOCK_STREAM, 0);
remove(FILEPATH);
memset(&addr, 0, sizeof(struct sockaddr_un));
addr.sun_family = AF_UNIX;
strncpy(addr.sun_path, FILEPATH, sizeof(addr.sun_path));
bind(sfd, (struct sockaddr *)&addr, sizeof(struct sockaddr_un));
listen(sfd, 5);
for(;;){
cfd = accept(sfd, NULL, NULL);
while((numRead = read(cfd, buf, BUF_SIZE)) >0) {
write(STDOUT_FILENO, buf, numRead);
}
close(cfd);
}
}
クライアント側のテストプログラムを作成します。
[root@server ~]# cat cl.c
#include <stdio.h>
#include <string.h>
#include <unistd.h>
#include <sys/socket.h>
#include <sys/un.h>
#define FILEPATH "/tmp/afunix_test"
#define BUF_SIZE 100
int main(int argc, char *argv[])
{
struct sockaddr_un addr;
int sfd;
ssize_t numRead;
char buf[BUF_SIZE];
sfd = socket(AF_UNIX, SOCK_STREAM, 0);
memset(&addr, 0, sizeof(struct sockaddr_un));
addr.sun_family = AF_UNIX;
strncpy(addr.sun_path, FILEPATH, sizeof(addr.sun_path));
connect(sfd, (struct sockaddr *)&addr, sizeof(struct sockaddr_un));
while((numRead=read(STDIN_FILENO, buf, BUF_SIZE)) > 0) {
write(sfd, buf, numRead);
}
_exit(0);
}
テストプログラムをコンパイルします。
[root@server ~]# gcc -Wall -o sv sv.c
[root@server ~]# gcc -Wall -o cl cl.c
テストプログラムを確認します。
[root@server ~]# ls -l sv* cl*
-rwxr-xr-x. 1 root root 8704 1月 6 21:46 cl
-rw-r--r--. 1 root root 661 1月 6 21:45 cl.c
-rwxr-xr-x. 1 root root 8856 1月 6 21:46 sv
-rw-r--r--. 1 root root 796 1月 6 21:44 sv.c
12.2 実験結果
テストプログラム(sv)を実行します。
[root@server ~]# ./sv
UNIXドメインソケットを確認します。
テストプログラム(sv)が使用しているUNIXドメインソケットが確認できます。
[root@server ~]# lsof -c sv -a -U
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
sv 3346 root 3u unix 0xffff8f1e70934400 0t0 43435 /tmp/afunix_test
テストプログラム(cl)を実行します。
[root@server ~]# ./cl
UNIXドメインソケットを確認します。
テストプログラム(cl)が使用しているUNIXドメインソケットが確認できます。
[root@server ~]# lsof -c sv -c cl -a -U
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
sv 3346 root 3u unix 0xffff8f1e70934400 0t0 43435 /tmp/afunix_test
sv 3346 root 4u unix 0xffff8f1e717b2a80 0t0 43436 /tmp/afunix_test
cl 3423 root 3u unix 0xffff8f1e717b1100 0t0 41286 socket
テストプログラムのPIDを確認します。
[root@server ~]# ps -C sv
PID TTY TIME CMD
3346 pts/1 00:00:00 sv
[root@server ~]# strace -f -e trace=read,write -e read=3,4 -e write=3,4 -p 3346
strace: Process 3346 attached
read(4,
クライアントで"12345"を入力します。
[root@server ~]# ./cl
12345
クライアントで入力した文字列("12345")が、サーバのFD=4より読み出されていることがわかります。
[root@server ~]# strace -f -e trace=read,write -e read=3,4 -e write=3,4 -p 3346
strace: Process 3346 attached
read(4, "12345\n", 100) = 6
| 00000 31 32 33 34 35 0a 12345. |
write(1, "12345\n", 6) = 6
read(4,
13 統計情報を確認する方法(-S)
13.1 システムコールの実行時間でソートする方法(time)
lsコマンドが実行するシステムコールを実行時間の多い順に出力してみます。
mmapシステムコールの実行時間の割合(22.66%)が一番多いことがわかります。
[root@server ~]# strace -c -S time ls
Anaconda3-2021.05-Linux-x86_64.sh a.txt anaconda3 c.txt stress.1TGpB0 stress.BKIcbc sv.dat tp
Anaconda3-2021.05-Linux-x86_64.sh.1 anaconda-ks.cfg b.txt python stress.8BbTyX stress.vgARxb test.txt tp.c
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
22.66 0.000213 7 27 mmap
21.81 0.000205 11 18 mprotect
10.96 0.000103 10 10 open
7.98 0.000075 9 8 read
5.32 0.000050 3 13 close
5.00 0.000047 4 11 fstat
4.79 0.000045 22 2 statfs
4.04 0.000038 19 2 munmap
3.40 0.000032 16 2 write
3.19 0.000030 15 2 getdents
2.02 0.000019 9 2 ioctl
1.81 0.000017 17 1 openat
1.60 0.000015 15 1 stat
1.17 0.000011 3 3 brk
1.17 0.000011 5 2 1 access
0.85 0.000008 4 2 rt_sigaction
0.53 0.000005 5 1 getrlimit
0.43 0.000004 4 1 rt_sigprocmask
0.43 0.000004 4 1 arch_prctl
0.43 0.000004 4 1 set_tid_address
0.43 0.000004 4 1 set_robust_list
0.00 0.000000 0 1 execve
------ ----------- ----------- --------- --------- ----------------
100.00 0.000940 112 1 total
13.2 システムコールの呼び出し回数でソートする方法(calls)
lsコマンドが実行するシステムコールを呼び出し回数の多い順に出力してみます。
mmapシステムコールの呼び出し回数(27回)が一番多いことがわかります。
また、openシステムコールは実行時間が占める割合(14.74%)は3番目ですが、呼び出し回数(10回)としては5番目であることがわかります。
[root@server ~]# strace -c -S calls ls
Anaconda3-2021.05-Linux-x86_64.sh a.txt anaconda3 c.txt stress.1TGpB0 stress.BKIcbc sv.dat tp
Anaconda3-2021.05-Linux-x86_64.sh.1 anaconda-ks.cfg b.txt python stress.8BbTyX stress.vgARxb test.txt tp.c
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
24.79 0.000301 11 27 mmap
19.69 0.000239 13 18 mprotect
5.44 0.000066 5 13 close
5.02 0.000061 5 11 fstat
14.74 0.000179 17 10 open
5.02 0.000061 7 8 read
1.40 0.000017 5 3 brk
2.47 0.000030 15 2 write
3.21 0.000039 19 2 munmap
0.74 0.000009 4 2 rt_sigaction
1.24 0.000015 7 2 ioctl
4.94 0.000060 30 2 1 access
2.47 0.000030 15 2 getdents
3.71 0.000045 22 2 statfs
1.15 0.000014 14 1 stat
0.33 0.000004 4 1 rt_sigprocmask
0.74 0.000009 9 1 execve
0.41 0.000005 5 1 getrlimit
0.33 0.000004 4 1 arch_prctl
0.41 0.000005 5 1 set_tid_address
1.40 0.000017 17 1 openat
0.33 0.000004 4 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.001214 112 1 total
13.3 システムコールの名前でソートする方法(name)
システムコールの名前をアルファベット順でソートしてみます。
access,arch_prctl,brkの順で表示されていることがわかります。
[root@server ~]# strace -c -S name ls
Anaconda3-2021.05-Linux-x86_64.sh a.txt anaconda3 c.txt stress.1TGpB0 stress.BKIcbc sv.dat tp
Anaconda3-2021.05-Linux-x86_64.sh.1 anaconda-ks.cfg b.txt python stress.8BbTyX stress.vgARxb test.txt tp.c
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
1.52 0.000011 5 2 1 access
0.55 0.000004 4 1 arch_prctl
1.52 0.000011 3 3 brk
5.95 0.000043 3 13 close
0.00 0.000000 0 1 execve
4.15 0.000030 2 11 fstat
4.15 0.000030 15 2 getdents
0.69 0.000005 5 1 getrlimit
3.18 0.000023 11 2 ioctl
21.72 0.000157 5 27 mmap
21.44 0.000155 8 18 mprotect
5.12 0.000037 18 2 munmap
9.27 0.000067 6 10 open
2.07 0.000015 15 1 openat
3.60 0.000026 3 8 read
1.24 0.000009 4 2 rt_sigaction
0.55 0.000004 4 1 rt_sigprocmask
0.41 0.000003 3 1 set_robust_list
0.55 0.000004 4 1 set_tid_address
1.94 0.000014 14 1 stat
5.95 0.000043 21 2 statfs
4.43 0.000032 16 2 write
------ ----------- ----------- --------- --------- ----------------
100.00 0.000723 112 1 total
Z 参考情報
私が業務や記事執筆で参考にした書籍を以下のページに記載します。
Linux技術のスキルアップをしよう！ - hana_shinのLinux技術ブログ
