X

Oracle Solaris, Oarcle ハードウェア製品に関する情報

Try Oracle Cloud Platform For Free
  • Sun
    September 17, 2009

DTrace を使ってロックの競合を調査する

Guest Author


はじめに

今回は DTrace を使用してロックの競合を調査する初歩的な手順をご紹介したいと思います。DTrace には豊富なプローブが用意されていますので、アイデアさえあれば無限にスクリプトを作成することが可能です。その全てを解説することは難しいですが、DTrace を使ってマルチスレッドプログラムの動きを調べる際の基礎となるスクリプトを幾つかご紹介したいと思います。


plockstat コマンドの実装から

先日ご紹介した plockstat コマンド はその機能の殆どを DTrace を利用して実装しています。OpenSolaris.org にある plockstat コマンドの ソースコード を見てみると、1000 行ほどのコードの内の 300 行ほどが DTrace スクリプトの定義で、残りはヘルパー関数になっています。実は、この plockstat コマンドに含まれている DTrace スクリプトは plockstat コマンドと独立して使用することも可能です。まず始めに、その使い方から見ていきましょう。


mutex ロックの競合を調査する DTrace スクリプト

plockstat コマンドのソースコードから mutex ロックの競合を検知している部分を抜き出して、単独で実行できる様に修正したのが下記のスクリプトです。plockstat$target::: で始まるプローブが並んでいますが、plockstat コマンドに含まれるスクリプトは DTrace の plockstat プロバイダの機能を利用しています。plockstat プロバイダは mutex ロックと reader/writer ロックを監視する為の DTrace のプロバイダです。plockstat コマンドは plockstat プロバイダの機能を全面的に使用しているため、plockstat コマンドは plockstat プロバイダのラッパーと言って良いかもしれません。続いて個々のプローブを見ていきましょう。plockstat$target:::mutex-block はスレッドが mutex ロックでブロックされる直前に呼び出されるプローブです。一方 plockstat$target:::mutex-blocked はブロックから解放された直後に呼び出されますので、mutex-block と mutex-blocked で timestamp の差分を取ると mutex ロックでブロックされていた時間を割り出す事が出来ます。なお、plockstat$target:::mutex-blocked の arg1 が 0 の場合は何らかのエラーで mutex ロックが取得できなかったことを意味するため、ブロックされていた時間には加算されていません。

 #!/usr/sbin/dtrace -s
 plockstat$target:::mutex-block
 {
   self->mtxblock[arg0] = timestamp;
 }
 plockstat$target:::mutex-blocked
 /self->mtxblock[arg0] && arg1 != 0/  /\* arg1 is not 0 => lock is acquired \*/
 {
   @mtx_block[arg0, ustack(5)] =
     sum(timestamp - self->mtxblock[arg0]);
   @mtx_block_count[arg0, ustack(5)] = count();
   self->mtxblock[arg0] = 0;
   mtx_block_found = 1;
 }
 plockstat$target:::mutex-blocked
 /self->mtxblock[arg0]/               /\* arg1 is 0 => error \*/
 {
   self->mtxblock[arg0] = 0;
 }
 END
 /mtx_block_found/
 {
   trace("Mutex block");
   printa(@mtx_block, @mtx_block_count);
 }


実際に動かしてみる

