Watson's Blog

RubyMotion アプリで DTrace を使ってみよう

| Comments

この記事は RubyMotion Advent Calendar 2012 の 3 日目の記事です。

DTrace は Sun Microsystems が開発した実行中のアプリの情報を取得する仕組みです。DTrace を使用するとアプリケーションを一切変更することなく情報取得を可能にします。 Xcode に付属している Instruments が様々な情報を表示できるのは、縁の下に DTrace が存在しているからです。

Ruby 2.0 preview2 でいよいよ DTrace がサポートされましたが、MacRuby や RubyMotion ではすでに DTrace をサポートしています。

プローブを確認してみる

DTrace では、アプリに埋め込まれている「プローブ」と呼ばれる計測ポイントを用い、追跡をおこないます。

現在利用可能なプローブの一覧は sudo dtrace -l で確認することができます。シミュレータで RubyMotion アプリを実行した状態で確認してみましょう。

1
2
3

$ motion create HelloDTrace
$ cd HelloDTrace
$ rake

別の Terminal ウィンドウで sudo dtrace -l を実行してみます。

1
2
3
4
5
6
7
8

$ sudo dtrace -l
   ID   PROVIDER            MODULE                          FUNCTION NAME
    1     dtrace                                                     BEGIN
    2     dtrace                                                     END
    3     dtrace                                                     ERROR
    4   lockstat       mach_kernel                      lck_mtx_lock adaptive-acquire
    5   lockstat       mach_kernel                      lck_mtx_lock adaptive-spin
...

各列の説明を簡単にします。

  • PROVIDER は、プローブを提供しているプログラムの識別子のようなものです。
  • MODULE は、プローブが属するカーネルモジュール名やライブラリ名が入ります。上のように、存在しない場合もあります。
  • FUNCTION は、プローブが属するプログラムの関数名を表します。上の例のように、存在しない場合もあります。
  • NAME は、プローブの機能を表す名前を表します。

大量に表示されるプローブの一覧から RubyMotion が提供しているものを探し出すのは不可能に近いので grep で検索してみましょう。

1
2
3
4

$ sudo dtrace -l | grep HelloDTrace
 8037 macruby2577       HelloDTrace                    rb_vm_dispatch method-entry
 8038 macruby2577       HelloDTrace                    rb_vm_dispatch method-return
 8039 macruby2577       HelloDTrace   _ZL10__vm_raisev [__vm_raise()] raise

RubyMotion は MacRuby と同様に macruby というプロバイダ名でプローブを提供しています。プローブは method-entry、 method-return と raise の 3 種類あることが分かります。

プローブ説明

プローブ名実行タイミング変数 arg0変数 arg1変数 arg2変数 arg3
method-entryメソッド呼出開始クラス名メソッド名ソースファイル名行番号
method-returnメソッド呼出終了クラス名メソッド名ソースファイル名行番号
raise例外発生時クラス名ソースファイル名行番号-

method-entry プローブが実行されるとき、変数 arg0 にはクラス名、変数 arg1 には メソッド名が格納されています。(ソースファイル名と行番号は正しく格納されていない)

とりあえず動かしてみよう

準備

最初に作成した HelloDTrace アプリの app/app_delegate.rb を以下のように変更しておきます。

app/app_delegate.rb 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

def hello_dtrace
  time = Time.now
  UIAlertView.alloc.initWithTitle(
    "Hello DTrace",
    message: "Current time is #{time.to_s}",
    delegate: nil,
    cancelButtonTitle: nil,
    otherButtonTitles: "OK",
    nil
  ).show
end

class AppDelegate
  def application(application, didFinishLaunchingWithOptions:launchOptions)
    true
  end
end

次に以下のような DTrace 用のスクリプト trace.d を用意します。

trace.d 
1
2
3
4
5
6
7
8
9

// メソッドの開始と終了の出力をインデント (->) を付けて表示させる
#pragma D option flowindent

macruby$target:::method-entry,
macruby$target:::method-return
{
    /* arg0 にはクラス名、 arg1 にはメソッド名が格納されています */
    printf("(%s#%s)", copyinstr(arg0), copyinstr(arg1))
}

実行してみよう

まずは RubyMotion アプリを rake コマンドで起動します。

