Solairs Dtrace（ダイナミックトレース） の応用の紹介 2

2. OS(Solaris10)起動時の情報をトレース

OS 起動時に何らかの問題が発生した際に、Dtrace で調査を行いたいという場合があります。まず rcスクリプトから Dtrace を実行することが考え付くと思いますが、rcスクリプトが実行されるよりももっと前の段階から情報を採取したいようなときは、匿名トレースと呼ばれる方法を利用することが有効です。もちろん rcスクリプトが実行された後の調査でも利用できます。

dtrace コマンドを -Aオプション付きで実行すると、dtrace ドライバの構成ファイル(通常は /kernel/drv/dtrace.conf) に処理内容が書き込まれます。また、/etc/system に dtrace ドライバが強制ロードされるように forceload文が書き込まれます。この状態で OS を起動すると、/etc/system が読み込まれた段階で dtraceドライバがロードされ、ドライバ構成ファイル内の処理内容に従って dtraceが実行されます。/etc/system が読み込まれるのは、OS起動時のかなりはやい段階ですので、OS起動時の多くの問題はこれで調査することが可能です。

匿名トレースで実行された dtrace の出力はメモリ上のバッファに蓄えられます。内容を確認する方法は二通りあります。一つはモジュールデバッガの mdbコマンドを利用する方法で、もう一つは dtrace コマンドの -a オプションを付けて実行する方法です。ただdtrace -aは一度実行すると情報がバッファから消去されます。

以下に一連の流れを含んだ実行例を示します。例では、コマンドの実行をトレースするスクリプトexec.dを使用しています。これで、OS起動中にどのようなコマンドが実行されているのかトレースできます。

exec.d

#!/usr/sbin/dtrace -qs

BEGIN
{
   printf("%-20s %6s %6s %6s %sn", "TIME", "UID", "PID", "PPID", "ARGS");
}

proc:::exec-success,exec-failure
{

   printf("%-20Y %6d %6d %6d ", walltimestamp, uid, pid, ppid);
   printf("%sn", curpsinfo->pr_psargs);
}

以下のように通常時に実行するオプションに加えて -Aオプションを付けて実行すると、dtrace.conf と /etc/system に匿名トレースのための記述がされます。

# dtrace -A -qs exec.d
dtrace: saved anonymous enabling in /kernel/drv/dtrace.conf
dtrace: added forceload directives to /etc/system
dtrace: run update_drv(1M) or reboot to enable changes
#

/etc/system には、OS起動時の情報が採取できるようにモジュールを強制ロードする記述が追記されます。

/etc/system 抜粋

* vvvv Added by DTrace
*
* The following forceload directives were added by dtrace(1M) to allow for
* tracing during boot.  If these directives are removed, the system will
* continue to function, but tracing will not occur during boot as desired.
* To remove these directives (and this block comment) automatically, run
* "dtrace -A" without additional arguments.  See the "Anonymous Tracing"
* chapter of the Solaris Dynamic Tracing Guide for details.
*
forceload: drv/fasttrap
forceload: drv/sdt
forceload: drv/systrace
forceload: drv/profile
forceload: drv/fbt
forceload: drv/lockstat
forceload: drv/dtrace
* ^^^^ Added by DTrace

dtrace.conf には、dtrace の処理に応じた内容が記載されます。ただし、以下の例をご覧いただくとわかると思いますが、人間には理解できるようには書かれていません。

/kernel/drv/dtrace.conf

#
# Copyright 2003 Sun Microsystems, Inc.  All rights reserved.
# Use is subject to license terms.
#
#ident  "@(#)dtrace.conf        1.1     03/09/02 SMI"

name="dtrace" parent="pseudo" instance=0;
dof-data-0=0x7f,0x44,0x4f,0x46,0x2,0x2,0x1,0x2,0x8,0x8,0x0,0x0,0x0,0x0 ……

これで準備できましたので、OS を再起動します。

まず、mdbコマンドで出力結果を確認してみます。mdb は -k オプションを付けてカーネルデバッグモードで実行します。そうすると mdbのコマンドプロンプトが表示されますので、そこで mdb のサブコマンドを実行します。余談ですが、dcmdsというサブコマンドで、どのようなサブコマンドがあるか確認できます。

