プログラムから呼ばれるシステムコールを確認する (strace)

straceはプログラムから呼ばれるLinuxのシステムコールをトレースするためのツールです。 Linuxのプログラムはその動作の中で様々なシステムコールを呼びますが、strace経由でプログラムを実行すると、プログラムが呼び出したシステムコールの情報を出力することができるためプログラムのバグや動作を確認するために利用することができます。

$ strace "プログラム"

とやることでLinuxのプログラムが呼んでいるシステムコールを出力します。 また、-pオプションでPIDを指定することもできるので実行中のプログラムのトレースを行うこともできます。

$ starce -p "PID"

straceの出力は大変多いので、ファイルに出力するほうが良いと思いますが、その場合は-oオプションで出力ファイルを指定できます。 以下のようにすると実行中のプログラムのトレースが簡単に記録しながら確認できるので便利です。

$ strace -p "PID" -o strace.log
$ tail -f strace.log

インストール

例を見るのが一番早いと思いますが、通常インストールされていないことも多いので、まずインストール。

$ sudo yum -y install strace
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
* base: www.ftp.ne.jp
* epel: ftp.iij.ad.jp
* extras: www.ftp.ne.jp
* rpmforge: mirror.fairway.ne.jp
* updates: www.ftp.ne.jp
Setting up Install Process
Resolving Dependencies
--> Running transaction check
---> Package strace.x86_64 0:4.5.19-1.17.el6 will be installed
--> Finished Dependency Resolution

Dependencies Resolved

======================================================================================================    Package                Arch            Version            Repository             Size
======================================================================================================    Installing:
strace                 x86_64          4.5.19-1.17.el6    base                  172 k

Transaction Summary
======================================================================================================
Install       1 Package(s)

Total download size: 172 k
Installed size: 533 k
Downloading Packages:
strace-4.5.19-1.17.el6.x86_64.rpm                                                                                                                                                 | 172 kB     00:02
Running rpm_check_debug
Running Transaction Test
Transaction Test Succeeded
Running Transaction
 Installing : strace-4.5.19-1.17.el6.x86_64                                            1/1
 Verifying  : strace-4.5.19-1.17.el6.x86_64                                            1/1

Installed:
 strace.x86_64 0:4.5.19-1.17.el6

Complete!

試してみる

簡単な例としてecho コマンドの出力をファイルに書き出す例を見てみます。 最初の2行は、一応、出力があるのでディレクトリを作ってそのなかでやっているだけです。

