hana_shinのLinux技術ブログ

Linuxの技術情報を掲載しています。特にネットワークをメインに掲載していきます。

straceコマンドの使い方

centos7 トラブルシューティング


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 システムコールの実行順序を表示する方法

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)

7.1 特定のシステムコールを表示する方法(-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 UNIXドメインソケットを監視する方法

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技術ブログ