17 トレーシングツール #Edit source
openSUSE Leap には、お使いのシステムに関して情報の採取を行うためのツールがいくつか用意されています。この情報採取では、たとえばプログラム内での問題を解析 (デバッグ) したり検出したり、性能面での問題点となっている箇所の発見や、プログラムの動作中に使用しているシステムリソースを見つけたりすることができます。
注記: トレーシングによる性能面への影響について
動作中のプロセスに対してシステムコールやライブラリコールの監視を行うと、そのプロセスの性能が大幅に落ちることになります。そのため、トレーシングツールの使用は、データ収集の際にのみ実施することをお勧めします。
17.1 strace によるシステムコールの追跡 #Edit source
strace コマンドは、プロセスが使用したシステムコールと、プロセスが受信したシグナルを追跡するためのコマンドです。 strace では新しくプロセスを起動してシステムコールを追跡することができるほか、既に実行されているコマンドに接続して、システムコールを追跡することもできます。コマンドの出力の各行にはシステムコールの名前のほか、括弧でくくられたパラメータの一覧と返り値も表示されます。
新しくコマンドを起動してシステムコールの追跡を開始したい場合は、通常のコマンドラインの前に strace を入れて実行します:
> strace ls
execve("/bin/ls", ["ls"], [/* 52 vars */]) = 0
brk(0) = 0x618000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) \
= 0x7f9848667000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) \
= 0x7f9848666000
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=200411, ...}) = 0
mmap(NULL, 200411, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f9848635000
close(3) = 0
open("/lib64/librt.so.1", O_RDONLY) = 3
[...]
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) \
= 0x7fd780f79000
write(1, "Desktop
Documents
bin
inst-sys
", 31Desktop
Documents
bin
inst-sys
) = 31
close(1) = 0
munmap(0x7fd780f79000, 4096) = 0
close(2) = 0
exit_group(0) = ?既に起動しているプロセスに対して strace を接続するには、接続先のプロセスのプロセス ID ( PID ) を -p パラメータで指定します:
> strace -p `pidof cron`
Process 1261 attached
restart_syscall(<... resuming interrupted call ...>) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
select(5, [4], NULL, NULL, {0, 0}) = 0 (Timeout)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(5, "\2\0\0\0\0\0\0\0\5\0\0\0root\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=5, revents=POLLIN|POLLHUP}])
read(5, "\2\0\0\0\1\0\0\0\5\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\6\0\0\0"..., 36) = 36
read(5, "root\0x\0root\0/root\0/bin/bash\0", 28) = 28
close(5) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {0x7f772b9ea890, [], SA_RESTORER|SA_RESTART, 0x7f772adf7880}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({60, 0}, 0x7fff87d8c580) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
select(5, [4], NULL, NULL, {0, 0}) = 0 (Timeout)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(5, "\2\0\0\0\0\0\0\0\5\0\0\0root\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=5, revents=POLLIN|POLLHUP}])
read(5, "\2\0\0\0\1\0\0\0\5\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\6\0\0\0"..., 36) = 36
read(5, "root\0x\0root\0/root\0/bin/bash\0", 28) = 28
close(5)
[...]-e オプションはいくつかのサブオプションを指定するための仕組みです。たとえばファイルに対する open や write だけを追跡したい場合は、下記のように入力して実行します:
> strace -e trace=open,write ls ~
open("/etc/ld.so.cache", O_RDONLY) = 3
open("/lib64/librt.so.1", O_RDONLY) = 3
open("/lib64/libselinux.so.1", O_RDONLY) = 3
open("/lib64/libacl.so.1", O_RDONLY) = 3
open("/lib64/libc.so.6", O_RDONLY) = 3
open("/lib64/libpthread.so.0", O_RDONLY) = 3
[...]
open("/usr/lib/locale/cs_CZ.utf8/LC_CTYPE", O_RDONLY) = 3
open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
write(1, "addressbook.db.bak
bin
cxoffice
"..., 311) = 311ネットワーク関連のシステムコールのみを追跡したい場合は、 -e trace=network を指定します:
> strace -e trace=network -p 26520
Process 26520 attached - interrupt to quit
socket(PF_NETLINK, SOCK_RAW, 0) = 50
bind(50, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
getsockname(50, {sa_family=AF_NETLINK, pid=26520, groups=00000000}, \
[12]) = 0
sendto(50, "\24\0\0\0\26\0\1\3~p\315K\0\0\0\0\0\0\0\0", 20, 0,
{sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
[...]-c オプションを指定すると、それぞれのシステムコールでカーネルが費やした時間を計算することができます:
> strace -c find /etc -name xorg.conf
/etc/X11/xorg.conf
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
32.38 0.000181 181 1 execve
22.00 0.000123 0 576 getdents64
19.50 0.000109 0 917 31 open
19.14 0.000107 0 888 close
4.11 0.000023 2 10 mprotect
0.00 0.000000 0 1 write
[...]
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 3 1 futex
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 4 fadvise64
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.000559 3633 33 total子プロセスについても追跡を行いたい場合は、 -f を指定します:
> strace -f systemctl status apache2.service
execve("/usr/bin/systemctl", ["systemctl", "status", "apache2.service"], \
0x7ffea44a3318 /* 56 vars */) = 0
brk(NULL) = 0x5560f664a000
[...]
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f98c58a5000
mmap(NULL, 4420544, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f98c524a000
mprotect(0x7f98c53f4000, 2097152, PROT_NONE) = 0
[...]
[pid 9130] read(0, "\342\227\217 apache2.service - The Apache"..., 8192) = 165
[pid 9130] read(0, "", 8027) = 0
● apache2.service - The Apache Webserver227\217 apache2.service - Th"..., 193
Loaded: loaded (/usr/lib/systemd/system/apache2.service; disabled; vendor preset: disabled)
Active: inactive (dead)
) = 193
[pid 9130] ioctl(3, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
[pid 9130] exit_group(0) = ?
[pid 9130] +++ exited with 0 +++
<... waitid resumed>{si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9130, \
si_uid=0, si_status=0, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9130, si_uid=0, \
si_status=0, si_utime=0, si_stime=0} ---
exit_group(3) = ?
+++ exited with 3 +++strace の出力を分析したいものの、コンソールウインドウ内に表示してしまうと長すぎるような場合は、 -o オプションをお使いください。この場合、プロセスへの接続や接続終了などのメッセージが省略されます。また、通常は標準出力に書かれるようなメッセージについても、 -q を指定することで省略することができます。このほか、それぞれのシステムコールの行に対して、行頭に時刻を表示させたい場合は、 -t を指定します:
> strace -t -o strace_sleep.txt sleep 1; more strace_sleep.txt
08:44:06 execve("/bin/sleep", ["sleep", "1"], [/* 81 vars */]) = 0
08:44:06 brk(0) = 0x606000
08:44:06 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, \
-1, 0) = 0x7f8e78cc5000
[...]
08:44:06 close(3) = 0
08:44:06 nanosleep({1, 0}, NULL) = 0
08:44:07 close(1) = 0
08:44:07 close(2) = 0
08:44:07 exit_group(0) = ?strace の動作や出力形式は変更することができます。詳しくは strace のマニュアルページ (man 1 strace) をお読みください。
17.2 ltrace によるライブラリコールの追跡 #Edit source
ltrace はプロセスの動的なライブラリコールを追跡することができます。 strace と同様の用途で使用するツールであり、ほとんどのパラメータは似通っているか、同じ意味になっています。既定では ltrace は、 /etc/ltrace.conf もしくは ~/.ltrace.conf にある設定ファイルを使用します。それ以外の設定ファイルを使用したい場合は、 -F 設定ファイル オプションを指定してください。
ltrace で -S オプションを指定すると、ライブラリコールに加えて システムコールについても追跡を行うことができます:
> ltrace -S -o ltrace_find.txt find /etc -name \
xorg.conf; more ltrace_find.txt
SYS_brk(NULL) = 0x00628000
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f1327ea1000
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f1327ea0000
[...]
fnmatch("xorg.conf", "xorg.conf", 0) = 0
free(0x0062db80) = <void>
__errno_location() = 0x7f1327e5d698
__ctype_get_mb_cur_max(0x7fff25227af0, 8192, 0x62e020, -1, 0) = 6
__ctype_get_mb_cur_max(0x7fff25227af0, 18, 0x7f1327e5d6f0, 0x7fff25227af0,
0x62e031) = 6
__fprintf_chk(0x7f1327821780, 1, 0x420cf7, 0x7fff25227af0, 0x62e031
<unfinished ...>
SYS_fstat(1, 0x7fff25227230) = 0
SYS_mmap(0, 4096, 3, 34, 0xffffffff) = 0x7f1327e72000
SYS_write(1, "/etc/X11/xorg.conf
", 19) = 19
[...]-e オプションを指定することで、追跡するイベントの種類を変更することができます。下記の例では、 fnmatch と strlen に関連したライブラリコールを表示しています:
> ltrace -e fnmatch,strlen find /etc -name xorg.conf
[...]
fnmatch("xorg.conf", "xorg.conf", 0) = 0
strlen("Xresources") = 10
strlen("Xresources") = 10
strlen("Xresources") = 10
fnmatch("xorg.conf", "Xresources", 0) = 1
strlen("xorg.conf.install") = 17
[...]特定のライブラリ内に含まれているシンボルのみを表示したい場合は、 -l ライブラリのパス オプションを指定します:
> ltrace -l /lib64/librt.so.1 sleep 1
clock_gettime(1, 0x7fff4b5c34d0, 0, 0, 0) = 0
clock_gettime(1, 0x7fff4b5c34c0, 0xffffffffff600180, -1, 0) = 0
+++ exited (status 0) +++入れ子になった呼び出し構造を読みやすくするため、 -n スペース数 というオプションを指定すると、インデントを設定することもできます。
17.3 Valgrind によるデバッグとプロファイリング #Edit source
Valgrind はプログラムをデバッグしたりプロファイルしたりするためのツール集で、これによってより高速に、エラーの少ないプログラムを作ることができるようになります。 Valgrind はメモリ管理やスレッドに関する問題点を検出することができるほか、新しいデバッグツールを作成するためのフレームワークとしても使用することができます。ただし、このツールはオーバーヘッドが大きく、複数の処理を同時に実行するような状況では、通常よりもずっと遅い速度になってしまうことに注意する必要があります。
17.3.1 一般的な情報 #Edit source
Valgrind の主な利点は、コンパイル済みの実行ファイルの問題を直接検出できる点にあります。プログラムをコンパイルし直したり、修正したりする必要はありません。 Valgrind は下記のようにして使用します:
valgrind Valgrind_のオプション プログラム名 プログラムのオプション
Valgrind には、様々な機能を持つツールが含まれています。本章で説明しているのは非常に一般的なもので、ツールとは無関係に使用できるものばかりです。 Valgrind の設定オプションで最も重要なものは --tool で、ここではどのツールを使用するのかを指定することができます。このオプションを省略すると、既定では memcheck が選択されたものと見なされます。たとえば Valgrind の memcheck ツールで find ~ -name .bashrc を実行したい場合は、下記のように入力して実行します:
valgrind --tool =memcheck find ~ -name .bashrc
Valgrind で提供されているツールの一覧と、その簡潔な説明は下記のとおりです:
memcheckメモリエラーを検出します。お使いのプログラムの動作をチェックして、正しく動作するように支援するためのツールです。
cachegrindキャッシュ予測のプロファイルを行います。お使いのプログラムをより高速に動作させるためのヒントを提示する仕組みです。
callgrindcachegrindと同様の処理を行うツールですが、追加でキャッシュプロファイル情報も収集します。exp-drdスレッドのエラーを検出します。マルチスレッド型のプログラムの動作をチェックして、正しく動作するように支援する仕組みです。
helgrindもう 1 つのスレッドエラー検出ツールです。
exp-drdに似ていますが、問題の分析に際して異なる技術を使用します。massifヒーププロファイラです。ヒープは動的なメモリ管理に使用するメモリ領域で、このツールは少ないメモリ量で動作するように、プログラムをチューニングする支援を行います。
lackey基本的な仕組みを説明するためのサンプルツールです。
17.3.2 既定のオプション #Edit source
Valgrind はその起動時にオプションを読み込みます。 Valgrind がオプションをチェックする箇所には、下記の 3 種類のものがあります:
Valgrind を起動するユーザのホームディレクトリ内にある、
.valgrindrcファイル。環境変数
$VALGRIND_OPTS。Valgrind を起動する時点でのカレントディレクトリ内にある
.valgrindrcファイル。
これらのリソースは上記の順序で処理が行われます。そのため、前のほうのファイルで設定を行っていても、後ろのほうのファイル内に同じ設定があれば、上書きされることになります。また、特定の Valgrind ツールに固有のオプションを指定する場合は、ツールの名前とコロンを付けなければなりません。たとえば cachegrind に対して、プロファイルデータを /tmp/cachegrind_PID.log に書き込むように指定するには、ホームディレクトリの .valgrindrc ファイル内に、下記の内容を記述します:
--cachegrind:cachegrind-out-file=/tmp/cachegrind_%p.log
17.3.3 Valgrind の動作原理 #Edit source
Valgrind は実行ファイルの起動が行われる前から、その制御を実施します。実行ファイルのデバッグ情報を読み込み、関連する共有ライブラリを読み込みます。実行ファイルのコードは、選択された Valgrind ツールに転送され、ツール側でデバッグ処理のためのコードを追加したあと、 Valgrind のコアに戻され、実際の実行が行われます。
たとえば memcheck では、それぞれのメモリアクセスに対してチェックを行うコードを追加します。そのため、プログラムは通常の実行よりもずっと遅くなります。
Valgrind はプログラム内の各インストラクションを擬似します。そのため、プログラムのコードをチェックするだけでなく、関連するライブラリ (C ライブラリを含む) やグラフィカル環境で使用されるライブラリまでも、チェックすることができます。 Valgrind でエラーを検出しようとすると、関連するライブラリ (C ライブラリ, X11, Gtk ライブラリなど) のエラーも検出することになります。これらのエラーについては通常検出する必要はありませんので、省略設定ファイルを作成して Valgrind 側で省略するように指定することができます。 --gen-suppressions=yes を指定して実行すると、 Valgrind に対して省略用の設定を作成させることができます。
Valgrind のパラメータには実際の実行ファイル (マシンコード) を指定してください。シェルや Perl のスクリプトなどからお使いのアプリケーションを起動してしまうと、 /bin/sh (または /usr/bin/perl ) を起動することによる無関係なエラーが表示されることがありますので、この場合は --trace-children=yes を指定して、エラーを回避してください。ただし、通常は実行ファイルを直接指定して実行してください。
17.3.4 メッセージ #Edit source
Valgrind は、その実行中に詳細なエラーメッセージや重要なイベントを報告することがあります。下記にメッセージの出力例を示します:
> valgrind --tool=memcheck find ~ -name .bashrc
[...]
==6558== Conditional jump or move depends on uninitialised value(s)
==6558== at 0x400AE79: _dl_relocate_object (in /lib64/ld-2.11.1.so)
==6558== by 0x4003868: dl_main (in /lib64/ld-2.11.1.so)
[...]
==6558== Conditional jump or move depends on uninitialised value(s)
==6558== at 0x400AE82: _dl_relocate_object (in /lib64/ld-2.11.1.so)
==6558== by 0x4003868: dl_main (in /lib64/ld-2.11.1.so)
[...]
==6558== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 0 from 0)
==6558== malloc/free: in use at exit: 2,228 bytes in 8 blocks.
==6558== malloc/free: 235 allocs, 227 frees, 489,675 bytes allocated.
==6558== For counts of detected errors, rerun with: -v
==6558== searching for pointers to 8 not-freed blocks.
==6558== checked 122,584 bytes.
==6558==
==6558== LEAK SUMMARY:
==6558== definitely lost: 0 bytes in 0 blocks.
==6558== possibly lost: 0 bytes in 0 blocks.
==6558== still reachable: 2,228 bytes in 8 blocks.
==6558== suppressed: 0 bytes in 0 blocks.
==6558== Rerun with --leak-check=full to see details of leaked memory.上記の Valgrind の出力例には ==6558== が含まれていますが、これはプロセス ID 番号 (PID) を表しています。これにより、 Valgrind のメッセージとプログラム自身の出力を区別できるようになっているほか、 Valgrind のメッセージがどのプロセスに対するものであるのかがわかるようにもなっています。
Valgrind のメッセージをより詳細に出力させたい場合は、 -v もしくは -v -v のように指定してください。
Valgrind の出力するメッセージを制御するには、下記のようにして行います:
既定では、 Valgrind がメッセージを送信する際、出力先をファイルディスクリプタの 2 番 (つまり標準エラー出力) に設定します。それ以外のファイルディスクリプタ番号を使用したい場合は、
--log-fd=ファイルディスクリプタ番号のように指定してください。おそらくはこちらの方法のほうが期待されるとは思いますが、もう 1 つの方法として、
--log-file=ファイル名のように指定することで、ログを指定したファイルに書き込むこともできます。このオプションを指定するにあたっては、いくつかのプレースホルダを使用することができます。たとえばファイル名の一部に%pを指定すると、その部分にはプロファイル対象のプログラムのプロセス ID (PID) が埋め込まれるようになります。また、%q{env_var}のように指定すると、env_varという名前の環境変数の値を展開して出力することができます。下記の例では、 Apache Web サーバの再起動時にメモリエラーが発生していないかどうかを確認している例となります。この場合、子プロセスも追跡して、詳細な Valgrind メッセージをプロセス ID ごとに分けて別々のファイルに書き込むように指定しています:
>valgrind -v --tool=memcheck --trace-children=yes \ --log-file=valgrind_pid_%p.log systemctl restart apache2.serviceこの処理を実行すると、テストで使用した環境の場合 52 個のログファイルを作成していたほか、通常であれば 7 秒程度で
sudo systemctl restart apache2.serviceを処理できていたところ、 Valgrind を入れることによって、おおよそ 10 倍の 75 秒程度かかるようになっていました。>ls -1 valgrind_pid_*log valgrind_pid_11780.log valgrind_pid_11782.log valgrind_pid_11783.log [...] valgrind_pid_11860.log valgrind_pid_11862.log valgrind_pid_11863.logValgrind のメッセージをネットワーク経由で送信したいと思うことがあるかもしれません。そのような場合は、
--log-socket=aa.bb.cc.dd:port_numのような形式でオプションを指定してください。ここで、aa.bb.cc.ddには送信先の IP アドレスを、port_numには送信先のポート番号をそれぞれ指定します。ポート番号を省略した場合は、 1500 を使用します。Valgrind のメッセージをネットワークソケット経由で送信する場合、受信側のアプリケーションを用意しないと意味がありません。 Valgrind では
valgrind-listenerと呼ばれるシンプルなリスナーが同梱されていて、指定したポートで接続を待ち受けて、受信した内容をそのまま標準出力に出力することができます。
17.3.5 エラーメッセージ #Edit source
Valgrind では全てのエラーメッセージを記憶していて、新しいエラーを検出すると既存のエラーメッセージと比較を行います。この方法により、 Valgrind はエラーを繰り返し表示するような事態を防いでいます。同じエラーが発生した場合、 Valgrind は単純にそのメッセージを記録するだけで、メッセージを表示しなくなります。この仕組みにより、似たようなエラーを多数受け取って混乱を起こすことがないようになっています。
-v オプションを指定すると、 Valgrind の実行出力の最後に全ての概要レポート (発生回数順に並べたもの) を表示することができます。これに加えて、 Valgrind では 1000 種類以上のエラーが発生した場合や、合計で 10,000,000 回以上のエラーが発生した場合、エラーの収集処理を停止する機能があります。このような制限を無効化して、全てのエラーメッセージを表示するようにしたい場合は、 --error-limit=no を指定してください。
エラーによっては他のエラーを引き起こす種類のものもあります。そのため、エラーを修正する場合は、その発生順に行うものとし、プログラムを繰り返しチェックし直してください。
17.4 さらなる情報 #Edit source
上記のトレーシングツールに関連する全オプションの一覧を確認するには、それぞれ対応するマニュアルページ (
man 1 strace,man 1 ltrace,man 1 valgrind) をお読みください。Valgrind の高度な使用方法については、本書では説明していません。詳しい説明を読みたい場合は、 Valgrind User Manual (英語) をお読みください。これらのページは Valgrind をより高度に使用したり、標準ツールの使い方や目的を知ったりしたい場合には、必須の情報源です。