2 オペレーティング・システムの動作のトレース

この章では、オペレーティング・システムで発生している状況を調査するために使用できるDプログラムの例を提供しています。

プロセスの作成のトレース

procプローブを使用すると、システムでのプロセスの作成と終了、新しいプログラム・イメージの実行、およびシグナルの処理をトレースできます。procプローブおよびその引数の説明は、Oracle Linux: DTraceリファレンス・ガイドprocプロバイダに関する項を参照してください。

例: システムでのプログラム実行のモニタリング(execcalls.d)

次の例は、procプローブを使用してシステムでのプロセス・イメージの実行をモニターする、Dプログラムexeccalls.dを示しています。

/* execcalls.d -- Monitor the system as it executes programs */

proc::do_execveat_common:exec
{
  trace(stringof(args[0]));
}

execプローブへのargs[0]引数には、実行されるプログラムのパス名が設定されます。stringof()関数を使用して、タイプをchar *からDタイプstringに変換します。

ノート:

procプロバイダ・プローブを有効にするsdtカーネル・モジュールは、ほとんどの場合、テスト・システムにすでにロードされています。または、まだロードされていない(システムのブート以降にDTraceモジュールを手動でロードしなかった)場合は、sdtカーネル・モジュールにより、自動的にロードされます。詳細は、「DTraceモジュールの手動ロード」を参照してください。次の例では、sdtカーネル・モジュールを手動でロードするか、適切な機能のために自動的にロードできる必要があります。

dtrace -s execcalls.dコマンドを入力して、Dプログラムを1つのウィンドウで実行します。別のウィンドウで別のプログラムを開始し、最初のウィンドウでdtraceの出力を監視します。数秒経過した後にトレースを停止するには、dtraceを実行しているウィンドウで[Ctrl]+[C]を押します。
# dtrace -s execcalls.d
dtrace: script 'execcalls.d' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1   1185          do_execveat_common:exec /usr/sbin/sshd
  0   1185          do_execveat_common:exec /usr/sbin/unix_chkpwd
  0   1185          do_execveat_common:exec /bin/bash
  0   1185          do_execveat_common:exec /usr/bin/id
  0   1185          do_execveat_common:exec /usr/bin/hostname
  0   1185          do_execveat_common:exec /usr/bin/id
  0   1185          do_execveat_common:exec /usr/bin/id
  0   1185          do_execveat_common:exec /usr/bin/grep
  0   1185          do_execveat_common:exec /usr/bin/tty
  0   1185          do_execveat_common:exec /usr/bin/tput
  0   1185          do_execveat_common:exec /usr/bin/grep
  1   1185          do_execveat_common:exec /usr/sbin/unix_chkpwd
  1   1185          do_execveat_common:exec /usr/libexec/grepconf.sh
  1   1185          do_execveat_common:exec /usr/bin/dircolors
  0   1185          do_execveat_common:exec /usr/bin/ls
^C

ここでのアクティビティは、スクリプトの実行中に同じシステムへ(別の端末から)ログインする様子を示しています。

システムで新しいプログラムが実行されるとプローブproc::do_execveat_common:execが実行され、関連付けられているアクションによってtrace()が使用されてプログラムのパス名が表示されます。

演習: DTraceの冗長な出力を抑制する

execcalls.dプログラムを再度実行しますが、今度は-qオプションを追加して、trace()からの出力を除くすべての出力を抑制してください。trace()によってトレースされた内容のみがDTraceで表示されます。

(予想完了時間: 5分未満)

演習の回答: DTraceの冗長な出力を抑制する

# dtrace -q -s execcalls.d
/usr/bin/id/usr/bin/tput/usr/bin/dircolors/usr/bin/id/
usr/lib64/qt-3.3/bin/gnome-terminal/usr/local/bin/gnome-terminal
/usr/bin/gnome-terminal/bin/bash/usr/bin/id/bin/grep/bin/basename
/usr/bin/tty/bin/ps

システム・コールのトレース

システム・コールはユーザー・プログラムとカーネルの間のインタフェースであり、プログラムのかわりに操作を実行します。

次の例は、次のDプログラムsyscalls.dを示しています。このプログラムでは、syscallプローブを使用して、システムでのopen()システム・コールのアクティビティを記録します。

例: システムでのopen()システム・コールの記録(syscalls.d)

/* syscalls.d -- Record open() system calls on a system */

syscall::open:entry
{
  printf("%-16s %-16s\n",execname,copyinstr(arg0));
}

この例では、printf()関数を使用して、open()をコールしている実行可能ファイルの名前、および開こうとしているファイルのパス名を表示します。

ノート:

copyinstr()関数を使用して、open()コールの最初の引数(arg0)を文字列に変換します。プローブがユーザー・プロセスのアドレス空間にあるデータへのポインタにアクセスするときは、copyin()copyinstr()またはcopyinto()関数のいずれかを使用して、データをユーザー・スペースからカーネル・スペースのDTraceバッファにコピーする必要があります。この例では、文字配列を参照するポインタとしてcopyinstr(),の使用が適切です。文字列がnullで終わっていない場合は、文字列の長さもcopyinstr()に指定する必要があります。たとえば、write()などのシステム・コールの場合は、copyinstr(arg1, arg2),のように指定します。Oracle Linux: DTraceリファレンス・ガイドユーザー・プロセスのトレースに関する項を参照してください。

procプロバイダ・プローブを有効にするsdtカーネル・モジュールは、ほとんどの場合、テスト・システムにすでにロードされています。または、まだロードされていない(システムのブート以降にDTraceモジュールを手動でロードしなかった)場合は、sdtカーネル・モジュールにより、自動的にロードされます。詳細は、「DTraceモジュールの手動ロード」を参照してください。

次の例では、sdtカーネル・モジュールを手動でロードするか、適切な機能のために自動的にロードできる必要があります。

# dtrace -q -s syscalls.d
udisks-daemon    /dev/sr0               
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/present
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/energy_now
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/voltage_max_design
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/voltage_min_design
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/status
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/current_now
devkit-power-da  /sys/devices/LNXSYSTM:00/.../PNP0C0A:00/power_supply/BAT0/voltage_now     
VBoxService      /var/run/utmp         
firefox          /home/guest/.mozilla/firefox/qeaojiol.default/sessionstore.js
firefox          /home/guest/.mozilla/firefox/qeaojiol.default/sessionstore-1.js
firefox          /home/guest/.mozilla/firefox/qeaojiol.default/sessionstore-1.js    
^C

演習: printf()関数を使用して出力をフォーマットする

printf()関数の引数を変更して、dtraceによってプロセスのプロセスIDおよびユーザーIDも出力されるようにしてください。変換指定子(%-4dなど)を使用します。

printf()関数の説明は、Oracle Linux: DTraceリファレンス・ガイド出力フォーマットに関する項を参照してください。

プロセスIDおよびユーザーIDは、変数pidおよびuidとして利用できます。BEGINプローブを使用して、出力のヘッダーを作成します。