$ mkdir strace
$ cd strace
$ strace echo "test" > test_file
execve("/bin/echo", ["echo", "test"], [/* 39 vars */]) = 0
brk(0)                                  = 0xaf5000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f72c000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=36592, ...}) = 0
mmap(NULL, 36592, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f4d8f723000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY)      = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1912432, ...}) = 0
mmap(NULL, 3741864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f4d8f17c000
mprotect(0x7f4d8f305000, 2093056, PROT_NONE) = 0
mmap(0x7f4d8f504000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x188000) = 0x7f4d8f504000
mmap(0x7f4d8f509000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f509000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f722000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f721000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f720000
arch_prctl(ARCH_SET_FS, 0x7f4d8f721700) = 0
mprotect(0x7f4d8f504000, 16384, PROT_READ) = 0
mprotect(0x7f4d8f72d000, 4096, PROT_READ) = 0
munmap(0x7f4d8f723000, 36592)           = 0
brk(0)                                  = 0xaf5000
brk(0xb16000)                           = 0xb16000
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=99154480, ...}) = 0
mmap(NULL, 99154480, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f4d892ec000
close(3)                                = 0
fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d8f72b000
write(1, "test\n", 5)                   = 5
close(1)                                = 0
munmap(0x7f4d8f72b000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?


execve("/bin/echo", ["echo", "test"], [/* 39 vars */]) = 0

と

exit_group(0)                           = ?

の間で結構いろんなものをopenしてcloseしているのが分かりますが、最終的には最後から5行目のところで、"test(と改行)"をwriteしています。

次にこのファイルを削除してみると下のように出力されます。

$ strace rm test_file
execve("/bin/rm", ["rm", "test_file"], [/* 39 vars */]) = 0
brk(0)                                  = 0x1b41000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f51e9217000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=36592, ...}) = 0
mmap(NULL, 36592, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f51e920e000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY)      = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1912432, ...}) = 0
mmap(NULL, 3741864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f51e8c67000
mprotect(0x7f51e8df0000, 2093056, PROT_NONE) = 0
mmap(0x7f51e8fef000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x188000) = 0x7f51e8fef000
mmap(0x7f51e8ff4000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f51e8ff4000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f51e920d000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f51e920c000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f51e920b000
arch_prctl(ARCH_SET_FS, 0x7f51e920c700) = 0
mprotect(0x7f51e8fef000, 16384, PROT_READ) = 0
mprotect(0x7f51e9218000, 4096, PROT_READ) = 0
munmap(0x7f51e920e000, 36592)           = 0
brk(0)                                  = 0x1b41000
brk(0x1b62000)                          = 0x1b62000
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=99154480, ...}) = 0
mmap(NULL, 99154480, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f51e2dd7000
close(3)                                = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B9600 opost isig icanon echo ...}) = 0
newfstatat(AT_FDCWD, "test_file", {st_mode=S_IFREG|0664, st_size=5, ...}, AT_SYMLINK_NOFOLLOW) = 0
geteuid()                               = 500
newfstatat(AT_FDCWD, "test_file", {st_mode=S_IFREG|0664, st_size=5, ...}, AT_SYMLINK_NOFOLLOW) = 0
faccessat(AT_FDCWD, "test_file", W_OK)  = 0
unlinkat(AT_FDCWD, "test_file", 0)      = 0
close(0)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?

こちらもたくさん出ますが、最後から5行目のところのunlinkatが実際の削除にあたる部分です。

トレース情報にタイムスタンプを追加するには-tオプションが使えます。

