- 1 ltraceコマンドとは?
- 2 検証環境
- 3 インストール方法
- 4 オプション一覧
- 5 テストプログラム（以降TP）の作成
- 6 ライブラリ関数の実行順序を表示する方法
- 7 時刻情報を表示する方法
- 8 実行結果を絞り込む方法(-e trace)
- 9 システムコールを表示する方法(-S)
- 10 表示する文字列数を調整する方法(-s)
- 11 実行結果をファイルに保存する方法(-o)
- 12 子プロセス／スレッドをトレースする方法(-f)
- 13 特定のライブラリ関数だけを表示する方法(-l)
- 14 統計情報を表示する方法(-c)
- Z 参考情報
1 ltraceコマンドとは?
プロセスが実行する関数をトレースするためのコマンドです。なお、システムコールのトレースには、straceコマンドを使います。straceコマンドの使い方は、straceコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。
2 検証環境
AlmaLinuxの版数は以下のとおりです。
[root@server ~]# cat /etc/redhat-release AlmaLinux release 8.6 (Sky Tiger)
カーネル版数は以下のとおりです。
[root@server ~]# uname -r 4.18.0-372.9.1.el8.x86_64
3 インストール方法
ltraceパッケージをインストールします。
[root@server ~]# dnf -y install ltrace
版数を確認します。
[root@server ~]# ltrace -V ltrace 0.7.91
4 オプション一覧
オプションは以下のとおりです。
[root@server ~]# ltrace -h Usage: ltrace [option ...] [command [arg ...]] Trace library calls of a given program. -a, --align=COLUMN align return values in a secific column. -A MAXELTS maximum number of array elements to print. -b, --no-signals don't print signals. -c count time and calls, and report a summary on exit. -C, --demangle decode low-level symbol names into user-level names. -D, --debug=MASK enable debugging (see -Dh or --debug=help). -Dh, --debug=help show help on debugging. -e FILTER modify which library calls to trace. -f trace children (fork() and clone()). -F, --config=FILE load alternate configuration file (may be repeated). -h, --help display this help and exit. -i print instruction pointer at time of library call. -l, --library=LIBRARY_PATTERN only trace symbols implemented by this library. -L do NOT display library calls. -n, --indent=NR indent output by NR spaces for each call level nesting. -o, --output=FILENAME write the trace output to file with given name. -p PID attach to the process with the process ID pid. -r print relative timestamps. -s STRSIZE specify the maximum string size to print. -S trace system calls as well as library calls. -t, -tt, -ttt print absolute timestamps. -T show the time spent inside each call. -u USERNAME run command with the userid, groupid of username. -V, --version output version information and exit. -w, --where=NR print backtrace showing NR stack frames at most. -x FILTER modify which static functions to trace. Report bugs to ltrace-devel@lists.alioth.debian.org
5 テストプログラム（以降TP）の作成
ltraceの対象となるTPを作成します。
[root@server ~]# cat tp.c
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
int main(int argc, char *argv[])
{
struct timespec req;
char *p;
req.tv_sec = 2;
req.tv_nsec = 0;
for(;;) {
p=(char *)malloc(100);
strncpy(p, "012345678901234567890123456789012345678", 40);
printf("%s\n",p);
free(p);
nanosleep(&req, NULL);
}
}TPをコンパイルします。
[root@server ~]# gcc -Wall -o tp tp.c
実行ファイルを確認します。tpという名前の実行ファイルが作成されたことがわかります。
[root@server ~]# ls -l tp* -rwxr-xr-x. 1 root root 18192 11月 23 08:08 tp -rw-r--r--. 1 root root 388 11月 23 08:06 tp.c
6 ライブラリ関数の実行順序を表示する方法
ターミナルを2つ使います。ターミナル1でテストプログラムを起動します。
[root@server ~]# ./tp 012345678901234567890123456789012345678 012345678901234567890123456789012345678 -snip-
ターミナル2でテストプログラムのPIDを確認します。PID=8890 であることがわかります。なお、psコマンドの使い方は、psコマンドの使い方 - hana_shinのLinux技術ブログを参照ください。
[root@server ~]# ps -C tp
PID TTY TIME CMD
8890 pts/0 00:00:00 tpPID=8890 に対して、ltraceを実行します。malloc->puts->free->nanosleepの順序で繰り返し関数を呼び出していることがわかります。
[root@server ~]# ltrace -p 8890
malloc(100) = 0x8ae2a0
puts("01234567890123456789012345678901"...) = 40
free(0x8ae2a0) = <void>
nanosleep({ 2, 0 }, nil) = 0
-snip-
7 時刻情報を表示する方法
7.1 関数の実行時刻（秒単位）の表示方法(-t)
-tは、関数の実行時刻を秒単位で表示（左端の時刻）するオプションです。
[root@server ~]# ltrace -p 8890 -t
08:17:37 malloc(100) = 0x8ae2a0
08:17:37 puts("01234567890123456789012345678901"...) = 40
08:17:37 free(0x8ae2a0) = <void>
08:17:37 nanosleep({ 2, 0 }, nil) = 0
-snip-
7.2 関数の実行時刻（マイクロ秒単位）の表示方法(-tt)
-ttは、関数の実行時刻をマイクロ秒単位で表示（左端の時刻）するオプションです。
[root@server ~]# ltrace -p 8890 -tt
08:18:29.051837 malloc(100) = 0x8ae2a0
08:18:29.055810 puts("01234567890123456789012345678901"...) = 40
08:18:29.060301 free(0x8ae2a0) = <void>
08:18:29.063287 nanosleep({ 2, 0 }, nil) = 0
-snip-
7.3 関数の実行時間の表示方法(-T)
-Tは、関数を実行してから完了するまでの実行時間を表示するオプションです。右端の<>に囲まれた部分が、関数の実行時間を表しています。マイクロ秒単位の精度で表示されていることがわかります。nanosleep関数の実行時間は、TPで指定した2秒にほぼ等しい2.001000秒かかっていることがわかります。
[root@server ~]# ltrace -p 8890 -T
malloc(100) = 0x8ae2a0 <0.002453>
puts("01234567890123456789012345678901"...) = 40 <0.000805>
free(0x8ae2a0) = <void> <0.000318>
nanosleep({ 2, 0 }, nil) = 0 <2.001000>
-snip-
7.4 開始時刻の相対時間を表示する方法(-r)
-rオプションを指定すると、1つ前に実行した関数からの相対時間を表示することができます。ここでは、さらに-Tオプションも指定してみます。malloc(★1)は、nanosleep(★2)の実行開始から2.004081秒後に実行していることがわかります。
[root@server ~]# ltrace -p 8890 -r -T
0.000000 malloc(100) = 0x8ae2a0 <0.002059>
0.002854 puts("01234567890123456789012345678901"...) = 40 <0.004437>
0.004940 free(0x8ae2a0) = <void> <0.001227>
0.001498 nanosleep({ 2, 0 }, nil) ★2 = 0 <2.003671>
2.004081 malloc(100) ★1 = 0x8ae2a0 <0.000491>
-snip-
8 実行結果を絞り込む方法(-e trace)
8.1 特定の関数を表示する方法(-e trace=関数名)
malloc関数だけを表示してみます。
[root@server ~]# ltrace -p 8890 -e malloc exe->malloc(100) = 0x8ae2a0 exe->malloc(100) = 0x8ae2a0 exe->malloc(100) -snip-
次に、malloc関数とfree関数を表示してみます。
[root@server ~]# ltrace -p 8890 -e malloc -e free exe->malloc(100) = 0x8ae2a0 exe->free(0x8ae2a0) = <void> exe->malloc(100) = 0x8ae2a0 exe->free(0x8ae2a0) = <void> -snip-
9 システムコールを表示する方法(-S)
-Sは、関数の延長で呼び出すシステムコールを表示するオプションです。実行結果を確認すると、puts関数からwriteシステムコール、nanosleep関数からnanosleepシステムコールを呼び出しているのがわかります。
[root@server ~]# ltrace -p 8890 -S
restart_syscall@SYS(0x7ffe742c1f50, 0, 0, 3) = 0
malloc(100) = 0x8ae2a0
puts("01234567890123456789012345678901"... <unfinished ...>
write@SYS(1, "01234567890123456789012345678901"..., 40) = 40
<... puts resumed> ) = 40
free(0x8ae2a0) = <void>
nanosleep({ 2, 0 }, nil <unfinished ...>
nanosleep@SYS(0x7ffe742c1f50, 0, 0, 3) = 0
<... nanosleep resumed> ) = 0
-snip-
10 表示する文字列数を調整する方法(-s)
-sは、表示する文字列のバイト数を変更するオプションです。デフォルトの表示数は32バイトです。-sオプションを使うことで、表示する文字列のバイト数を変更することができます。
まず、デフォルトの実行結果を確認してみます。puts関数の第1パラメータに指定する文字列が32バイトであることがわかります。
[root@server ~]# ltrace -p 8890 -e puts
exe->puts("01234567890123456789012345678901"...) = 40
-snip-次に、表示するバイト数を33バイトにしてみます。puts関数の第1パラメータに指定する文字列が33バイトであることがわかります。
[root@server ~]# ltrace -p 8890 -e puts -s 33
exe->puts("012345678901234567890123456789012"...) = 40
-snip-最後に、表示するバイト数を34バイトにしてみます。puts関数の第1パラメータに指定する文字列が34バイトであることがわかります。
[root@server ~]# ltrace -p 8890 -e puts -s 34
exe->puts("0123456789012345678901234567890123"...) = 40
11 実行結果をファイルに保存する方法(-o)
-oは、ltraceコマンドの実行結果をファイルに保存するオプションです。ltraceの実行結果をltrace.txtに保存してみます。
[root@server ~]# ltrace -p 8890 -o ltrace.txt
ファイルに保存したltraceの実行結果を確認してみます。ライブラリ関数を実行したプロセスのPIDと関数名が表示されていることがわかります。
[root@server ~]# cat ltrace.txt
8890 malloc(100) = 0x8ae2a0
8890 puts("01234567890123456789012345678901"...) = 40
8890 free(0x8ae2a0) = <void>
8890 nanosleep({ 2, 0 }, nil) = 0
-snip-
12 子プロセス／スレッドをトレースする方法(-f)
-fは、親プロセスが生成する子プロセス／スレッドのトレースを表示するオプションです。ここでは、マルチスレッドのトレースを確認してみます。作成するテストプログラムは、1プロセスに2スレッドの構成です。
12.1 テストプログラム（以降TP）の作成
TPを作成します。
[root@server ~]# cat thread.c
#include <stdio.h>
#include <unistd.h>
#include <math.h>
#include <pthread.h>
int *threadFunc1(void)
{
double x = 4.0;
pow (x, 2.0);
sleep(10);
pthread_exit(NULL);
}
int main(int argc, char *argv[])
{
pthread_t t1;
for(;;){
pthread_create(&t1, NULL, (void *)&threadFunc1, NULL);
pthread_join(t1, NULL);
}
}テストプログラムをコンパイルします。pthread_create/pthread_joinは、libpthreadライブラリ、powは、libmライブラリにあるので、それぞれ、-lオプションをつけてコンパイルします。
[root@server ~]# gcc -Wall -lpthread -lm -o thread thread.c
作成したTPを確認します。
[root@server ~]# ls -l thread* -rwxr-xr-x. 1 root root 18304 11月 23 08:34 thread -rw-r--r--. 1 root root 350 11月 23 08:34 thread.c
作成したTPは、libcに加え、libmやlibpthreadをリンクしていることがわかります。
[root@server ~]# ldd thread
linux-vdso.so.1 (0x00007ffc1ed40000)
libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f75b0b68000)
libm.so.6 => /lib64/libm.so.6 (0x00007f75b07e6000)
libc.so.6 => /lib64/libc.so.6 (0x00007f75b0421000)
/lib64/ld-linux-x86-64.so.2 (0x00007f75b0d88000)
12.2 動作確認
TPを実行します。
[root@server ~]# ./thread
テストプログラムは、1プロセスに2スレッドであることがわかります。
[root@server ~]# ps -LC thread
PID LWP TTY TIME CMD
8941 8941 pts/1 00:00:00 thread
8941 8944 pts/1 00:00:00 thread
13 特定のライブラリ関数だけを表示する方法(-l)
-lは、-lで指定したライブラリに含まれる関数だけをトレースするオプションです。まずpsコマンドを実行して、TPのPIDを確認します。
[root@server ~]# ps -LC thread
PID LWP TTY TIME CMD
8941 8941 pts/1 00:00:00 thread
8941 8991 pts/1 00:00:00 threadTPのPIDを指定してltraceコマンドを実行します。このとき、-lオプションでlibmライブラリを指定して、libmライブラリに含まれる関数だけをトレースしてみます。
[root@server ~]# ltrace -p 8941 -f -l libm.so.6 [pid 8981] +++ exited (status 0) +++ [pid 8983] exe->pow(0, 0, 0xdf05251cfc03bac4, 0x7f43cf8b5149 <unfinished ...> [pid 8983] libm.so.6->__pow_finite(0, 0, 0xdf05251cfc03bac4, 0x7f43cf8b5149) = 0 [pid 8983] <... pow resumed> ) = 0 -snip-
次に、libpthreadに含まれる関数だけを表示してみます。pthread_create,pthread_join,pthread_exit関数が実行されていることがわかります。
[root@server ~]# ltrace -p 8941 -f -l libpthread.so.0 [pid 8997] exe->pthread_exit(0, 0x7f43cf164ea0, 0, 0x7f43cf260678 <no return ...> [pid 8997] +++ exited (status 0) +++ [pid 8941] exe->pthread_create(0x7ffd61e49298, 0, 0x400716, 0) = 0 [pid 8941] exe->pthread_join(0x7f43cf165700, 0, 0, 0x7f43cf165700 <unfinished ...> [pid 8999] exe->pthread_exit(0, 0x7f43cf164ea0, 0, 0x7f43cf260678 <no return ...> -snip-
14 統計情報を表示する方法(-c)
-cは、統計情報を表示するオプションです。親スレッド、子スレッドで実行される関数の統計情報を表示してみます。適当な時間経過したら、Ctrl + cを押下して終了します。"% time"は実行時間の割合を表しています。全体の実行時間の約49%がpthread_exit関数の実行時間で占めていることがわかります。また、各関数を1回(calls)ずつ実行しています。
[root@server ~]# ltrace -p 8941 -f -c % time seconds usecs/call calls function ------ ----------- ----------- --------- -------------------- 48.53 0.001350 1350 1 pthread_exit 25.56 0.000711 711 1 pow 17.65 0.000491 491 1 pthread_create 8.27 0.000230 230 1 exit ------ ----------- ----------- --------- -------------------- 100.00 0.002782 4 total
Z 参考情報
私が業務や記事執筆で参考にした書籍を以下のページに記載します。
Linux技術のスキルアップをしよう！ - hana_shinのLinux技術ブログ
