Help us understand the problem. What is going on with this article?

straceコマンドの使い方

1 環境

[root@master1 ~]# cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)

[root@master1 ~]# uname -r
3.10.0-514.el7.x86_64

2 インストール方法

[root@master1 ~]# yum -y install strace

[root@master1 ~]# strace -V
strace -- version 4.8

3 事前準備

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@master1 strace]# gcc -Wall -o tp tp.c

"tp"という実行ファイルが作成できたことがわかります。

作成したファイルの確認
[root@master1 strace]# ls
tp  tp.c

4 システムコールの実行順序を表示する方法(もっとも単純な使い方)

ターミナル1(テストプログラムの起動)
[root@master1 strace]# ./tp
ターミナル2
もう1つターミナルを開く。テストプログラムのPIDを確認する。PID=2298であることがわかる。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  2298 pts/0    00:00:00 tp

straceを実行する。-pはテストプログラムのPIDを指定する。
open,write,close,nanosleepの順(★印)にシステムコールを実行していることがわかる。
[root@master1 strace]# strace -p 2298
Process 2298 attached
restart_syscall(<... resuming interrupted call ...>) = 0
★open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
★write(3, "0123456789\0", 11)            = 11
★close(3) = 0
★nanosleep({2, 0}, NULL) = 0
-以下、略-

5 時刻情報を表示する方法

5.1 システムコール実行時刻(秒単位)の表示方法(-t)

システムコールの実行時刻が秒単位で表示(左端の時刻)されていることがわかります。

ターミナル2
[root@master1 strace]# strace -t -p 2298
Process 2298 attached
17:07:22 restart_syscall(<... resuming interrupted call ...>) = 0
17:07:23 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:07:23 write(3, "0123456789\0", 11)   = 11
17:07:23 close(3)                       = 0
17:07:23 nanosleep({2, 0}, NULL)        = 0
-以下、略-

5.2 システムコール実行時刻(マイクロ秒単位)の表示方法(-tt)

システムコールの実行時刻がマイクロ秒単位で表示(左端の時刻)されていることがわかります。

ターミナル2
[root@master1 strace]# strace -tt -p 2298
Process 2298 attached
17:08:46.386233 restart_syscall(<... resuming interrupted call ...>) = 0
17:08:47.578517 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:08:47.578877 write(3, "0123456789\0", 11) = 11
17:08:47.579029 close(3)                = 0
17:08:47.579551 nanosleep({2, 0}, NULL) = 0

5.3 システムコール実行時間の表示方法(-T)

システムコールを実行してから完了するまでの実行時間を表示する。
右端の<>に囲まれた部分が、システムコールの実行時間を表します。
マイクロ秒単位の精度で表示されていることがわかります。
nanosleepシステムコールの場合、スリープ時間に指定した2秒より少し時間がかかっています(★印)。

ターミナル2
[root@master1 strace]# strace -T -p 2298
Process 2298 attached
restart_syscall(<... resuming interrupted call ...>) = 0 <0.712816>
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000182>
write(3, "0123456789\0", 11)            = 11 <0.000148>
close(3)                                = 0 <0.000364>
nanosleep({2, 0}, NULL)                 = 0 ★<2.000711>
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000187>
write(3, "0123456789\0", 11)            = 11 <0.000144>
close(3)                                = 0 <0.000415>
nanosleep({2, 0}, NULL)                 = 0 ★<2.001113>
-以下、略-

5.4 システムコール実行間隔の表示方法(-r)

時刻T1と時刻T2にシステムコールを実行したとき、システムコールの実行間隔(T2-T1)を表示する。

テストプログラムを実行する。
[root@master1 strace]# ./tp

もう1つターミナルを開く。テストプログラムのPIDを確認する。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  4250 pts/1    00:00:00 tp