(予想完了時間: 10分)

演習の回答: printf()関数を使用して出力をフォーマットする

/* syscalls1.d -- Modified version of syscalls.d that displays more information */

BEGIN
{
  printf("%-6s %-4s %-16s %-16s\n","PID","UID","EXECNAME","FILENAME");
}

syscall::open:entry
{
  printf("%-6d %-4d %-16s %-16s\n",pid,uid, execname,copyinstr(arg0));
}

このソリューションでは、似たようなフォーマット文字列を使用して、ヘッダーおよびデータが出力されています。

# dtrace -q -s syscalls1.d
PID    UID  EXECNAME         FILENAME
3220   0    udisks-daemon    /dev/sr0        
2571   0    sendmail         /proc/loadavg   
3220   0    udisks-daemon    /dev/sr0        
2231   4    usb              /dev/usblp0     
2231   4    usb              /dev/usb/lp0    
2231   4    usb              /dev/usb/usblp0
...
^C

 指定した間隔でのアクションの実行

profileプロバイダには、システムの状態の特性を一定の間隔でサンプリングするために使用できるtickプローブが含まれています。これらのプローブを使用するには、profileカーネル・モジュールをロードする必要があることに注意してください。

例: tick.dの使用

次に、tick.dプログラムの例を示します。

/* tick.d -- Perform an action at regular intervals */

BEGIN
{
  i = 0;
}

profile:::tick-1sec
{
  printf("i = %d\n",++i);
}

END
{
  trace(i);
}

この例では、Dプログラムの起動時に変数iを宣言および初期化し、変数を増分して1秒に1回その値を出力し、プログラムの終了時にiの最終値を表示します。

このプログラムを実行すると、[Ctrl]+[C]が押されるまで次のような出力が生成されます。

# dtrace -s tick.d 
dtrace: script 'tick.d' matched 3 probes
CPU     ID                    FUNCTION:NAME
  1   5315                       :tick-1sec i = 1

  1   5315                       :tick-1sec i = 2

  1   5315                       :tick-1sec i = 3

  1   5315                       :tick-1sec i = 4

  1   5315                       :tick-1sec i = 5

  1   5315                       :tick-1sec i = 6

^C
  1   5315                       :tick-1sec i = 7

  0      2                             :END         7 

printf()およびtrace()からの出力を除くすべての出力を抑制するには、-qオプションを指定します。

# dtrace -q -s tick.d 
i = 1
i = 2
i = 3
i = 4
^C
i = 5
5

演習: tickプローブの使用

使用可能なprofileプロバイダのプローブを一覧表示してください。別のtickプローブを使用してみてください。END内のtrace()コールをprintf()コールに置き換えます。

プローブの詳細は、Oracle Linux: DTraceリファレンス・ガイドprofileプロバイダに関する項を参照してください。

(予想完了時間: 10分)

演習および例の回答: tickプローブの使用

# dtrace -l -P profile
  ID   PROVIDER           MODULE               FUNCTION NAME
   5    profile                                         profile-97
   6    profile                                         profile-199
   7    profile                                         profile-499
   8    profile                                         profile-997
   9    profile                                         profile-1999
  10    profile                                         profile-4001
  11    profile                                         profile-4999
  12    profile                                         tick-1
  13    profile                                         tick-10
  14    profile                                         tick-100
  15    profile                                         tick-500
  16    profile                                         tick-1000
  17    profile                                         tick-5000
5315    profile                                         tick-1sec
5316    profile                                         tick-10sec

例: 変更されたバージョンのtick.d

/* tick1.d -- Modified version of tick.d */

BEGIN
{
  i = 0;
}

/* tick-500ms fires every 500 milliseconds */
profile:::tick-500ms
{
  printf("i = %d\n",++i);
}

END
{
  printf("\nFinal value of i = %d\n",i);
}

この例では、1秒間に2回実行されるtick-500msプローブを使用しています。

# dtrace -s tick1.d
dtrace: script 'tick1.d' matched 3 probes
CPU     ID                    FUNCTION:NAME
  2    642                      :tick-500ms i = 1

  2    642                      :tick-500ms i = 2

  2    642                      :tick-500ms i = 3

  2    642                      :tick-500ms i = 4

^C
  2    642                      :tick-500ms i = 5

  3      2                             :END
Final value of i = 5

 述語を使用したアクションの選択

述語は、プローブに関連付けられたアクションをDTraceで起動するかどうかを選択する論理文です。述語を使用すると、プローブが実行されたコンテキストの特定のコンテキストに対してトレース分析の焦点を当てることができます。

例: daterun.dの使用

次の例は、システムでdateコマンドが実行されるたびに、write()システム・コールに指定されたファイル記述子、出力文字列および文字列長を表示する実行可能なDTraceスクリプト(daterun.d)を示しています。

#!/usr/sbin/dtrace -qs

/* daterun.d -- Display arguments to write() when date runs */

syscall::write:entry
/execname == "date"/
{
  printf("%s(%d, %s, %d)\n", probefunc, arg0, copyinstr(arg1), arg2);
} 

この例では、述語は/execname == "date"/であり、プローブsyscall::write:entryがトリガーされたときに、実行可能ファイルの名前がdateの場合にのみ、DTraceで関連付けられているアクションを実行するように指定されています。

スクリプトのモードを変更して実行可能にします。

# chmod +x daterun.d

ウィンドウからスクリプトを実行し、別のウィンドウでdateコマンドを入力すると、最初のウィンドウに次のような出力が表示されます。

# ./daterun.d
write(1, Thu Oct 31 11:14:43 GMT 2013
, 29)

例: 使用可能なsyscallプロバイダのプローブの一覧表示

次の例は、使用可能なsyscallプロバイダのプローブを一覧表示する方法を示しています。

# dtrace -l -P syscall | less
   ID   PROVIDER            MODULE                 FUNCTION NAME
   18    syscall           vmlinux                     read entry
   19    syscall           vmlinux                     read return
   20    syscall           vmlinux                    write entry
   21    syscall           vmlinux                    write return
   22    syscall           vmlinux                     open entry
   23    syscall           vmlinux                     open return
   24    syscall           vmlinux                    close entry
   25    syscall           vmlinux                    close return
   26    syscall           vmlinux                  newstat entry
   27    syscall           vmlinux                  newstat return
...
  648    syscall           vmlinux               pkey_alloc entry
  649    syscall           vmlinux               pkey_alloc return
  650    syscall           vmlinux                pkey_free entry
  651    syscall           vmlinux                pkey_free return
  652    syscall           vmlinux                    statx entry
  653    syscall           vmlinux                    statx return
  654    syscall           vmlinux                   waitfd entry
  655    syscall           vmlinux                   waitfd return

演習: syscallプローブの使用

別のプログラム用にdaterun.dスクリプトを修正して試します。システムでwが実行されたときに、新しいスクリプトによって出力が生成されます。

(予想完了時間: 10分)

演習の回答: syscallプローブの使用