$ strace -t echo "test" > test_file
21:50:18 execve("/bin/echo", ["echo", "test"], [/* 39 vars */]) = 0
21:50:18 brk(0)                         = 0x18b4000
21:50:18 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa27097b000
21:50:18 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
21:50:18 open("/etc/ld.so.cache", O_RDONLY) = 3
21:50:18 fstat(3, {st_mode=S_IFREG|0644, st_size=36592, ...}) = 0
21:50:18 mmap(NULL, 36592, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa270972000
21:50:18 close(3)                       = 0
21:50:18 open("/lib64/libc.so.6", O_RDONLY) = 3
21:50:18 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\1\0\0\0\0\0"..., 832) = 832
21:50:18 fstat(3, {st_mode=S_IFREG|0755, st_size=1912432, ...}) = 0
21:50:18 mmap(NULL, 3741864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa2703cb000
21:50:18 mprotect(0x7fa270554000, 2093056, PROT_NONE) = 0
21:50:18 mmap(0x7fa270753000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x188000) = 0x7fa270753000
21:50:18 mmap(0x7fa270758000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa270758000
21:50:18 close(3)                       = 0
21:50:18 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa270971000
21:50:18 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa270970000
21:50:18 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa27096f000
21:50:18 arch_prctl(ARCH_SET_FS, 0x7fa270970700) = 0
21:50:18 mprotect(0x7fa270753000, 16384, PROT_READ) = 0
21:50:18 mprotect(0x7fa27097c000, 4096, PROT_READ) = 0
21:50:18 munmap(0x7fa270972000, 36592)  = 0
21:50:18 brk(0)                         = 0x18b4000
21:50:18 brk(0x18d5000)                 = 0x18d5000
21:50:18 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
21:50:18 fstat(3, {st_mode=S_IFREG|0644, st_size=99154480, ...}) = 0
21:50:18 mmap(NULL, 99154480, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa26a53b000
21:50:18 close(3)                       = 0
21:50:18 fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
21:50:18 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa27097a000
21:50:18 write(1, "test\n", 5)          = 5
21:50:18 close(1)                       = 0
21:50:18 munmap(0x7fa27097a000, 4096)   = 0
21:50:18 close(2)                       = 0
21:50:18 exit_group(0)                  = ?

どんなシステムコールが何回呼ばれているかや、どれぐらいの時間CPUタイムを消費しているかなどといった統計情報を出すためには-cオプションを使用します。

$ strace -c echo "test" > test_file
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000081          81         1         1 access
  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         4           fstat
  0.00    0.000000           0        10           mmap
  0.00    0.000000           0         3           mprotect
  0.00    0.000000           0         2           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000081                    35         1 total

統計情報をみて、気になるシステムコールがあれば、必要なものだけに表示を絞ると出力が見やすくなるので分析時には有効です。 必要なシステムコールに出力を絞るには-eオプションを使用します。以下の例では、open、close、read、writeだけに絞っています。

$ strace -e open,close,read,write echo "test" > test_file
open("/etc/ld.so.cache", O_RDONLY)      = 3
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY)      = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\1\0\0\0\0\0"..., 832) = 832
close(3)                                = 0
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
close(3)                                = 0
write(1, "test\n", 5)                   = 5
close(1)                                = 0
close(2)                                = 0

その他、トレース対象のプログラムが子プロセスを生成し、子プロセスをトレースする必要がある場合は-fオプションを使うことで実現出来ます。 この様にプログラムのなかで何が行われているかを確認するのに便利なのがstraceです。ほかにもいろいろ機能が豊富で、使いこなすとデバッグ時の強力なツールになると思います。自分のプログラムのデバッグだけでなく、いろいろと試してみると意外な発見があって面白いと思います。

• システムステータス確認
• 設定・構成の確認
• 接続されたPCIデバイスを確認する (lspci)
• 使用しているカーネルモジュールを確認する (lsmod, modinfo)
• CPUの型番やスペックなどの情報を確認する方法 (lscpu)
• CPUの型番やスペックなどの情報を確認する方法 (cpuinfo)
• LinuxでOSが32bit版か64bit版かを確認する方法 (uname)
• 自動起動するプロセスの確認と設定 (chkconfig)
• インストール方法毎の自動起動プロセスについて (chkconfig)
• rpmパッケージのインストール、アップデート、アンインストール (rpm -ivh/rpm -Uvh/rpm -e)
• rpmパッケージインストールに必要な依存パッケージを調べる (rpm -pqR)
• 指定したパッケージに依存しているパッケージを調べる (rpm -q --whatrequires)
• rpmインストールでインストールされたファイルの一覧取得 (rpm -ql)
• インストールされているrpmを確認する (rpm -qa)
• rpmがいつインストールされたかを調べる (rpm -qi)
• どのrpmパッケージでインストールされたかを確認する (rpm -qf)
• rpmパッケージファイルに含まれるファイルを確認する (rpm -qpl)
• ネットワーク設定・状態を確認する
• 間隔や実行回数等を変えてネットワークの疎通確認を実行する (ping)
• 通信経路を確認する (traceroute)
• NICの接続状態を確認する (ethtool)
• IPアドレスの重複を確認する (arping)
• DNS問合せによる名前解決 (nslookup)
• WAN側IPアドレスを確認する
• システムのヘルスステータスを確認する
• サーバの各種リソース使用状況を記録・確認する (sysstat)
• プロセス単位のリソース使用量を調べる (pidstat)
• サーバの各種リソース使用状況を確認する (dstat)
• 各パーティション、マウントポイントの空き領域を確認する (df)
• メモリ使用量確認方法いろいろ
• プログラムから呼ばれるシステムコールを確認する (strace)
• プログラムやユーザが使用中のファイルを調べる (lsof)