Solaris 動的トレースガイド

例

以下は、mpstat(1M) の出力例です。

CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
 12   90  22 5760   422  299  435   26   71  116   11  1372    5  19  17  60
 13   46  18 4585   193  162  431   25   69  117   12  1039    3  17  14  66
 14   33  13 3186   405  381  397   21   58  105   10   770    2  17  11  70
 15   34  19 4769   109   78  417   23   57  115   13   962    3  14  14  69
 16   74  16 4421   437  406  448   29   77  111    8  1020    4  23  14  59
 17   51  15 4493   139  110  378   23   62  109    9   928    4  18  14  65
 18   41  14 4204   494  468  360   23   56  102    9   849    4  17  12  68
 19   37  14 4229   115   87  363   22   50  106   10   845    3  15  14  67
 20   78  17 5170   200  169  456   26   69  108    9  1119    5  21  25  49
 21   53  16 4817    78   51  394   22   56  106    9   978    4  17  22  57
 22   32  13 3474   486  463  347   22   48  106    9   769    3  17  17  63
 23   43  15 4572    59   34  361   21   46  102   10   947    4  15  22  59

この出力をよく見ると、システムが比較的アイドル状態にあるのに xcal フィールドの値が大きすぎることがわかります。mpstat は、xcal フィールドの値を決めるとき、sys カーネル統計情報の xcalls フィールドを調べます。したがって、次の例のように xcalls sysinfo プローブを有効にすれば、この異常について簡単に調べることができます。

# dtrace -n xcalls'{@[execname] = count()}'
dtrace: description 'xcalls' matched 4 probes
^C
  dtterm                                                            1
  nsrd                                                              1
  in.mpathd                                                         2
  top                                                               3
  lockd                                                             4
  java_vm                                                          10
  ksh                                                              19
  iCald.pl6+RPATH                                                  28
  nwadmin                                                          30
  fsflush                                                          34
  nsrindexd                                                        45
  in.rlogind                                                       56
  in.routed                                                       100
  dtrace                                                          153
  rpc.rstatd                                                      246
  imapd                                                           377
  sched                                                           431
  nfsd                                                           1227
  find                                                           3767

この出力から、クロスコールのソースをどこで探せばよいかがわかります。ほとんどのクロスコールは、find(1) プロセス数個に影響を受けています。問題をもっと詳しく調べるには、次の D スクリプトを使用します。

syscall:::entry
/execname == "find"/
{
	self->syscall = probefunc;
	self->insys = 1;
}

sysinfo:::xcalls
/execname == "find"/
{
	@[self->insys ? self->syscall : "<none>"] = count();
}

syscall:::return
/self->insys/
{
	self->insys = 0;
	self->syscall = NULL;
}

このスクリプトでは、syscall プロバイダを使って、find からのクロスコールがどのシステムコールに起因するか調べます。ページフォルトに起因するクロスコールなど、システムコールに起因しないクロスコールも存在します。この場合は <none> と出力されます。このスクリプトを実行すると、次のような出力が得られます。

# dtrace -s ./find.d
 dtrace: script './find.d' matched 444 probes
^C
  <none>                                                            2
  lstat64                                                        2433
  getdents64                                                    14873

find によるクロスコールの大部分が、システムコール getdents(2) によって行われています。以降の作業は、調べたい内容に応じて異なります。たとえば、find プロセスが getdents を呼び出している理由を調べたい場合は、find がクロスコールを引き起こしたときに ustack() を集積するような D スクリプトを作成するとよいでしょう。getdents の呼び出しがクロスコールを引き起こす理由を調べたい場合は、find がクロスコールを引き起こしたときに stack() を集積するような D スクリプトを作成するとよいでしょう。次の作業が何であっても、xcalls プローブを利用することで、異常な監視結果が出力された原因を簡単に突き止めることができます。