#!/usr/sbin/dtrace -qs

/* wrun.d -- Modified version of daterun.d for the w command */

syscall::write:entry
/execname == "w"/
{
  printf("%s(%d, %s, %d)\n", probefunc, arg0, copyinstr(arg1, arg2), arg2);
} 

write()への文字列引数はnullで終わっていないことがあるため、このプログラムでは、2つの引数の形式のcopyinstr()を使用しています。

# chmod +x wrun.d
# ./wrun.d
write(1,  12:14:55 up  3:21,  3 users,  load average: 0.14, 0.15, 0.18
, 62)
write(1, USER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT
, 69)
write(1, guest    tty1     :0               08:55    3:20m 11:23   0.17s pam: gdm-passwo
, 80)
write(1, guest    pts/0    :0.0             08:57    7.00s  0.17s  0.03s w
m: gdm-passwo
, 66)
write(1, guest    pts/1    :0.0             12:14    7.00s  0.69s  8.65s gnome-terminal

, 79)
...
^C

 システム上のイベントの計測

システムが様々なアクティビティを実行するためにかかる時間を判別することは、動作を分析したり、ボトルネックが発生している可能性がある場所を判別するための基本的なテクニックです。

例: read()システム・コール期間のモニタリング(readtrace.d)

次に、Dプログラムreadtrace.dの例を示します。

/* readtrace.d -- Display time spent in read() calls */

syscall::read:entry
{
  self->t = timestamp; /* Initialize a thread-local variable */
}

syscall::read:return
/self->t != 0/
{
  printf("%s (pid=%d) spent %d microseconds in read()\n",
  execname, pid, ((timestamp - self->t)/1000)); /* Divide by 1000 for microseconds */

  self->t = 0; /* Reset the variable */
}

この例では、プロセスによってread()システム・コールが起動されるたびに、readtrace.dプログラムにより、コマンド名、プロセスIDおよび呼出しにかかった時間(マイクロ秒)が表示されます。変数self->tスレッド・ローカルです。これは、システムでのスレッド実行のスコープ内にのみ存在することを意味します。プログラムは、プロセスがread()をコールしたときにtimestampの値をself->tに記録し、コールが戻るときにtimestampの値からこの値を減算します。timestampの単位はナノ秒であるため、マイクロ秒の値を取得するために1000で除算します。

このプログラムを実行すると、次のように出力されます。

# dtrace -q -s readtrace.d
NetworkManager (pid=878) spent 10 microseconds in read()
NetworkManager (pid=878) spent 9 microseconds in read()
NetworkManager (pid=878) spent 2 microseconds in read()
in:imjournal (pid=815) spent 63 microseconds in read()
gdbus (pid=878) spent 7 microseconds in read()
gdbus (pid=878) spent 66 microseconds in read()
gdbus (pid=878) spent 63 microseconds in read()
irqbalance (pid=816) spent 56 microseconds in read()
irqbalance (pid=816) spent 113 microseconds in read()
irqbalance (pid=816) spent 104 microseconds in read()
irqbalance (pid=816) spent 91 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 63 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
sshd (pid=10230) spent 8 microseconds in read()
in:imjournal (pid=815) spent 6 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 5 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 6 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 5 microseconds in read()
^C

演習: システム・コールの計測

readtrace.dentryプローブに述語を追加して、dtraceにより、その実行可能ファイルの名前(df)で選択されたディスク領域使用状況レポートの結果が表示されるようにします。

(予想完了時間: 10分)

演習の回答: システム・コールの計測

次の例は、述語を含むreadtrace.dプログラムの変更済バージョンを示しています。

/* readtrace1.d -- Modified version of readtrace.d that includes a predicate */

syscall::read:entry
/execname == "df"/
{
  self->t = timestamp;
}

syscall::read:return
/self->t != 0/
{
  printf("%s (pid=%d) spent %d microseconds in read()\n",
  execname, pid, ((timestamp - self->t)/1000));

  self->t = 0; /* Reset the variable */
}

述語/execname == "df"/は、プローブが実行されたときに、dfプログラムが実行されているかどうかをテストします。

# dtrace -q -s readtrace1.d 
df (pid=1666) spent 6 microseconds in read()
df (pid=1666) spent 8 microseconds in read()
df (pid=1666) spent 1 microseconds in read()
df (pid=1666) spent 50 microseconds in read()
df (pid=1666) spent 38 microseconds in read()
df (pid=1666) spent 10 microseconds in read()
df (pid=1666) spent 1 microseconds in read()
^C

演習: cpのすべてのシステム・コールの計測(calltrace.d)

probefunc変数、syscall:::entryプローブおよびsyscall:::returnプローブを使用して、実行可能ファイルcpのすべてのシステム・コールを計測するDプログラムcalltrace.dを作成します。

(予想完了時間: 10分)

演習の回答: cpのすべてのシステム・コールの計測(calltrace.d)

/* calltrace.d -- Time all system calls for cp */

syscall:::entry
/execname == "cp"/
{
  self->t = timestamp; /* Initialize a thread-local variable */
}

syscall:::return
/self->t != 0/
{
  printf("%s (pid=%d) spent %d microseconds in %s()\n",
  execname, pid, ((timestamp - self->t)/1000), probefunc);

  self->t = 0; /* Reset the variable */
}

関数名readをプローブ仕様から削除すると、syscallentryプローブおよびreturnプローブのすべてのインスタンスと一致するようになります。次に、cp実行可能ファイルを実行したことによるシステム・コールのチェックを示します。

# dtrace -q -s calltrace.d 
cp (pid=2801) spent 4 microseconds in brk()
cp (pid=2801) spent 5 microseconds in mmap()
cp (pid=2801) spent 15 microseconds in access()
cp (pid=2801) spent 7 microseconds in open()
cp (pid=2801) spent 2 microseconds in newfstat()
cp (pid=2801) spent 3 microseconds in mmap()
cp (pid=2801) spent 1 microseconds in close()
cp (pid=2801) spent 8 microseconds in open()
cp (pid=2801) spent 3 microseconds in read()
cp (pid=2801) spent 1 microseconds in newfstat()
cp (pid=2801) spent 4 microseconds in mmap()
cp (pid=2801) spent 12 microseconds in mprotect()
   ...
cp (pid=2801) spent 183 microseconds in open()
cp (pid=2801) spent 1 microseconds in newfstat()
cp (pid=2801) spent 1 microseconds in fadvise64()
cp (pid=2801) spent 17251 microseconds in read()
cp (pid=2801) spent 80 microseconds in write()
cp (pid=2801) spent 58 microseconds in read()
cp (pid=2801) spent 57 microseconds in close()
cp (pid=2801) spent 85 microseconds in close()
cp (pid=2801) spent 57 microseconds in lseek()
cp (pid=2801) spent 56 microseconds in close()
cp (pid=2801) spent 56 microseconds in close()
cp (pid=2801) spent 56 microseconds in close()
^C

 親プロセスおよび子プロセスのトレース

forkを処理すると、事実上親プロセスのコピーであるが異なるプロセスIDを持つ子プロセスが作成されます。その他の違いについては、fork(2)のマニュアル・ページを参照してください。子プロセスは、その親プロセスとは別に実行でき、いくつかの個別のタスクを実行できます。または、子プロセスは、同じプロセスIDを保持したまま、子のプログラム・イメージを置き換える新しいプログラムイメージを実行できます。

例: procプローブを使用したシステムでのアクティビティのレポート(activity.d)

次の例のDプログラムactivity.dでは、procプローブを使用して、システムでのfork()アクティビティおよびexec()アクティビティをレポートします。

#pragma D option quiet

/* activity.d -- Record fork() and exec() activity */

proc::_do_fork:create
{
  /* Extract PID of child process from the psinfo_t pointed to by args[0] */
  childpid = args[0]->pr_pid;

  time[childpid] = timestamp;
  p_pid[childpid] = pid; /* Current process ID (parent PID of new child) */
  p_name[childpid] = execname; /* Parent command name */
  p_exec[childpid] = ""; /* Child has not yet been exec'ed */ 
}

proc::do_execveat_common:exec
/p_pid[pid] != 0/
{
  p_exec[pid] = args[0]; /* Child process path name */
}

proc::do_exit:exit
/p_pid[pid] != 0 &&  p_exec[pid] != ""/ 
{
  printf("%s (%d) executed %s (%d) for %d microseconds\n",
    p_name[pid], p_pid[pid], p_exec[pid], pid, (timestamp - time[pid])/1000);
}

proc::do_exit:exit
/p_pid[pid] != 0 &&  p_exec[pid] == ""/
{
  printf("%s (%d) forked itself (as %d) for %d microseconds\n",
    p_name[pid], p_pid[pid], pid, (timestamp - time[pid])/1000);
}  

この例では、文#pragma D option quietには、コマンドラインに-qオプションを指定するのと同じ効果があります。

fork()が実行された後の子プロセスのプロセスID (childpid)は、args[0]プローブ引数によって指し示されているpsinfo_tデータ構造体のpr_pidメンバーを検査することによって判別します。procプローブの引数の詳細は、Oracle Linux: DTraceリファレンス・ガイドprocプロバイダに関する項を参照してください。

プログラムは子プロセスIDの値を使用して、グローバルに一意な連想配列のエントリ(p_pid[childpid]など)を初期化しています。

ノート:

連想配列は、キーを値に関連付けるという点では通常の配列と同じですが、キーに任意のタイプを使用することが可能で、整数である必要はありません。

プログラムの実行時、sshコマンドを使用して別のターミナル・ウィンドウから同じシステムにアクセスすると、次のような出力が表示されます。この新しいターミナル・ウィンドウから異なるプログラムの実行を試行して、追加の出力を生成することが必要になる場合もあります。

# dtrace -s activity.d 
sshd (3966) forked itself (as 3967) for 3667020 microseconds
bash (3971) forked itself (as 3972) for 1718 microseconds
bash (3973) executed /usr/bin/hostname (3974) for 1169 microseconds
grepconf.sh (3975) forked itself (as 3976) for 1333 microseconds
bash (3977) forked itself (as 3978) for 967 microseconds
bash (3977) executed /usr/bin/tput (3979) for 1355 microseconds
bash (3980) executed /usr/bin/dircolors (3981) for 1212 microseconds
sshd (3966) executed /usr/sbin/unix_chkpwd (3968) for 31444 microseconds
sshd (3966) executed /usr/sbin/unix_chkpwd (3969) for 1653 microseconds
bash (3970) forked itself (as 3971) for 2411 microseconds
bash (3970) forked itself (as 3973) for 1830 microseconds
bash (3970) executed /usr/libexec/grepconf.sh (3975) for 3696 microseconds
bash (3970) forked itself (as 3977) for 3273 microseconds
bash (3970) forked itself (as 3980) for 1928 microseconds
bash (3970) executed /usr/bin/grep (3982) for 1570 microseconds
^C

演習: 述語を使用して、アクションの実行を制御する

dtraceが実行可能ファイル名(たとえば、bash)、またはdtraceコマンドへの引数として指定されたプログラム名によって選択された親プロセスの結果を表示するように、activity.dを変更してください。

(予想完了時間: 10分)

演習の回答: 述語を使用して、アクションの実行を制御する

実行可能ファイルの名前を指定するために必要な唯一の変更は、次のようにproc::_do_fork:createプローブに述語を追加することです。
/execname == "bash"/

より汎用的なバージョンのプログラムでは、渡されたコマンドライン引数の述語チェック値がかわりに設定されます。次に例を示します。

/execname == $1/

例: 指定したプログラムのfork()およびexec()のアクティビティの記録(activity1.d)

次の例では、コマンドラインから渡される述語を使用しています。

#pragma D option quiet

/* activity1.d -- Record fork() and exec() activity for a specified program */

proc::_do_fork:create
/execname == $1/
{
  /* Extract PID of child process from the psinfo_t pointed to by args[0] */
  childpid = args[0]->pr_pid;

  time[childpid] = timestamp;
  p_pid[childpid] = pid; /* Current process ID (parent PID of new child) */
  p_name[childpid] = execname; /* Parent command name */
  p_exec[childpid] = ""; /* Child has not yet been exec'ed */ 
}

proc::do_execveat_common:exec
/p_pid[pid] != 0/
{
  p_exec[pid] = args[0]; /* Child process path name */
}

proc::do_exit:exit
/p_pid[pid] != 0 &&  p_exec[pid] != ""/ 
{
  printf("%s (%d) executed %s (%d) for %d microseconds\n",
    p_name[pid], p_pid[pid], p_exec[pid], pid, (timestamp - time[pid])/1000);
}

proc::do_exit:exit
/p_pid[pid] != 0 &&  p_exec[pid] == ""/
{
  printf("%s (%d) forked itself (as %d) for %d microseconds\n",
    p_name[pid], p_pid[pid], pid, (timestamp - time[pid])/1000);
}  

次の例に示すように、トレースするプログラムの名前をdtraceコマンドに引数として指定できます。引数をエスケープして、シェルから二重引用符を保護する必要があります。

# dtrace -s activity.d '"bash"'
bash (10367) executed /bin/ps (10368) for 10926 microseconds
bash (10360) executed /usr/bin/tty (10361) for 3046 microseconds
bash (10359) forked itself (as 10363) for 32005 microseconds
bash (10366) executed /bin/basename (10369) for 1285 microseconds
bash (10359) forked itself (as 10370) for 12373 microseconds
bash (10360) executed /usr/bin/tput (10362) for 34409 microseconds
bash (10363) executed /usr/bin/dircolors (10364) for 29527 microseconds
bash (10359) executed /bin/grep (10365) for 21024 microseconds
bash (10366) forked itself (as 10367) for 11749 microseconds
bash (10359) forked itself (as 10360) for 41918 microseconds
bash (10359) forked itself (as 10366) for 14197 microseconds
bash (10370) executed /usr/bin/id (10371) for 11729 microseconds
^C

簡単なデータの集積

DTraceには、個々のプローブが収集したデータを集積するためのいくつかの関数があります。これらの関数には、avg()count()max()min()stddev()およびsum()が含まれ、収集されたデータの平均、数、最大値、最小値、標準偏差および合計がそれぞれ返されます。集積関数の説明は、Oracle Linux: DTraceリファレンス・ガイド集積に関する項を参照してください。

DTraceは、連想配列で使用されるものと同様のタプル式を使用して集積の結果に索引を設定します。

@name[list_of_keys] = aggregating_function(args);

集積体の名前には、接頭辞として@文字が付けられます。キーは、集積関数が収集するデータを示します。集積の名前を指定しない場合、DTraceは@を無名の集積名として使用します。簡単なDプログラムの場合は、通常これで十分です。

例: プロセスによって起動されたwrite()システム・コール数のカウント

次の例では、ユーザーが[Ctrl]+[C]を押すまで、コマンドによりプロセスによって起動されたwrite()システム・コールの数がカウントされます。

# dtrace -n 'syscall::write:entry { @["write() calls"] = count(); }'
dtrace: description 'syscall:::' matched 1 probe
^C

  write() calls                                              9

ノート:

この簡単な例では、個別のDスクリプトを作成するのではなく、dtraceコマンドラインにプローブとアクションが指定されています。

DTraceでは、集積の結果を自動的に出力します。または、printa()関数を使用すると、集積の結果をフォーマットできます。

例: read()およびwrite()システム・コール数のカウント

次の例では、read()write()の両方のシステム・コールの数をカウントします。

# dtrace -n 'syscall::write:entry,syscall::read:entry { @[strjoin(probefunc,"() calls")] = count(); }' 
dtrace: description 'syscall::write:entry,syscall::read:entry' matched 2 probes
^C

  write() calls                                            150
  read() calls                                            1555

演習: 固定された期間におけるシステム・コールのカウント

tickプローブおよびexit()を使用して、100秒後にデータの収集を停止し、open()read()およびwrite()をコールする回数を表示するcountcalls.dというDプログラムを記述してください。

(予想完了時間: 15分)

演習および例の回答: write、readおよびopenシステム・コールの100秒間にわたるカウント(countcalls.d)

/* countcalls.d -- Count write, read, and open system calls over 100 seconds */

profile:::tick-100sec
{
  exit(0);
}

syscall::write:entry, syscall::read:entry, syscall::open:entry
{
  @[strjoin(probefunc,"() calls")] = count();
}

tick-100sプローブに関連付けられているアクションは、dtraceが100秒後に終了し、集積の結果を出力することを意味しています。

# dtrace -s countcalls.d
dtrace: script 'countcalls.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
  3    643                     :tick-100sec 

  write() calls                                                  1062
  open() calls                                                   1672
  read() calls                                                  29672

例: プロセスによって呼び出されたシステム・コールのカウント(countsyscalls.d)

次の例に示すDプログラムcountsyscalls.dは、プロセスIDによって指定されたプロセスが様々なシステム・コールを呼び出す回数をカウントします。

#!/usr/sbin/dtrace -qs

/* countsyscalls.d -- Count system calls invoked by a process */

syscall:::entry
/pid == $1/
{
  @num[probefunc] = count();
}

syscalls.dファイルを実行可能にした後に、引数としてプロセスIDを指定してコマンドラインから実行できます。

次の例は、以前に呼び出されたemacsプログラムの使用をモニターする方法を示しています。スクリプトの起動後、emacs内で、Dスクリプトを終了する前に2つのファイルが開かれ、変更されて保存されます。

スクリプトを実行可能にします。

# chmod +x countsyscalls.d

別のコマンドラインから次のように入力します。

# emacs foobar.txt

ここでスクリプトを起動し、開いたemacsウィンドウを使用します。

# ./countsyscalls.d $(pgrep -u root emacs)
                     ^C 

  chmod                                                             1 
  exit_group                                                        1 
  futex                                                             1 
  getpgrp                                                           1 
  lseek                                                             1 
  lsetxattr                                                         1 
  rename                                                            1 
  fsync                                                             2 
  lgetxattr                                                         2 
  alarm                                                             3 
  rt_sigaction                                                      3 
  unlink                                                            3 
  mmap                                                              4 
  munmap                                                            4 
  symlink                                                           4 
  fcntl                                                             6 
  newfstat                                                          6 
  getgid                                                            7 
  getuid                                                            7 
  geteuid                                                           8 
  openat                                                            8 
  access                                                            9 
  getegid                                                          14 
  open                                                             14 
  getdents                                                         15 
  close                                                            17 
  readlink                                                         19 
  newlstat                                                         33 
  newstat                                                         155 
  read                                                            216 
  timer_settime                                                   231 
  write                                                           314 
  pselect6                                                        376 
  rt_sigreturn                                                    393 
  ioctl                                                           995 
  rt_sigprocmask                                                 1261 
  clock_gettime                                                  3495 

前の例で、pgrepコマンドを使用して、rootユーザーが実行中のemacsプログラムのプロセスIDを確認します。

演習: ユーザーによって実行されるプロセスのトレース

(ユーザー名によって指定された)ユーザーが様々なプログラムを実行する回数をカウントして表示するプログラムcountprogs.dを作成します。id -u userコマンドを使用すると、ユーザー名に対応するIDを取得できます。

(予想完了時間: 10分)

演習および例の回答: 指定したユーザーによって起動されたプログラムのカウント(countprogs.d)

#!/usr/sbin/dtrace -qs

/* countprogs.d -- Count programs invoked by a specified user */

proc::do_execveat_common:exec
/uid == $1/
{
  @num[execname] = count();
}

述語/uid == $1/は、コマンドラインで指定された引数に対して実行される各プログラムの有効なUIDを比較しています。id -u userコマンドを使用して、ゲスト・ユーザー・アカウントのIDを検索できます。次に例を示します。

# chmod +x countprogs.d
# ./countprogs.d $(id -u guest)
^C

less 1
lesspipe.sh 1
sh 1
bash 9

rootユーザー(通常はユーザー0)の場合、同じコマンドを使用できます。テストのために、別のウィンドウを使用して、テスト・ログインの下でユーザー・アカウントを設定し、いくつかの公称プログラムを実行することが必要になる場合があります。

例: プログラムが様々なファイルから読取りを行った回数の10秒間にわたるカウント(fdscount.d)

次のDプログラムは、プログラムが様々なファイルから読取りを行った回数を10秒間カウントし、上位5件の結果のみを表示します。

# emacs fdscount.d
# dtrace -C -D ENAME='"emacs"' -qs fdscount.d

  /usr/share/terminfo/x/xterm                                       2
  /dev/urandom                                                      3
  /usr/share/emacs/24.3/lisp/calendar/time-date.elc                 5
  /dev/tty                                                          8
  /usr/share/emacs/24.3/lisp/term/xterm.elc                         8

fds[]組込み配列を使用して、read()のファイル記述子引数arg0に対応するファイルを判別します。arg0によってfds[]に索引付けされているfileinfo_t構造体のfi_pathnameメンバーには、ファイルのフルパス名が含まれています。

fileinfo_t構造体のメンバーの詳細は、Oracle Linux: DTraceリファレンス・ガイドfileinfo_tに関する項を参照してください。

ENDアクション内のtrunc()関数は、集積から上位5件の結果のみを表示するようにDTraceに指示しています。

DTraceは、profile:::tick-10sプローブ、fds[]組込み配列およびsyscall::read:entryプローブにアクセスできます。Cプリプロセッサ・ディレクティブをdtraceに指定して、ENAME変数の値を(emacsなどに)設定します。任意の実行可能ファイルを選択できます。文字列の引用符をエスケープするには、追加の一重引用符を使用する必要があることに注意してください。次に例を示します。

# dtrace -C -D ENAME='"emacs"' -qs fdscount.d

/usr/share/terminfo/x/xterm 2
/dev/tty 3
/dev/urandom 3
/usr/share/emacs/24.3/lisp/calendar/time-date.elc 5
/usr/share/emacs/24.3/lisp/term/xterm.elc 8

テストでの実行可能ファイルにより、出力に/proc/ pid/mapsエントリが表示される場合、このエントリは、プロセスのマップされたメモリー領域および権限に関する情報が含まれているprocfsファイル・システム内のファイルを指しています。pipe: inodeおよびsocket: inodeエントリを参照すると、pipefsおよびsocketfsファイル・システムのinodeを指しています。

演習: システムでのコンテキスト・スイッチのカウント

タイムスタンプを表示して、1秒に一度、CPUごとのコンテキスト・スイッチの回数とすべてのCPUの合計回数をCPU番号または"total"とともに表示するcswpercpu.dという実行可能なDプログラムを作成してください。

  • BEGINプローブを使用して、TimestampCPUおよびNcswというラベルの列が表示されるヘッダーを出力します。

  • sched:::on-cpuプローブを使用してコンテキスト・スイッチの終了を検出し、プローブが実行されたコンテキストのCPU番号をlltostr()を使用して文字列に変換し、count()を使用して集積変数@nを増分します(キー値にCPU番号の文字列が設定されたとき、およびキー値に"total"が設定されたとき)。

    sched:::on-cpuプローブの詳細は、Oracle Linux: DTraceリファレンス・ガイドschedプロバイダに関する項を参照してください。

  • profile:::tick-1secプローブを使用し、printf()を使用してデータおよび時間を出力し、printa()を使用してキー(CPU番号文字列または"total")および集積値を出力します。日付と時間は、%Y変換形式を使用して出力できるwalltimestamp変数の値として利用できます。

  • clear()を使用して、集積変数@nをリセットします。

(予想完了時間: 40分)

演習および例の回答: システムでのコンテキスト・スイッチのカウント

次の例は、実行可能なDプログラムcswpercpu.dを示しています。プログラムにより、タイムスタンプが表示され、1秒に1回、CPUごとのコンテキスト・スイッチの回数、およびすべてのCPUの合計回数がCPU番号または"total"とともに表示されます。

#!/usr/sbin/dtrace -qs

/* cswpercpu.d -- Print number of context switches per CPU once per second */

#pragma D option quiet

dtrace:::BEGIN
{
  /* Print the header */
  printf("%-25s %5s %15s", "Timestamp", "CPU", "Ncsw");
}

sched:::on-cpu
{
  /* Convert the cpu number to a string */
  cpustr = lltostr(cpu);
  /* Increment the counters */
  @n[cpustr] = count();
  @n["total"] = count();
}

profile:::tick-1sec
{
  /* Print the date and time before the first result */
  printf("\n%-25Y ", walltimestamp);

  /* Print the aggregated counts for each CPU and the total for all CPUs */
  printa("%5s %@15d\n                          ", @n);

  /* Reset the aggregation */
  clear(@n);
}
# chmod +x cswpercpu.d
# ./cswpercpu.d
Timestamp                   CPU            Ncsw
2013 Nov  6 20:47:26          1             148
                              0             155
                              3             200
                              2             272
                          total             775
                          
2013 Nov  6 20:47:27          1             348
                              0             364
                              3             364
                              2             417
                          total            1493
                          
2013 Nov  6 20:47:28          3              47
                              1             100
                              0             121
                              2             178
                          total             446
                          ^C

コンテキスト・スイッチにかかった合計時間およびコンテキスト・スイッチごとの平均時間の集積を計測することが必要になる場合があります。たとえば、sched:::off-cpuプローブのアクションでスレッド・ローカル変数をtimestampの値で初期化し、sched:::on-cpuのアクションでtimestampの値からその値を減算することで検証できます。sum()およびavg()集積関数をそれぞれ使用します。

より複雑なデータの集積の操作

lquantize()関数およびquantize()関数を使用して、2の累乗の数値ごとのデータの線形度数分布を表示します。集積関数の説明は、Oracle Linux: DTraceリファレンス・ガイド集積に関する項を参照してください。

例: コマンドの結果生成される読取りサイズの分布の表示

次の例で示すように、実行中のfindのすべてのインスタンスによって呼び出されたread()コールのarg2に指定されたサイズの分布を表示できます。スクリプトの実行後、別のウィンドウでfindを使用して検索を開始します(find .find /.など)。

# dtrace -n 'syscall::read:entry /execname=="find"/{@dist["find"]=quantize(arg2);}'
dtrace: description 'syscall::read:entry ' matched 1 probe
^C

   find
            value  ------------- Distribution ------------- count
              256 | 0
              512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
             1024 | 0
             2048 | 0
             4096 |@@@@@@@@@@ 2
             8192 | 0

前の例のプログラムと同じくらい簡単なプログラムの場合、通常はコマンドラインから実行すると便利です。

例: ブロック・デバイスのI/Oスループットの分布の表示(diskact.d)

次の例では、diskact.dスクリプトで、sdtカーネル・モジュールによって有効になっているioプロバイダのプローブを使用し、システム上のブロック・デバイスのI/Oスループットを表示します。

#pragma D option quiet

/* diskact.d -- Display the distribution of I/O throughput for block devices */

io:::start
{
  start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}

io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
  /*
     You want to get an idea of our throughput to this device in KB/sec
     but you have values that are measured in bytes and nanoseconds.
     You want to calculate the following:
    
     bytes / 1024
     ------------------------
     nanoseconds / 1000000000
    
     As DTrace uses integer arithmetic and the denominator is usually
     between 0 and 1 for most I/O, the calculation as shown will lose
     precision. So, restate the fraction as:
    
     bytes         1000000000      bytes * 976562
     ----------- * ------------- = --------------
     nanoseconds   1024            nanoseconds
    
     This is easy to calculate using integer arithmetic.
   */
  this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
  @[args[1]->dev_statname, args[1]->dev_pathname] =
    quantize((args[0]->b_bcount * 976562) / this->elapsed);
  start[args[0]->b_edev, args[0]->b_blkno] = 0;
}

END
{
  printa(" %s (%s)\n%@d\n", @);
}

#pragma D option quiet文を使用して不要な出力を抑制し、printa()関数を使用して集積の結果を表示します。

io:::startプローブおよびio:::doneプローブの引数の説明は、Oracle Linux: DTraceリファレンス・ガイドioプロバイダに関する項を参照してください。

printa()関数の説明は、Oracle Linux: DTraceリファレンス・ガイド出力フォーマットに関する項を参照してください。

プログラムを約1分間実行した後に、[Ctrl]+[C]を押して結果を表示します。

# dtrace -s diskact.d
                     ^C

xvda2 (<unknown>)

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
                1 | 0

xvdc (<unknown>)

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
                1 | 0

xvdc1 (<unknown>)

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
                1 | 0

  dm-0 (<unknown>)

            value  ------------- Distribution ------------- count
              256 | 0
              512 |@@ 1
             1024 |@@ 1
             2048 |@@@@@@ 3
             4096 |@@@@@@@@@@ 5
             8192 |@@@@@@@@@@@@@@@@@ 9
            16384 |@@@@ 2
            32768 | 0

演習: 読取りおよび書込みのI/Oスループットを個別に表示する

ブロック・デバイスからの読取りおよび書込みの結果を個別に集積するdiskact.dのバージョンを作成してください。tickプローブを使用して、データを10秒間収集します。

  • io:::startおよびio:::doneのアクションで、args[0]->b_flags & B_READ ? "READ" : "WRITE"の値を変数iodirに割り当てます。

  • io:::startおよびio:::doneのアクションで、start[]連想配列へのキーとしてiodirを追加します。

  • io:::doneのアクションで、無名の集積変数@[]へのキーとしてiodirを追加します。

  • iodirキーの値を表示するためのprinta()のフォーマット文字列を変更します。

(予想完了時間: 20分)

演習の回答: 読取りおよび書込みのI/Oスループットを個別に表示する

次の例は、読取りおよび書込みのI/Oの結果を個別に表示するdiskact.dスクリプトの変更済バージョンを示しています。

#pragma D option quiet

/* rwdiskact.d -- Modified version of diskact.d that displays
                  separate results for read and write I/O     */

profile:::tick-10sec
{
  exit(0);
}

io:::start
{
  iodir = args[0]->b_flags & B_READ ? "READ" : "WRITE";
  start[args[0]->b_edev, args[0]->b_blkno, iodir] = timestamp;
}

io:::done
{
  iodir = args[0]->b_flags & B_READ ? "READ" : "WRITE";
  this->elapsed = timestamp - start[args[0]->b_edev,args[0]->b_blkno,iodir];
  @[args[1]->dev_statname, args[1]->dev_pathname, iodir] = 
    quantize((args[0]->b_bcount * 976562) / this->elapsed);
  start[args[0]->b_edev, args[0]->b_blkno,iodir] = 0;}

END
{
  printa(" %s (%s) %s \n%@d\n", @);
}

この例では、iodir変数を集積変数のタプルに追加すると、DTraceが読取りおよび書込みI/O操作の個別の集積を表示できます。

# dtrace -s rwdiskact.d
                     
^C
  xvda2 (<unknown>) WRITE

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
                1 | 0

  xvdc (<unknown>) WRITE

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
                1 | 0

  xvdc1 (<unknown>) WRITE

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
                1 | 0

  nfs (<nfs>) READ

            value  ------------- Distribution ------------- count
               -1 | 0
                0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5
                1 | 0

  dm-0 (<unknown>) WRITE

            value  ------------- Distribution ------------- count
             4096 | 0
             8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
            16384 | 0

例: ファイル・システム・デバイスの累積の読取りおよび書込みアクティビティの表示 (fsact)

次の例は、埋込みDプログラムを使用して、ファイル・システムの基礎となるブロック・デバイスの場所に応じて、ローカル・ファイル・システムの累積の読取りおよび書込みブロック・カウントを表示するbashシェル・スクリプトです。lquantize()集積関数を使用して、デバイスの合計ブロック数の10分の1として線形の結果を表示します。

#!/bin/bash

# fsact -- Display cumulative read and write activity across a file system device
#
#          Usage: fsact [<filesystem>]

# Could load the required DTrace modules, if they were not autoloaded.
# grep profile /proc/modules > /dev/null 2>&1 || modprobe profile
# grep sdt /proc/modules > /dev/null 2>&1 || modprobe sdt

# If no file system is specified, assume /
[ $# -eq 1 ] && FSNAME=$1 || FSNAME="/"
[ ! -e $FSNAME ] && echo "$FSNAME not found" && exit 1

# Determine the mountpoint, major and minor numbers, and file system size
MNTPNT=$(df $FSNAME | gawk '{ getline; print $1; exit }')
MAJOR=$(printf "%d\n" 0x$(stat -Lc "%t" $MNTPNT))
MINOR=$(printf "%d\n" 0x$(stat -Lc "%T" $MNTPNT))
FSSIZE=$(stat -fc "%b" $FSNAME)

# Run the embedded D program
dtrace -qs /dev/stdin << EOF
io:::done
/args[1]->dev_major == $MAJOR && args[1]->dev_minor == $MINOR/
{
  iodir = args[0]->b_flags & B_READ ? "READ" : "WRITE";
  /* Normalize the block number as an integer in the range 0 to 10 */ 
  blkno = (args[0]->b_blkno)*10/$FSSIZE;
  /* Aggregate blkno linearly over the range 0 to 10 in steps of 1 */ 
  @a[iodir] = lquantize(blkno,0,10,1)
}

tick-10s
{
  printf("%Y\n",walltimestamp);
  /* Display the results of the aggregation */
  printa("%s\n%@d\n",@a);
  /* To reset the aggregation every tick, uncomment the following line */
  /* clear(@a); */
}
EOF

必要なパラメータ(基礎となるデバイスのメジャー番号とマイナー番号、およびファイル・システム・ブロック内のファイル・システムの合計サイズ)を設定できるように、Dプログラムをシェル・スクリプトに埋め込みます。次に、Dコードでこれらのパラメータに直接アクセスします。

ノート:

Dプログラムに値を渡す別の方法としては、次のようにCプリプロセッサ・ディレクティブを使用する方法があります。

dtrace -C -D MAJ=$MAJOR -D MIN=$MINOR -D FSZ=$FSSIZE -qs /dev/stdin << EOF

シェル名のかわりにマクロ名で、Dプログラム内の変数を参照できるようになります。

/args[1]->dev_major == MAJ && args[1]->dev_minor == MIN/

blkno = (args[0]->b_blkno)*10/FSZ;

次の例は、スクリプトを実行可能にした後にfsactコマンドを実行してから、ディレクトリでcp -Rを実行し、コピーされたディレクトリでrm -rfを実行した場合の出力を示しています。

# chmod +x fsact
# ./fsact
2018 Feb 16 16:59:46
READ

            value  ------------- Distribution ------------- count
              < 0 | 0
                0 |@@@@@@@ 8
                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32
                2 | 0
                3 | 0
                4 | 0
                5 | 0
                6 | 0
                7 | 0
                8 | 0
                9 | 0
            >= 10 |@@@@@@@ 8

WRITE

            value  ------------- Distribution ------------- count
                9 | 0
            >= 10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 42                                       0        

^C

 システム・コールでのエラーの表示

次の情報は、Dプログラムerrno.dを使用したシステム・コール・エラーの表示に関連しています。

 例: システム・コール・エラーの表示(errno.d)

次に、Dプログラムerrno.dの例を示します。この例では、open()システム・コールを使用してファイルを開くときにエラーが発生した場合に、プログラムによりerrnoの値およびファイル名が表示されます。

#!/usr/sbin/dtrace -qs

/* errno.d -- Display errno and the file name for failed open() calls */

syscall::open:entry
{
  self->filename = copyinstr(arg0);
}

syscall::open:return
/arg0 < 0/
{
  printf("errno = %-2d   file = %s\n", errno, self->filename);
}

open()システム・コールでエラーが発生すると、returnプローブによってarg0引数に-1が設定され、組込みerrno変数の値にエラーの性質が示されます。述語を使用して、arg0の値をテストします。または、errnoの値がゼロより大きいかどうかをテストできます。

このスクリプトをファイルに保存し、そのファイルを実行可能にしたら、そのスクリプトを実行して、システムで発生したopen()システム・コールの失敗に関する情報を表示できます。スクリプトを開始したら、別のターミナル・ウィンドウで、lsコマンドを実行して存在しないファイルを一覧表示するなど、エラーが発生するコマンドを実行できます。または、次の例のように、別のターミナルからディレクトリに対してcatコマンドが発行されると、エラーが発生します。

# ./errno.d

errno = 2    file = /usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo
errno = 2    file = /usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo
errno = 2    file = /usr/share/locale/en_US/LC_MESSAGES/libc.mo
errno = 2    file = /usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo
errno = 2    file = /usr/share/locale/en.utf8/LC_MESSAGES/libc.mo
errno = 2    file = /usr/share/locale/en/LC_MESSAGES/libc.mo
^C

演習: システム・コールでのエラーに関する情報をさらに表示する

失敗したシステム・コールのエラー番号ではなくエラー名が表示されるようにerrno.dを変更してください。

  • エラー(EACCESEEXISTなど)の数値は、/usr/include/asm-generic/errno-base.hおよび/usr/include/asm-generic/errno.hに定義されています。DTraceでは、数値エラー値のインライン名(実際には定数)は/usr/lib64/dtrace/ kernel-version /errno.dに定義されます。error[]という連想配列を使用して、/usr/include/asm-generic/errno-base.hに定義されているエラー名とインライン名のマッピングを格納します。

  • printf()を使用して、ユーザーID、プロセスID、プログラム名、エラー名およびシステム・コールの名前を表示します。

  • BEGINプローブを使用して、列見出しを出力します。

  • arg0ではなくerrnoの値を使用して、マップされた名前の範囲からのエラーがシステム・コールで発生したかどうかをテストします。

(予想完了時間: 30分)

演習の回答: システム・コールでのエラーに関する情報をさらに表示する

次に、エラー名を表示するerrno.dの変更済バージョンの例を示します。

  例: エラー名が表示される変更されたバージョンのerrno.d (displayerrno.d)
#!/usr/sbin/dtrace -qs

/* displayerrno.d -- Modified version of errno.d that displays error names */

BEGIN
{
  printf("%-4s %-6s %-10s %-10s %s\n", "UID", "PID", "Prog", "Error", "Func");

  /* Assign error names to the associative array error[] */
  error[EPERM]   = "EPERM";    /* Operation not permitted */
  error[ENOENT]  = "ENOENT";   /* No such file or directory */
  error[ESRCH]   = "ESRCH";    /* No such process */
  error[EINTR]   = "EINTR";    /* Interrupted system call */
  error[EIO]     = "EIO";      /* I/O error */
  error[ENXIO]   = "ENXIO";    /* No such device or address */
  error[E2BIG]   = "E2BIG";    /* Argument list too long */
  error[ENOEXEC] = "ENOEXEC";  /* Exec format error */
  error[EBADF]   = "EBADF";    /* Bad file number */
  error[ECHILD]  = "ECHILD";   /* No child processes */
  error[EAGAIN]  = "EAGAIN";   /* Try again or operation would block */
  error[ENOMEM]  = "ENOMEM";   /* Out of memory */
  error[EACCES]  = "EACCES";   /* Permission denied */
  error[EFAULT]  = "EFAULT";   /* Bad address */
  error[ENOTBLK] = "ENOTBLK";  /* Block device required */
  error[EBUSY]   = "EBUSY";    /* Device or resource busy */
  error[EEXIST]  = "EEXIST";   /* File exists */
  error[EXDEV]   = "EXDEV";    /* Cross-device link */
  error[ENODEV]  = "ENODEV";   /* No such device */
  error[ENOTDIR] = "ENOTDIR";  /* Not a directory */
  error[EISDIR]  = "EISDIR";   /* Is a directory */
  error[EINVAL]  = "EINVAL";   /* Invalid argument */
  error[ENFILE]  = "ENFILE";   /* File table overflow */
  error[EMFILE]  = "EMFILE";   /* Too many open files */
  error[ENOTTY]  = "ENOTTY";   /* Not a typewriter */
  error[ETXTBSY] = "ETXTBSY";  /* Text file busy */
  error[EFBIG]   = "EFBIG";    /* File too large */
  error[ENOSPC]  = "ENOSPC";   /* No space left on device */
  error[ESPIPE]  = "ESPIPE";   /* Illegal seek */
  error[EROFS]   = "EROFS";    /* Read-only file system */
  error[EMLINK]  = "EMLINK";   /* Too many links */
  error[EPIPE]   = "EPIPE";    /* Broken pipe */
  error[EDOM]    = "EDOM";     /* Math argument out of domain of func */
  error[ERANGE]  = "ERANGE";   /* Math result not representable */
}

/* Specify any syscall return probe and test that the value of errno is in range */

syscall:::return
/errno > 0 && errno <= ERANGE/
{
  printf("%-4d %-6d %-10s %-10s %s()\n", uid, pid, execname, error[errno], probefunc);
}
# chmod +x displayerrno.d
# ./displayerrno.d
UID  PID    Prog       Error      Func
500  3575   test       EACCES     open()
500  3575   test       EINTR      clock_gettime()
^C

エラー名に加えて、エラーの性質に関する詳細な情報が表示されるように、このプログラムを変更できます。