シミュレータが起動したところで、別の Terminal ウィンドウで起動したアプリのプロセス ID を ps コマンドやアクティビティモニターで調べておきます。DTrace を実行する際にこのプロセス ID を使用します。

1
2

$ ps cux | grep HelloDTrace
watson  5140   0.0  0.3   875476  21148   ??  S     6:04PM   0:00.31 HelloDTrace

プロセス ID は 5140 でした。

次に DTrace を実行します。dtrace の後に -s オプションで用意した DTrace 用のスクリプト、-p で情報を取得するプロセスの ID を指定します。

1

$ sudo dtrace -s trace.d -p 5140

マウスカーソルを移動するたびに DTrace の実行画面にトレース情報が表示されるかと思います。シミュレータ上でマウスオーバーを検出するためにマウスカーソルのイベントが発生するとやりとりしているようです。(キーボード操作だけで乗り切ると、余計なログが表示されず見やすくなります)

RubyMotion の REPL で hello_dtrace メソッドを実行してみましょう。シミュレータにはアラートビューが表示され、DTrace を実行している Terminal には以下のように DTrace を起動した後に実行されたメソッドが表示されます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

  0  -> rb_vm_dispatch                        (TopLevel#inspect)
  0  <- rb_vm_dispatch                        (TopLevel#inspect)
  1  -> rb_vm_dispatch                        (TopLevel#hello_dtrace)
  1    -> rb_vm_dispatch                      (Class#now)
  1      -> rb_vm_dispatch                    (Class#alloc)
  1      <- rb_vm_dispatch                    (Class#alloc)
  1      -> rb_vm_dispatch                    (Time#initialize)
  1      <- rb_vm_dispatch                    (Time#initialize)
  1    <- rb_vm_dispatch                      (Class#now)
  1    -> rb_vm_dispatch                      (Time#to_s)
  1    <- rb_vm_dispatch                      (Time#to_s)
  1    -> rb_vm_dispatch                      (UIAlertView#inspect)
  1      -> rb_vm_dispatch                    (UIAlertView#to_s)
  1      <- rb_vm_dispatch                    (UIAlertView#to_s)
  1    <- rb_vm_dispatch                      (UIAlertView#inspect)
  3  <- rb_vm_dispatch                        (TopLevel#hello_dtrace)
^C

インデントの深さに応じて、メソッドがどのような順序で呼び出されているかが分かります。

CTRL + c か RubyMotion アプリを終了させると DTrace が終了します。

メソッドの実行時間を計測してみよう

今度はメソッドの実行時間を計測してみよう。使用するスクリプトは以下のようになります。

time.d 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

#pragma D option quiet

macruby$target:::method-entry
/ copyinstr(arg0) == "String" /  /* String クラスだけを計測する */
{
  self->starttime = walltimestamp / 1000;
}

macruby$target:::method-return
/ copyinstr(arg0) == "String" /  /* String クラスだけを計測する */
{
  @invoked_time[copyinstr(arg0), copyinstr(arg1)] = sum((walltimestamp / 1000) - self->starttime);
}

END
{
    printf("\n");
    printf("%-10s  %-15s  %s\n", "CLASS", "METHOD", "TOTAL TIME µsec");
    printf("--------------------------------------------------------------------------------\n");
    printa("%-10s  %-15s  %@d\n", @invoked_time);
}

/ copyinstr(arg0) == "String" / という記述を追加すると、変数 arg0 が “String” と一致するときだけ計測されるようになります。

DTrace で上のスクリプトを実行すると次のように、String クラスのメソッドの実行時間の合計が表示されます。

1
2
3
4
5

CLASS       METHOD           TOTAL TIME µsec
--------------------------------------------------------------------------------
String      +:               64
String      *:               71
String      index:           68125

わざわざアプリにパフォーマンスを計測するためのコードを追加しなくても、どのメソッドの処理が重たいのかが分かります。

まとめ

DTrace を利用すると、アプリケーションは全く変更しなくても実行をトレースすることができます。RubyMotion アプリはもちろん、Ruby 2.0 で DTrace がサポートされると Web アプリでも同様にトレースできることでしょう。

参考

MacRuby の DTrace のサンプルです。メソッドの実行回数を計測するスクリプトがあったりします。

DTrace の基本が書かれています。

DTrace についてはオラクルのドキュメントが一番詳しいです。

Comments