このスクリプトを先日の plockstat の記事 で使用したテストプログラムに対して実行してみた結果が以下の出力です。上から、"134614312" が plockstat コマンドの "Lock" のカラムに相当する mutex ロックのアドレス、次のスタックフレームが "Caller" のカラムを作成する為のデータです。"30002403544" は mutex ロックでブロックされていた総時間です。最後の "3" は plockstat コマンドの "Count" のカラムに相当するブロックされた回数です。先ほどの総時間をブロックされた回数で割ると、ブロックされた平均時間となり plockstat コマンドの "nsec" のカラムが求まります (30002403544 nsec / 3 Count = 10000801181 nsec)。きちんと plockstat コマンドに相当する情報が得られている事が分かります。

 # ./plockstat_mb.d -c ./mutex_test   <-- トレース対象のプログラムは -c オプションで指定します
 dtrace: script './plockstat_mb.d' matched 7 probes
 done
 done
 done
 dtrace: pid 9964 has exited
 CPU     ID                    FUNCTION:NAME
   1      2                             :END   Mutex block                      
         134614312  <-- "Lock"
               libc.so.1`mutex_lock_queue+0x24a
               libc.so.1`mutex_lock_impl+0x102
               libc.so.1`mutex_lock+0x1a
               mutex_test`func+0x13   <-- "Caller"
               libc.so.1`_thr_setup+0x4e
       30002403544                3  <-- "Count"
       ~~~~~~~~~~~ total time blocked


スレッドの毎に統計情報をまとめるスクリプト

先ほどのスクリプトを少しだけ書き換えて、ブロックされていた時間をスレッド毎に集計するスクリプトを作ってみました。下記のスクリプトを実行すると、プロセスを 10 秒間監視し、ブロックが発生した回数とブロックされていた時間をスレッド単位で出力します。先ほどのスクリプトからの変更点は、@mtx_block, @mtx_block_count 集積体のキーに tid を使用して、スレッド ID 毎に情報を集計しています。また、ブロックされた時間を保持していた self->mtxblock はスレッド毎に一つの値だけを保持すれば良いので、単純なスレッド固有変数にしてあります。tick-1sec は DTrace の profile プロバイダのプローブで、1 秒毎に呼び出されます。ここでは 10 秒間を数えるのに使用しています。

 #!/usr/sbin/dtrace -qs
 int ntick;
 BEGIN
 {
   ntick = 0;
 }
 plockstat$target:::mutex-block
 {
   self->mtxblock = timestamp;
 }
 plockstat$target:::mutex-blocked
 /self->mtxblock && arg1 != 0/  /\* arg1 is not 0 => lock is acquired \*/
 {
   @mtx_block[tid]= sum(timestamp - self->mtxblock);
   @mtx_block_count[tid] = count();
   self->mtxblock = 0;
 }
 plockstat$target:::mutex-blocked
 /self->mtxblock/               /\* arg1 is 0 => error \*/
 {
   self->mtxblock = 0;
 }
 tick-1sec
 {
   ntick += 1;
 }
 tick-1sec
 /ntick == 10/
 {
   trace("Count");
   printa(@mtx_block_count);
   trace("nsec");
   printa(@mtx_block);
   exit(0);
 }


DTrace スクリプトの実行結果

書き換えたスクリプトを plockstat コマンドの解説で使用した general.c で試してみます。Count 以下がブロックされた回数を表しており、nsec 以下がブロックされた時間を表しています。いずれも測定時間 10 秒辺りの結果です。Count の結果は、左側のカラムがスレッド ID、右側のカラムがブロックされた回数です。スレッド ID が 8 番のスレッドは 10 秒の間に 15197 回ブロックされていた事が分かります。nsec の結果も左のカラムはスレッド ID です。右側のカラムはナノ秒単位でブロックされていた総時間が出力されます。ここではスレッド ID 5 番のスレッドが 10 秒間のうち 5.8 秒間ブロックされていたことが見て取れます。

 # ./plockstat_mbt.d -c ./general
 Count
         8            15197
         2            15395
         3            15397
         7            15418
         6            15480
         4            15604
         9            15633
         5            16011
 nsec
         5       5849251426
         6       5891593031
         9       5904264724
         4       5912264400
         3       5953877535
         2       5983468423
         7       6004800234
         8       6067032588


plockstat プロバイダでトレースできないケースへの対応

plockstat プロバイダはその名の通り mutex ロックと reader/writer ロックを監視対象としており、条件変数でブロックされている場合は監視する事が出来ません。マルチスレッドプログラムでは条件変数も良く利用されていますので、mutex ロックや reader/writer ロックと同様に監視できると便利です。


条件変数のテストプログラム

以下のテストプログラムでは、各スレッドは main() 関数の中で res がインクリメントされるまで条件変数でブロックされます。

 /\*
  \* cv_test.c : a test program for cv tracing.
  \*   compile : cc cv_test.c -o cv_test
  \*/
 #include <stdio.h>
 #include <unistd.h>
 #include <atomic.h>
 #include <pthread.h>
 void \*func();
 volatile uint_t res = 0;
 pthread_mutex_t mp;
 pthread_cond_t cv;
 int main() {
   pthread_t tid1, tid2;
   pthread_mutex_init(&mp, NULL);
   pthread_cond_init(&cv, NULL);
   pthread_create(&tid1, NULL, func, NULL);
   pthread_create(&tid2, NULL, func, NULL);
   sleep(10);
   atomic_inc_uint(&res);
   pthread_mutex_lock(&mp);
   pthread_cond_broadcast(&cv);
   pthread_mutex_unlock(&mp);
   pthread_join(tid1, NULL);
   pthread_join(tid2, NULL);
   pthread_mutex_destroy(&mp);
   pthread_cond_destroy(&cv);
   exit(0);
 }
 void \*func() {
   pthread_mutex_lock(&mp);
   while(res == 0) {
     pthread_cond_wait(&cv, &mp);
   }
   puts("done");
   pthread_mutex_unlock(&mp);
   pthread_exit(0);
 }


コンパイル

上記のテストプログラムを cv_test.c という名前で保存し、以下の様にコンパイルして下さい。

 # gcc cv_test.c -o cv_test


prstat で調査する

prstat で見てみると LWPID 1 のスレッドがスリープ ("SLP") し、LWPID 2 と 3 のスレッドがロック待ち ("LCK") しているのが分かります。

 # ./cv_test&; prstat -mL -p $!
    PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID 
  10189 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 cv_test/3
  10189 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 cv_test/2
  10189 root     0.0 0.0 0.0 0.0 0.0 0.0 100 0.0   0   0   0   0 cv_test/1


plockstat で調査する

cv_test プログラムを plockstat コマンドと共に実行した結果が以下です。prstat コマンドではロック待ちをしていることが明らかに見て取れましたが、plockstat コマンドではロックの競合についての情報は一切出力されていません。

 # plockstat -Cv ./cv_test
 plockstat: tracing enabled for pid 19839
 done
 done
 plockstat: pid 19839 has exited


条件変数を調査する DTrace スクリプト

plockstat コマンドの代わりに以下の様な DTrace スクリプトを作成すれば条件変数を捕捉することが可能です。DTrace の pid プロバイダを使用して pthread_cond_wait() 関数の出入りを監視しています。同様に pthread_cond_timedwait() や pthread_cond_reltimedwait_np() についてスクリプトを作成すれば、汎用的に条件変数を監視することが可能です。

 #!/usr/sbin/dtrace -s
 pid$target::pthread_cond_wait:entry
 {
  self->start = timestamp;
  self->addr = arg0;
 }
 pid$target::pthread_cond_wait:return
 /self->start/
 {
  @time[tid,self->addr] = sum(timestamp - self->start);
  @cnt[tid,self->addr] = count();
  self->start = 0;
 }
 END
 {
   printf("¥n");
   printf("¥n");
   printf("tid¥tcv address¥ttime(nsec)¥n");
   printa("%d¥t%p¥t¥t%@u¥n", @time);
   printf("¥n");
   printf("tid¥tcv address¥tcount¥n");
   printa("%d¥t%p¥t¥t%@u¥n", @cnt);
 }


DTrace スクリプトの実行結果

上記スクリプトを cv.d という名前で保存し、実行権限を付けて、以下の様に実行して下さい。結果を見ると、tid 2 のスレッドの time(nsec) が 10000060220 (=> 10 sec)、tid 3 のスレッドの time(nsec) が 10000693754 (=> 10 sec) なので、各スレッドがそれぞれ 10 秒程ずつ待たされている事が分かります。また、tid 2, tid 3 のスレッドの count が 1 なので、両スレッドとも 1 回ずつ pthread_cond_wait() で待たされていたことになります。

 # chmod +x ./cv.d
 # ./cv.d -c ./cv_test      <-- トレース対象のプログラムは -c オプションで指定します
 dtrace: script './cv.d' matched 3 probes
 done
 done
 dtrace: pid 19939 has exited
 CPU     ID                    FUNCTION:NAME
   6      2                             :END 
 tid     cv address      time(nsec)      <-- pthread_cond_wait() で待った時間を条件変数とスレッド毎に集計
 2       8060fb8         10000060220
 3       8060fb8         10000693754
 tid     cv address      count      <-- pthread_cond_wait() で待った回数を条件変数とスレッド毎に集計
 2       8060fb8         1
 3       8060fb8         1


おわりに

以上、DTrace を使用してロックの競合を監視する基本的な方法をご紹介しました。ご覧頂きました通り、plockstat コマンドは DTrace の plockstat プロバイダを全面的に使用して実装されています。また、plockstat コマンドに含まれる DTrace スクリプトは DTrace のスクリプトとして単独でも使用可能であることも見て頂きました。更に、plockstat プロバイダでは捕捉できない条件変数のブロックを DTrace の pid プロバイダを使用したスクリプトで監視する方法もご紹介しました。DTrace にはここで紹介した以外にも proc プロバイダの lwp-create, lwp-start, lwp-exit と言ったプローブや、mutex_owned(), rw_write_held() 等のサブルーチンが備わっており、マルチスレッドプログラムの解析には非常に有用なツールです。是非ご活用下さい。


関連文書


マニュアル


plockstat プロバイダのマニュアル


『マルチスレッドのプログラミング』


ソースコード


plockstat コマンドのソースコード


plockstat プロバイダのソースコード


DTrace の解説

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.

Recent Content