まず、dtrace_stateサブコマンドで対象のアドレスを確認します。次に確認できたアドレスに対して dtraceサブコマンドを実行すると、通常の dtrace実行時と同じような出力結果が表示できます。mdb でのコマンド実行は アドレス::サブコマンドの形式で実行します(アドレス指定無しで実行できるサブコマンドもあります)。
以下が実行例となります。プロセス番号 1 の initプロセスから実行されたコマンドがすべて採取されています。

# mdb -k
Loading modules: [ unix genunix specfs dtrace ufs pcipsy ip hook neti sctp arp usba fctl nca zfs sd isp audiosup cpc random crypto fcip logindmux ptm sppp nfs ]
> ::dtrace_state
            ADDR MINOR             PROC NAME                         FILE
     30001192fc0     2                - <anonymous>                     -
> 30001192fc0::dtrace
TIME                    UID    PID   PPID ARGS
2012 Mar 30 10:56:20      0      1      0 /sbin/init
2012 Mar 30 10:56:26      0      4      1 INITSH -c exec /sbin/autopush -f /etc/iu.ap
2012 Mar 30 10:56:26      0      4      1 /sbin/autopush -f /etc/iu.ap
2012 Mar 30 10:56:28      0      5      1 INITSH -c exec /sbin/soconfig -f /etc/sock2path
2012 Mar 30 10:56:28      0      5      1 /sbin/soconfig -f /etc/sock2path
2012 Mar 30 10:56:29      0      6      1 INITSH -c exec /lib/svc/bin/svc.startd        >/dev/msglog 2<>/dev/msglog </dev/consol
2012 Mar 30 10:56:29      0      6      1 /lib/svc/bin/svc.startd
2012 Mar 30 10:56:30      0      8      7 /lib/svc/bin/svc.configd
2012 Mar 30 10:56:38      0     10      7 /sbin/sh -c exec /lib/svc/method/svc-tnctl
2012 Mar 30 10:56:38      0     10      7 /sbin/sh /lib/svc/method/svc-tnctl
2012 Mar 30 10:56:38      0     11      7 /sbin/sh -c exec /lib/svc/method/fs-root
2012 Mar 30 10:56:38      0     11      7 /sbin/sh /lib/svc/method/fs-root
2012 Mar 30 10:56:38      0     12     11 /sbin/zonename
...省略...
> ::quit

次に dtrace -a の出力例を示します。二度目の実行ではトレース情報が表示されません。

# dtrace -a
dtrace -a
TIME                    UID    PID   PPID ARGS
2012 Mar 30 10:56:20      0      1      0 /sbin/init
2012 Mar 30 10:56:26      0      4      1 INITSH -c exec /sbin/autopush -f /etc/iu.ap
2012 Mar 30 10:56:26      0      4      1 /sbin/autopush -f /etc/iu.ap
2012 Mar 30 10:56:28      0      5      1 INITSH -c exec /sbin/soconfig -f /etc/sock2path
2012 Mar 30 10:56:28      0      5      1 /sbin/soconfig -f /etc/sock2path
2012 Mar 30 10:56:29      0      6      1 INITSH -c exec /lib/svc/bin/svc.startd        >/dev/msglog 2<>/dev/msglog </dev/consol
2012 Mar 30 10:56:29      0      6      1 /lib/svc/bin/svc.startd
2012 Mar 30 10:56:30      0      8      7 /lib/svc/bin/svc.configd
2012 Mar 30 10:56:38      0     10      7 /sbin/sh -c exec /lib/svc/method/svc-tnctl
2012 Mar 30 10:56:38      0     10      7 /sbin/sh /lib/svc/method/svc-tnctl
2012 Mar 30 10:56:38      0     11      7 /sbin/sh -c exec /lib/svc/method/fs-root
2012 Mar 30 10:56:38      0     11      7 /sbin/sh /lib/svc/method/fs-root
2012 Mar 30 10:56:38      0     12     11 /sbin/zonename
...省略...
# dtrace -a
dtrace: could not enable tracing: No anonymous tracing state
#

匿名トレースの設定を解除したい場合には、dtaceコマンドを -A オプションのみで実行します。そうすると、dtraceドライバの構成ファイル(/kernel/drv/dtrace.conf)と /etc/system から追記された情報が削除されます。

# dtrace -A
dtrace: cleaned up old anonymous enabling in /kernel/drv/dtrace.conf
dtrace: cleaned up forceload directives in /etc/system
#

以上が Dtrace を使用した応用例の紹介となりますが、何かの調査の際に役立てば幸いです。

参考情報)