straceを実行する。システムコールの実行間隔がわかる。
[root@master1 strace]# strace -r -p 4250
Process 4250 attached
     0.000000 restart_syscall(<... resuming interrupted call ...>) = 0
     0.286757 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
     0.000320 write(3, "0123456789\0", 11) = 11
     0.000122 close(3)                  = 0
     0.000907 nanosleep({2, 0}, NULL)   = 0
     2.001321 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
     0.000307 write(3, "0123456789\0", 11) = 11
     0.000127 close(3)                  = 0
     0.002396 nanosleep({2, 0}, NULL)   = 0
     2.000634 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
     0.000261 write(3, "0123456789\0", 11) = 11
     0.000112 close(3)                  = 0
     0.000526 nanosleep({2, 0}, ^CProcess 4250 detached

6 実行結果を絞り込む方法(-e trace)

6.1 特定のシステムコールを表示する方法(-e trace=システムコール名)

tpのPIDを確認する。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  2401 pts/0    00:00:00 tp
openシステムコールだけを指定した場合
[root@master1 strace]# strace -t -e trace=open -p 2401
Process 2401 attached
17:35:47 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:35:49 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:35:51 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
-以下、略-
openとcloseだけを指定した場合
[root@master1 strace]# strace -t -e trace=open,close -p 2401
Process 2401 attached
17:46:04 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:46:04 close(3)                       = 0
17:46:06 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:46:06 close(3)                       = 0
17:46:08 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
17:46:08 close(3)                       = 0
-以下、略-

6.2 特定のシステムコールをstrace実行結果から除外する方法(-e 'trace=!システムコール名')

テストプログラムを実行する。
[root@master1 strace]# ./tp

もう1つターミナルを開く。テストプログラムのPIDを確認する。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  1347 pts/1    00:00:00 tp

writeシステムコール以外を指定する。writeシステムコールが表示されていないことがわかる。
[root@master1 strace]# strace -e 'trace=!write' -p 1347
Process 1347 attached
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
close(3)                                = 0
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

6.3 複数のシステムコールをstrace実行結果から除外する方法(-e 'trace=!システムコール名,システムコール名')

テストプログラムを実行する。
[root@master1 strace]# ./tp

もう1つターミナルを開く。テストプログラムのPIDを確認する。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  1593 pts/1    00:00:00 tp

straceを実行する。openとclose以外のシステムコール実行結果を表示する。
[root@master1 strace]# strace -e 'trace=!open,close' -p 1593
Process 1593 attached
restart_syscall(<... resuming interrupted call ...>) = 0
write(3, "0123456789\0", 11)            = 11
nanosleep({2, 0}, NULL)                 = 0
write(3, "0123456789\0", 11)            = 11
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

6.4 ネットワーク関連のシステムコールだけを表示する方法(-e trace=network)

テスト用のhttpdをインストールする。
[root@master1 strace]# yum -y install httpd
[root@master1 strace]# systemctl start httpd
[root@master1 strace]# systemctl is-active httpd
active

httpdのPIDを確認する。httpdの親プロセスは、PID=2949のhttpdであることがわかる。
[root@master1 strace]# ps -C httpd -o comm,pid,ppid
COMMAND            PID   PPID
httpd           ★2949      1
httpd             2950   2949
httpd             2951   2949
httpd             2952   2949
httpd             2953   2949
httpd             2954   2949
httpd             2958   2949
httpd             2959   2949
httpd             2960   2949

親プロセスのhttpdに対してstraceを実行する。
socket,sendmsg等のネットワーク関連のシステムコールを10秒間隔で実行しているのがわかる。
[root@master1 strace]# strace -t -e trace=network -p 2949
Process 2949 attached
18:19:28 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
18:19:28 sendmsg(8, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Total requests: 2"..., 87}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 87
18:19:38 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
18:19:38 sendmsg(8, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Total requests: 2"..., 87}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 87
18:19:48 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
18:19:48 sendmsg(8, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Total requests: 2"..., 87}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 87
-以下、略-

6.5 ファイル名を引数に取るシステムコールだけを表示する方法(-e trace=file)

事前準備(テストプログラム作成)
テストプログラムを作成する。ファイル名を引数に取るシステムコールは、openだけであることがわかる。
[root@admin ~]# vi tp.c
[root@admin ~]# 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 fd1, fd2;
    struct timespec req;
    char str[] = "0123456789";

    req.tv_sec = 2;
    req.tv_nsec = 0;

    for(;;) {
        fd1 = open("test1.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
        fd2 = open("test2.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);

        write(fd1, str, (size_t)sizeof(str));
        write(fd2, str, (size_t)sizeof(str));

        close(fd1);
        close(fd2);

        nanosleep(&req, NULL);
    }
}

テストプログラムをコンパイルする。
[root@admin ~]# gcc -Wall -o tp tp.c
実行結果確認
テストプログラムを実行する。
[root@admin strace]# ./tp &
[1] 1128

プロセスのPIDを確認する。
[root@admin strace]# ps -C tp
   PID TTY          TIME CMD
  1128 pts/0    00:00:00 tp

straceを実行する。
openはファイル名を引数にとるが、他のwrite,closeはファイル名ではなくfdを引数にとるので、
straceの実行結果としては、openだけが表示される。
[root@admin strace]# strace -e trace=file -p 1128
Process 1128 attached
open("test1.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("test2.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
open("test1.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
open("test2.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
-以下、略-

6.6 シグナルのシステムコールだけを表示する方法(-e trace=signal)

SIGKILLを送信した場合
sleepコマンドを実行する。
[root@server ~]# sleep 300&
[1] 2209

プロセスの状態を確認する。
[root@server ~]# ps -C sleep
   PID TTY          TIME CMD
  2209 pts/1    00:00:00 sleep

シグナルのシステムコールだけを表示する。SIGKILLが送信されていることがわかる。
[root@server ~]# strace -e trace=signal kill -9 2209
kill(2209, SIGKILL)                     = 0
+++ exited with 0 +++
[1]+  強制終了            sleep 300
SIGTERMを送信した場合
sleepコマンドを実行する。
[root@server ~]# sleep 300&
[1] 2215

プロセスの状態を確認する。
[root@server ~]# ps -C sleep
   PID TTY          TIME CMD
  2215 pts/1    00:00:00 sleep

シグナルのシステムコールだけを表示する。SIGTERMが送信されていることがわかる。
[root@server ~]# strace -e trace=signal kill -15 2215
kill(2215, SIGTERM)                     = 0
+++ exited with 0 +++
[1]+  Terminated              sleep 300

7 ファイルをアクセスしたときにトレースを表示する方法(-P)

事前準備(テストプログラム作成)
[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 tp*
tp  tp.c
テスト用ファイル作成
[root@server ~]# touch /tmp/test.txt
[root@server ~]# echo 1 > /tmp/test.txt
実行結果
テストプログラムを実行する。このときアクセスするファイルは/tmp/test.txtを指定する。
[root@server ~]# ./tp /tmp/test.txt
path=/tmp/test.txt

もう1つターミナルを開く。テストプログラムのPIDを確認する。
[root@server ~]# ps -C tp
   PID TTY          TIME CMD
  1763 pts/1    00:00:00 tp

straceを実行する。このとき、-Pのパラメータとして、/tmp/test.txtを指定する。
/tmp/test.txtにアクセスするたびに、straceが実行結果を表示していることがわかる。
[root@server strace]# strace -ttT -f -P /tmp/test.txt -p 1763
Process 1763 attached
20:44:43.482294 open("/tmp/test.txt", O_RDONLY) = 3 <0.000096>
20:44:43.482790 close(3)                = 0 <0.000045>
20:44:44.483263 open("/tmp/test.txt", O_RDONLY) = 3 <0.000043>
20:44:44.483489 close(3)                = 0 <0.000030>
20:44:45.484366 open("/tmp/test.txt", O_RDONLY) = 3 <0.000045>
20:44:45.484592 close(3)                = 0 <0.000031>
-以下、略-

8 複数プロセス/スレッドに対するstrace実行方法

8.1 複数プロセス対するstrace実行方法(-p pid,pid,...)

テスト用のhttpdをインストールする。
[root@master1 ~]# yum -y install httpd

テスト用ファイル(index.html)を作成する。
[root@master1 ~]# vi /var/www/html/index.html
[root@master1 ~]# cat /var/www/html/index.html
test
[root@master1 ~]# firewall-cmd --add-port=80/tcp

httpdを起動する。
[root@master1 ~]# systemctl start httpd
[root@master1 ~]# systemctl is-active httpd
active

起動したhttpdを確認する。PID=3311が親プロセス、他は子プロセスであることがわかる。
[root@master1 ~]# ps -C httpd -o comm,pid,ppid
COMMAND            PID   PPID
httpd             3311      1
httpd             3312   3311
httpd             3313   3311
httpd             3314   3311
httpd             3315   3311
httpd             3316   3311

全てのhttpdプロセスに対してstraceを実行する。
[root@master1 ~]# strace -t -p 3311,3312,3313,3314,3315,3316

もう1つターミナルを開く。httpdに対してアクセスする。
[root@master1 ~]# curl http://localhost
test

straceの実行結果を確認する。
親プロセス(PID=3311)がselectで事象発生待ちを繰り返している。
curlコマンドを実行すると、子プロセス(PID=3316)が動き出していることがわかる。
そして、子プロセス(PID=3316)はreadシステムコールを実行してindex.htmlを読み出して、
writevシステムコールを使って、httpヘッダとinedx.htmlファイルをfd=9に対して書き込みをしていることがわかる。
fd=9への書き込みが、curlコマンドへの応答となる。
[root@master1 ~]# strace -t -p 3311,3312,3313,3314,3315,3316
-中略-
[pid  3311] 19:58:23 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:24 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:24 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:25 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
[pid  3311] 19:58:25 sendmsg(8, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Total requests: 3"..., 87}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 87
[pid  3311] 19:58:25 close(8)           = 0
[pid  3311] 19:58:25 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:25 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:26 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:26 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:27 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:27 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:28 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:28 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[pid  3316] 19:58:29 <... accept4 resumed> {sa_family=AF_INET6, sin6_port=htons(49416), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 9
[pid  3316] 19:58:29 getsockname(9, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
[pid  3316] 19:58:29 fcntl(9, F_GETFL)  = 0x2 (flags O_RDWR)
[pid  3316] 19:58:29 fcntl(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid  3316] 19:58:29 read(9, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 8000) = 73
[pid  3316] 19:58:29 stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=46, ...}) = 0
[pid  3316] 19:58:29 stat("/var/www/html/index.html", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
[pid  3316] 19:58:29 open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 10
[pid  3316] 19:58:29 read(9, 0x7f9bf8687b28, 8000) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3316] 19:58:29 mmap(NULL, 5, PROT_READ, MAP_SHARED, 10, 0) = 0x7f9bf694a000
[pid  3316] 19:58:29 writev(9, [{"HTTP/1.1 200 OK\r\nDate: Fri, 26 M"..., 239}, {"test\n", 5}], 2) = 244
[pid  3316] 19:58:29 munmap(0x7f9bf694a000, 5) = 0
[pid  3316] 19:58:29 write(7, "::1 - - [26/May/2017:19:58:29 +0"..., 78) = 78
[pid  3316] 19:58:29 times({tms_utime=1, tms_stime=5, tms_cutime=0, tms_cstime=0}) = 431124864
[pid  3316] 19:58:29 close(10)          = 0
[pid  3316] 19:58:29 poll([{fd=9, events=POLLIN}], 1, 5000) = 1 ([{fd=9, revents=POLLIN}])
[pid  3316] 19:58:29 read(9, "", 8000)  = 0
[pid  3316] 19:58:29 shutdown(9, SHUT_WR) = 0
[pid  3316] 19:58:29 poll([{fd=9, events=POLLIN}], 1, 2000) = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
[pid  3316] 19:58:29 read(9, "", 512)   = 0
[pid  3316] 19:58:29 close(9)           = 0
[pid  3316] 19:58:29 read(5, 0x7ffcdd82bccf, 1) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3316] 19:58:29 accept4(4,  <unfinished ...>
[pid  3311] 19:58:29 <... select resumed> ) = 0 (Timeout)
[pid  3311] 19:58:29 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:29 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[pid  3311] 19:58:30 wait4(-1, 0x7ffcdd82bdac, WNOHANG|WSTOPPED, NULL) = 0
[pid  3311] 19:58:30 select(0, NULL, NULL, NULL, {1, 0}^CProcess 3311 detached

8.2 複数スレッドに対するstrace実行方法(-f)

8.2.1 事前準備

テストプログラムを作成します。
テストプログラムは、1プロセスに2つのスレッドを生成します。

[root@master1 strace]# vi thread.c
[root@master1 strace]# cat thread.c
#include <stdio.h>
#include <pthread.h>
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <sys/stat.h>
#include <time.h>

void *threadFunc1(void)
{
    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);
    }
}

int main(int argc, char *argv[])
{
    pthread_t t1;
    void *res;

    pthread_create(&t1, NULL, (void *)&threadFunc1, NULL);

    pthread_join(t1, &res);
    _exit(0);
}

テストプログラムをコンパイルします。

コンパイル
[root@master1 strace]# gcc -Wall -pthread -o thread thread.c
[root@master1 strace]# ls -l thread*
-rwxr-xr-x. 1 root root 8880  5月 26 20:36 thread
-rw-r--r--. 1 root root  633  5月 26 20:36 thread.c

スレッドIDを確認する。-Cオプションだとプロセスしか表示できません。

動作確認(Cオプションの場合)
[root@master1 strace]# ./thread
[root@master1 strace]# ps -C thread
   PID TTY          TIME CMD
  3753 pts/2    00:00:00 thread

-Lオプションを使って、スレッドを表示してみます。
スレッドはPIDが同じで、スレッドID(LWP)が異なります。

動作確認(Lオプションの場合)
[root@master1 strace]# ps -LC thread
   PID    LWP TTY          TIME CMD
  3753   3753 pts/2    00:00:00 thread
  3753   3754 pts/2    00:00:00 thread

1つのプロセスに、2つのスレッドが存在することがわかります。
1つはmain関数を実行(3753)、もう1つはthreadFunc1関数を実行(3754)しています。

8.2.2 スレッドに対してstraceを実行する(-f)

straceを実行する。-pには、親プロセスのIDを指定します。
スレッドID=3753とID=3754のスレッドが実行するシステムコールが確認できる。
[root@master1 strace]# strace -t -f -p 3753
Process 3753 attached with 2 threads
[pid  3754] 20:43:31 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid  3753] 20:43:31 futex(0x7fa4364ea9d0, FUTEX_WAIT, 3754, NULL <unfinished ...>
[pid  3754] 20:43:33 <... restart_syscall resumed> ) = 0
[pid  3754] 20:43:33 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[pid  3754] 20:43:33 write(3, "0123456789\0", 11) = 11
[pid  3754] 20:43:33 close(3)           = 0
[pid  3754] 20:43:33 nanosleep({2, 0}, NULL) = 0
[pid  3754] 20:43:35 open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[pid  3754] 20:43:35 write(3, "0123456789\0", 11) = 11
[pid  3754] 20:43:35 close(3)           = 0
[pid  3754] 20:43:35 nanosleep({2, 0}, NULL) = 0
-以下、略-

-fを指定しないと、親プロセスがfutexシステムコールを実行して、その状態でとまったままになっている。
つまり、スレッドもstrace実行対象にする場合は、-fを指定する必要があるということ。
[root@master1 strace]# strace -t -p 3753
Process 3753 attached
20:45:00 futex(0x7fa4364ea9d0, FUTEX_WAIT, 3754, NULL
ここで、表示がとまったままになる。

9 表示する文字列数を調整する方法(-s)

デフォルトでは32バイトまで表示できます。

9.1 事前準備

テストプログラム(tp.c)を改造する。
writeシステムコールに指定する文字列を10バイトから40バイトに変更する。

[root@master1 strace]# cp tp.c tp1.c
[root@master1 strace]# vi tp1.c
[root@master1 strace]# diff -Nur tp.c tp1.c
--- tp.c        2017-05-26 21:34:15.857907301 +0900
+++ tp1.c       2017-05-26 21:34:00.002347960 +0900
@@ -8,7 +8,7 @@
 {
     int fd;
     struct timespec req;
-    char str[] = "0123456789";
+    char str[] = "0123456789012345678901234567890123456789";

     req.tv_sec = 2;
     req.tv_nsec = 0;

テストプログラムをコンパイルする。
[root@master1 strace]# gcc -Wall -o tp1 tp1.c

9.2 効果(-s)の確認

テストプログラムを実行する。
[root@master1 strace]# ./tp1

もう1つターミナルを開く。PIDを確認する。
[root@master1 strace]# ps -C tp1
   PID TTY          TIME CMD
  4159 pts/2    00:00:00 tp1

straceを実行する。writeシステムコールの第2引数は32バイトまでしか表示されていないことがわかる(★印)。
[root@master1 strace]# strace -p 4159
Process 4159 attached
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, ★"01234567890123456789012345678901"..., 41) = 41
close(3)                                = 0
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

straceを実行する(-sに41を指定する)。writeシステムコールの第2引数が省略されず、すべて表示できたことがわかる(★印)。
[root@master1 strace]# strace -s 41 -p 4159
Process 4159 attached
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, ★"0123456789012345678901234567890123456789\0", 41) = 41
close(3)                                = 0
nanosleep({2, 0}, ^CProcess 4159 detached
-以下、略-

10 特定のFDを監視する方法

事前準備(テストプログラムの作成)
[root@admin ~]# vi tp.c
[root@admin ~]# 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 fd1, fd2;
    struct timespec req;
    char str[] = "0123456789";

    req.tv_sec = 2;
    req.tv_nsec = 0;

    for(;;) {
        fd1 = open("test1.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
        fd2 = open("test2.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);

        write(fd1, str, (size_t)sizeof(str));
        write(fd2, str, (size_t)sizeof(str));

        close(fd1);
        close(fd2);

        nanosleep(&req, NULL);
    }
}
テストプログラムのコンパイル
[root@admin ~]# gcc -Wall -o tp tp.c
fd=3の監視
テストプログラムのPIDを求める。
[root@admin ~]# ps -C tp
   PID TTY          TIME CMD
  1128 pts/0    00:00:01 tp

fd=3のwriteだけ、パラメータの詳細情報を表示する。
[root@admin ~]# strace -e trace=write -e write=3 -p 1128
Process 1128 attached
write(3, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |
write(4, "0123456789\0", 11)            = 11
write(3, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |
write(4, "0123456789\0", 11)            = 11
write(3, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |
fd=4の監視
fd=4のwriteだけ、パラメータの詳細情報を表示する。
[root@admin ~]# strace -e trace=write -e write=4 -p 1128
Process 1128 attached
write(3, "0123456789\0", 11)            = 11
write(4, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |
write(3, "0123456789\0", 11)            = 11
write(4, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |
write(3, "0123456789\0", 11)            = 11
write(4, "0123456789\0", 11)            = 11
 | 00000  30 31 32 33 34 35 36 37  38 39 00                 0123456789.      |

11 strace実行結果をファイルに保存する方法(-o)

11.1 実行結果を1つにまとめる方法

実行結果を1つにまとめる場合は、-oを指定するだけで良い。

strace実行対象のPIDを確認する。
[root@master1 strace]# ps -C tp
   PID TTY          TIME CMD
  1791 pts/1    00:00:00 tp

strace実行結果をファイルに保存する。
[root@master1 strace]# strace -p 1791 -o strace.log
Process 1791 attached

保存した結果を確認する。
[root@master1 strace]# cat strace.log
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, "0123456789\0", 11)            = 11
close(3)                                = 0
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

11.2 実行結果をプロセス毎にわける方法(-ff)

実行結果をプロセス単位にわける場合は、-oに加え、-ffを指定する。

httpdのPIDを確認する。
[root@master1 strace]# ps -C httpd
   PID TTY          TIME CMD
  3311 ?        00:00:02 httpd
  3312 ?        00:00:00 httpd
  3313 ?        00:00:00 httpd
  3314 ?        00:00:00 httpd
  3315 ?        00:00:00 httpd
  3316 ?        00:00:00 httpd

-ffを指定して、starceを実行する。
[root@master1 strace]# strace -ff -p 3311,3312,3313,3314,3315,3316 -o strace.log

strace実行結果を確認する。PID毎に実行結果が保存できたことがわかる。
[root@master1 strace]# ls -l strace.log*
-rw-r--r--. 1 root root 1413  5月 26 21:09 strace.log.3311
-rw-r--r--. 1 root root   27  5月 26 21:09 strace.log.3312
-rw-r--r--. 1 root root 1556  5月 26 21:09 strace.log.3313
-rw-r--r--. 1 root root   27  5月 26 21:09 strace.log.3314
-rw-r--r--. 1 root root   27  5月 26 21:09 strace.log.3315
-rw-r--r--. 1 root root   27  5月 26 21:09 strace.log.3316

strace.log.3313の中身を確認する。
[root@master1 strace]# cat strace.log.3313
accept4(4, {sa_family=AF_INET6, sin6_port=htons(54896), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 9
getsockname(9, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(9, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(9, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
read(9, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 8000) = 73
stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=46, ...}) = 0
stat("/var/www/html/index.html", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 10
read(9, 0x7f9bf8687b28, 8000)           = -1 EAGAIN (Resource temporarily unavailable)
mmap(NULL, 5, PROT_READ, MAP_SHARED, 10, 0) = 0x7f9bf694a000
writev(9, [{"HTTP/1.1 200 OK\r\nDate: Fri, 26 M"..., 239}, {"test\n", 5}], 2) = 244
munmap(0x7f9bf694a000, 5)               = 0
write(7, "::1 - - [26/May/2017:21:09:34 +0"..., 78) = 78
times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 431551437
close(10)                               = 0
poll([{fd=9, events=POLLIN}], 1, 5000)  = 1 ([{fd=9, revents=POLLIN}])
read(9, "", 8000)                       = 0
shutdown(9, SHUT_WR)                    = 0
poll([{fd=9, events=POLLIN}], 1, 2000)  = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
read(9, "", 512)                        = 0
close(9)                                = 0
read(5, 0x7ffcdd82bccf, 1)              = -1 EAGAIN (Resource temporarily unavailable)
accept4(4,  <detached ...>

12 straceの出力結果の変更方法

12.1 ASCIIコードを表示する方法(-x)

straceコマンドを実行する。"0123456789"が0x30x31..と表示されているのがわかる(★印)。
[root@master1 strace]# strace -x -p 2401
Process 2401 attached
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3, ★"\x30\x31\x32\x33\x34\x35\x36\x37\x38\x39\x00", 11) = 11
close(3)                                = 0
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

13 fd(ファイルディスクリプタ)番号とパスを表示する方法(-y)

straceを実行する。fd=3に対するファイルが/root/strace/test.txtであることがわかる。
[root@master1 strace]# strace -y -p 2401
Process 2401 attached
restart_syscall(<... resuming interrupted call ...>) = 0
open("test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(3</root/strace/test.txt>, "0123456789\0", 11) = 11
close(3</root/strace/test.txt>)         = 0
nanosleep({2, 0}, NULL)                 = 0
-以下、略-

14 ソートする方法(-S)

システムコールの実行に費やした時間、システムコールの呼び出し回数、システムコールの名前でソートする。

14.1 時間でソートする方法(time)

time(★)の時間が大きい順でソートされていることがわかる。
[root@router1 ~]# strace -c -S time ls
anaconda-ks.cfg  libreswan-3.20-5.el7_4.src.rpm  rr  stap  test  tools  trace.dat  trace.log
% time★   seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 34.57    0.000242           9        27           mmap
 31.00    0.000217          22        10           open
 13.86    0.000097           5        18           mprotect
  8.00    0.000056           7         8           read
  5.00    0.000035           3        11           fstat
  4.14    0.000029           2        13           close
  2.14    0.000015           8         2         1 access
  0.86    0.000006           6         1           execve
  0.43    0.000003           1         3           brk
-以下、略-

14.2 システムコールの呼び出し回数でソートする方法(calls)

calls(★)が大きい順でソートされていることがわかる。
[root@router1 ~]# strace -c -S calls ls
anaconda-ks.cfg  libreswan-3.20-5.el7_4.src.rpm  rr  stap  test  tools  trace.dat  trace.log
% time     seconds  usecs/call   ★calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 17.68    0.000055           2        27           mmap
  3.86    0.000012           1        18           mprotect
  2.25    0.000007           1        13           close
  2.89    0.000009           1        11           fstat
  9.97    0.000031           3        10           open
  2.57    0.000008           1         8           read
-以下、略-

14.3 システムコールの名前でソートする方法(name)

右端のsyscall(★)がアルファベット順にソートされていることがわかる。
[root@router1 ~]# strace -c -S name ls
anaconda-ks.cfg  libreswan-3.20-5.el7_4.src.rpm  rr  stap  test  tools  trace.dat  trace.log
% time     seconds  usecs/call     calls    errors syscall★
------ ----------- ----------- --------- --------- ----------------
  2.83    0.000055          28         2         1 access
  0.21    0.000004           4         1           arch_prctl
  1.80    0.000035          12         3           brk
  6.64    0.000129          10        13           close
  2.16    0.000042          42         1           execve
  6.54    0.000127          12        11           fstat
-以下、略-

15 UNIXドメインソケットを監視する方法

UNIXドメインソケットを流れるデータの監視方法について説明します。

15.1 事前準備(テストプログラムの作成)

サーバ側TP
[root@server test]# 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);
    }
}
クライアント側TP
[root@server test]# 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);
}
TPのコンパイル
[root@server test]# gcc -Wall -o sv sv.c
[root@server test]# gcc -Wall -o cl cl.c
[root@server test]# ls
cl  cl.c  sv  sv.c

15.2 実験結果

ターミナル1(サーバの起動)
[root@server test]# ./sv
ターミナル2(UNIXドメインソケットの確認)
[root@server ~]# lsof -c sv -a -U
COMMAND  PID USER   FD   TYPE             DEVICE SIZE/OFF  NODE NAME
sv      1198 root    3u  unix 0xffff8800b953a400      0t0 21628 /tmp/afunix_test
ターミナル3(クライアントの起動)
[root@server test]# ./cl
ターミナル2(UNIXドメインソケットの確認)
[root@server ~]# lsof -c sv -a -U
COMMAND  PID USER   FD   TYPE             DEVICE SIZE/OFF  NODE NAME
sv      1198 root    3u  unix 0xffff8800b953a400      0t0 21628 /tmp/afunix_test
sv      1198 root    4u  unix 0xffff8800b94bb800      0t0 22613 /tmp/afunix_test
ターミナル2(straceの実行)
[root@server ~]# strace -f -e trace=read,write -e read=3,4 -e write=3,4 -p 1198
strace: Process 1198 attached
read(4,

クライアントで"12345"を入力する。

ターミナル3(クライアントの起動)
[root@server test]# ./cl
12345

クライアントで入力した文字列("12345")が、サーバのFD=4より読み出されていることがわかる。

ターミナル2(straceの実行結果)
[root@server ~]# strace -f -e trace=read,write -e read=3,4 -e write=3,4 -p 1198
strace: Process 1198 attached
read(4, "12345\n", 100)                 = 6
 | 00000  31 32 33 34 35 0a                                 12345.           |
write(1, "12345\n", 6)                  = 6
read(4,

x 参考情報

0から作るLinuxプログラム システムコールその1
Linuxシステムコール徹底ガイド

hana_shin
写真は淡路島SAから明石海峡大橋を撮影したものです('19夏撮影)。'20年夏も3年連続で四国、大阪に行く予定!毎回車でいってます。今から楽しみぃ~。次は、四国の四万十川に行ってみたいけど、ちょっと遠いかな?最近はネットワークに力を入れてます。保有国家資格:ネットワークスペシャリスト、オンライン情報処理技術者。メールは hana.shin.2018@gmail.com まで。
https://hana-shin.hatenablog.com/
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした