dtrace

/usr/ports 方面では、jpeg とか xorgでお祭になっていたようだけど、私は淡々と portupgrade しましたよ。そしたら、nmapが月(lua)を伴って、やって来ました。 configureの最終画面が、AA だったので、記念撮影しておきます。(笑)

config.status: creating config.h
            .       .
            \`-"'"-'/
             } 6 6 {
            ==. Y ,==
              /^^^\  .
             /     \  )  Ncat: A modern interpretation of classic Netcat
            (  )-(  )/
            -""---""---   /
           /   Ncat    \_/
          (     ____
           \_.=|____E
Configuration complete.
   (  )   /\   _                 (
    \ |  (  \ ( \.(               )                      _____
  \  \ \  `  `   ) \             (  ___                 / _   \
 (_`    \+   . x  ( .\            \/   \____-----------/ (o)   \_
- .-               \+  ;          (  O                           \____
(__                +- .( -'.- <.   \_____________  `              \  /
(_____            ._._: <_ - <- _- _  VVVVVVV VV V\                \/
  .    /./.+-  . .- /  +--  - .    (--_AAAAAAA__A_/                |
  (__ ' /x  / x _/ (                \______________//_              \_______
 , x / ( '  . / .  /                                  \___'          \     /
    /  /  _/ /    +                                       |           \   /
   '  (__/                                               /              \/
                                                       /                  \
             NMAP IS A POWERFUL TOOL -- USE CAREFULLY AND RESPONSIBLY
Configuration complete.  Type make (or gmake on some *BSD machines) to compile.

apt-get dist-upgrade とかだと、作者の息吹が感じられなくてつまんないけど、srcから だと、こういう楽しみがあって、好きだったりします。それにしても、作者さんは、2chで修行したのだろうか? それとも、寄贈品?

dtrace

風の噂では、ruby-1.9.2 で、dtrace をサポートするそうだ。プローブを埋め込んで びしばしと鍛えあげようって算段なのでしょうか。それとも、macruby方面からの圧力で ruby.specに盛り込まれたので、MRIでも実現せにゃとなったのでしょうか?

プローブって、オシロスコープに観測したい電気信号を導くための針の事です。えっ、 オシロスコープを知らないって? そんなら、SICP本のp165に例が出てますね。言って みれば、debug-printか。但し、debug-printだとユーザーが必要そうな所に埋め込んで あげなければならないし、enable/disableも面倒。得られた結果を統計処理(何回、Hit したか等)したいなんてのは、夢のまた夢であったりする。

dtraceは、これらの難題を統一的に解決する仕組みだ。D言語を使ってスクリプト化して おけるし、LLみたいにその場で臨機応変にプローブを活性化してデータ採取しても良い。 勿論、必要そうな所にあらかじめプローブが埋め込まれている。どんなプローブが必要か は、OS屋さん(かどうかは知らないけれど)が決めて、埋め込んでくれている。

dtraceとかzfsは、Sunで開発されて、FreeBSDとかMacには取り込まれているけど、 主義主張が違うLinux方面には、取り込めないみたいです。まあ、目玉の多いLinux 方面ですから、SystemTap なるものが作られています。

Tapって、怪しい雰囲気で好きだなあ。電話線に針を立てたりして。。こういうのは公安の 得意技かな。おいらは、黄色く太いケーブルに、よく針を立ててトランシーバーを 取り付け、パソコンをネット参加させたものです。今の人は知らないだろうけど。

偉そうにこんな事を書いてますが、実は私もdtraceを良く知らんのです。この際だから どんな物か少々手をだし手みる事にします。

資料など

そりゃ、man dtraceでしょうとなる訳だが、ちと歯が立たない。rubyを使いこなすに man rubyじゃ無理ってのと一緒。相手は何せ、D言語ですからねえ。

Sunのサイトへ資料を探しに行きましたよ。そしたら、何とまあ、真っ赤に紅葉してる じゃないですか。Oracleですって。そのうちに、docs.sun.comのURLも無くなっちゃう んでしょうか? 一抹の寂しさが沸いてきますねぇ。

資料は2つ DTrace ユーザーガイドSolaris 動的トレースガイド。 前者の方で概要を掴んで、後者は詳細を調べるって使い方になるかな。 仕組みについての、 技術的説明はここが参考になります。

参考と言いつつ、いきなりチョモランマまで征服するような飛ばしっぷりで、中高年は 途中で遭難しかねません。まずは、近くの山で足腰を鍛えてからにしますかね。 東京周辺では、ハイヒールでも登っちゃう高尾山ぐらいからですかね。(って、山を 舐めたら、遭難するぜー。せいぜい、ゼイゼイしない、山からですかね)

と思っていたら、トレーニング用も用意されて いました。ありがたい事です。更にはいろいろと 楽しい記事が満載されてました。 もう、自分で実験してみる事は無いかな?

いやいや、科学の進歩は、追試による所も多いので。。。

dtrace追試

まずは、型通り、どんなプローブがあるか調べてみます。

sakae@solaris:~/DTRACE$ dtrace -l | head
dtrace: failed to initialize dtrace: DTrace requires additional privileges

型通りにエラーになりました。そう、普通のユーザーにはセキュリティーの観点から 使用を禁止されてます。その事を上のエラーから読み取れたら、以下は読まなくて結構。 そんじゃ一応root権限でやります。

root@solaris:~/DTRACE# dtrace -l | head -5
   ID   PROVIDER            MODULE                          FUNCTION NAME
    1     dtrace                                                     BEGIN
    2     dtrace                                                     END
    3     dtrace                                                     ERROR
    4        fbt                bl                         bl_attach entry
root@solaris:~/DTRACE# dtrace -l | tail -5
60779   lockstat           genunix                     rw_tryupgrade rw-upgrade
60780   lockstat           genunix                      rw_downgrade rw-downgrade
60781   lockstat           genunix                       thread_lock thread-spin
60782   lockstat           genunix                  thread_lock_high thread-spin
61789    profile                                                     tick-1sec

プローブのリストです。非常にたくさん(私の所では、6万個以上ありました)あるので 最初と最後を出してみました。 いろいろな目的のプローブがあるので、ユーザーが迷わないように階層化されてます。 D言語内でプローブを指定する時は、PROVIDER:MODULE:FUNCTION:NAME という風に 指定します。fbt:bl:bl_attach:entryとかprofile:::tick-1sec みたいにですね。(略記法も あるようですが)

特定の階層に属すのもリストできます。その場合は -P,-m,-f,-nを付けます。

root@solaris:~/DTRACE# dtrace -lm genunix | head -5
   ID   PROVIDER            MODULE                          FUNCTION NAME
 2435    sysinfo           genunix                mod_remove_by_name modunload
 2436    sysinfo           genunix                 mod_uninstall_all modunload
 2437    sysinfo           genunix                        modunrload modunload
 2438    sysinfo           genunix                          modrload modload
root@solaris:~/DTRACE# cat count.d
pid$target:a.out::entry
{
    @counts[probefunc] = count();
}

pid$target:a.out::return
{
}

例に出ていた、D言語スクリプトです。ユーザープログラムの関数呼び出し状況を 調べてくれます。

root@solaris:~/DTRACE# dtrace -s count.d -q -c ../work/mosc
13
^C

  __fsr                                                             1
  _start                                                            1
  main                                                              1
  setup_audio                                                       1
  fill                                                              2

おお、ちゃんと検査してくれてるよ。_startはいいとして、__fsrて何よ。Solaris特有な もの?

次は、関数の実行時間をレポートするものだ。

root@solaris:~/DTRACE# cat time.d
pid$target:a.out::entry
{
    self->ts[probefunc] = timestamp;
}

pid$target:a.out::return
/probefunc != "main"/
{
    @sum[probefunc] = sum(timestamp - self->ts[probefunc] );

    self->ts[probefunc] = 0;
}
root@solaris:~/DTRACE# dtrace -s time.d -q -c ../work/mosc
310

  __fsr                                                         30886
  fill                                                          44913
  setup_audio                                               116918763

出てくる数値は、ナノ秒単位との事。上の例だと、fill関数は、約45マイクロ秒で 実行されてるんだな。

D言語って、進化したawkみたいな言語だな。time.dを例にすれば、指定されたプローブに 出会ったら、ブロック内を実行せよだな。但し /.../で、条件を付けられるよと。

関数に突入した時の時間を、関数名をKeyにした連想配列に記憶。関数からreturn する(但し、main関数以外)時、実行時間を求めてから、加算せよ。 dtraceを終了する時は、今までの結果を出力せよ、と言う、あ、うんの呼吸になってる。 ね、専用のawkでしょ。(BEGINとかENDも指定すれば、ちゃんと動くよ)

awkと言えば、一行野郎がかかせません。もどきのdtraceも勿論使えます。

root@solaris:~/DTRACE# dtrace -n 'pid$target:::entry{}' -c pwd | more
dtrace: description 'pid$target:::entry' matched 3419 probes
/export/home/sakae/DTRACE
CPU     ID                    FUNCTION:NAME
  0  61068                      tsort:entry
  0  61014                set_environ:entry
  0  60899                 lookup_sym:entry
  :
  0  63150     pthread_setcancelstate:entry
  0  63440                lmutex_lock:entry
  0  63158    set_cancel_pending_flag:entry
  0  63441              lmutex_unlock:entry
dtrace: pid 2620 has exited

たかがpwdなれど、内部では呆れるぐらいたくさんの関数が呼びだされていましたよ。

コマンド集を見る

dtraceがスクリプトなら、きっと誰かがそれ用のアプリケーションを書いているに違いない。 誰も、rubyそのものだけじゃ使わないのと一緒だな。

opensolarisの場合は、/opt/DTT以下に、既に準備されてます。 ネット上にも公開されてます。

この下にあるBinの中には、たくさんの*.dがありますが、中には .dと言うサフィックス 無しも混じっています。これって、/usr/bin/bashあたりでdtraceをラッッピングした ものだったりします。

root@solaris:/opt/DTT/Bin# ./dappprof ls
anonpgpid.d    j_cputime.d      php_cpudist.d    rb_flow.d       swapinfo.d
 :
j_cpudist.d    php_calltime.d   rb_cputime.d     statsnoop       zvmstat

CALL                                                       ELAPSED
set_char_quoting                                             26008
get_quoting_style                                            26224
__fsr                                                        27492
  :
quote_name                                               154025990
sort_files                                               157179287
print_many_per_line                                      312593350
print_dir                                                546241557

プロファイラーですね。

つらつら見てたらスクリプトの名前に、rbとかpyとかで始まるやつがあったよ。これって ひょっとして、ruby用とかpython用?

rubyでもdtrace?

sakae@solaris:/opt/DTT/Ruby$ ls
Readme         rb_calltime.d  rb_flow.d      rb_funccalls.d  rb_objcpu.d  rb_syscalls.d
rb_calldist.d  rb_cpudist.d   rb_flowinfo.d  rb_lines.d      rb_objnew.d  rb_syscolors.d
rb_calls.d     rb_cputime.d   rb_flowtime.d  rb_malloc.d     rb_stat.d    rb_who.d
sakae@solaris:/opt/DTT/Ruby$
sakae@solaris:/opt/DTT/Ruby$ more Readme
Ruby - DTracing Ruby

   These scripts trace activity of the Ruby programming language, and
   require the DTrace Ruby provider written by Joyent.

   Currently, the DTrace Ruby provider is a seperate download either in
   patch, source or binary form. Start with the "Ruby DTrace" link on
   http://dtrace.joyent.com/, and after getting a version running, the
   scripts in this directory should work.

   Since the DTrace Ruby provider is under development, there is a chance
   that it has changed slightly by the time you are reading this, causing
   these scripts to either break or behave oddly. Firstly, check for newer
   versions of the DTraceToolkit; if it hasn't been updated and you need
   to use these scripts immediately, then updating them shouldn't take
   too long. The following was the state of the provider when these scripts
   were written - check for changes and update the scripts accordingly,
     :

つう事で、dtrace入りのrubyを configure --enable-dtrace して、こさえてみました。 早速実験してみます。

sakae@solaris:~/DTRACE$ /usr/local/bin/ruby -v
ruby 1.8.6 (2007-03-13 patchlevel 0) [i386-solaris2.11]
sakae@solaris:~/DTRACE$ cat func_slow.rb
#!/usr/local/bin/ruby -w

def func_c
  print "Function C\n"
  i = 0
  while i < 300000
     i = i + 1
     j = i + 1
  end
end

def func_b
  print "Function B\n"
  i = 0
  while i < 200000
     i = i + 1
     j = i + 1
  end
  func_c
end

def func_a
  print "Function A\n"
  i = 0
  while i < 100000
     i = i + 1
     j = i + 1
  end
  func_b
end

func_a

dtrace入りのrubyは、ちとVerが古いけど、許してね。 そして、観測用のD言語は

sakae@solaris:~/DTRACE$ cat rb_funccalls.d
#!/usr/sbin/dtrace -Zs
/*
 * rb_funccalls.d - count Ruby function (method) calls using DTrace.
 *                  Written for the Ruby DTrace provider.
 *
 * $Id: rb_funccalls.d 20 2007-09-12 09:28:22Z brendan $
 *
 * This traces activity from all Ruby programs on the system that are
 * running with Ruby provider support.
 *
 * USAGE: rb_funccalls.d        # hit Ctrl-C to end
 *
 * FIELDS:
 *              FILE            Filename of the Ruby program
 *              METHOD          Method name
 *              COUNT           Number of calls during sample
 *
 * Filename and method names are printed if available.
 *
 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
 *
 * CDDL HEADER START
 *
 *  The contents of this file are subject to the terms of the
 *  Common Development and Distribution License, Version 1.0 only
 *  (the "License").  You may not use this file except in compliance
 *  with the License.
 *
 *  You can obtain a copy of the license at Docs/cddl1.txt
 *  or http://www.opensolaris.org/os/licensing.
 *  See the License for the specific language governing permissions
 *  and limitations under the License.
 *
 * CDDL HEADER END
 *
 * 09-Sep-2007  Brendan Gregg   Created this.
 */

#pragma D option quiet

dtrace:::BEGIN
{
        printf("Tracing... Hit Ctrl-C to end.\n");
}

ruby*:::function-entry
{
        @funcs[basename(copyinstr(arg2)), copyinstr(arg0), copyinstr(arg1)] =
            count();
}

dtrace:::END
{
        printf(" %-32.32s %-16s %-16s %8s\n", "FILE", "CLASS", "METHOD",
            "CALLS");
        printa(" %-32.32s %-16s %-16s %@8d\n", @funcs);
}

先に、観測用のスクリプトを起動しておきます。すると、終了はCtrl-Cねって案内が 出てきます。そしたら、別端末から、rubyスクリプトを起動します。 このrubyスクリプトが終了したら、観測用スクリプトを終了させます。すると、

root@solaris:~/DTRACE# ./rb_funccalls.d
Tracing... Hit Ctrl-C to end.
^C
 FILE                             CLASS            METHOD              CALLS
 func_slow.rb                     Object           func_a                  1
 func_slow.rb                     Object           func_b                  1
 func_slow.rb                     Object           func_c                  1
 func_slow.rb                     IO               write                   3
 func_slow.rb                     Module           method_added            3
 func_slow.rb                     Object           print                   3
 func_slow.rb                     Fixnum           <                  600003
 func_slow.rb                     Fixnum           +                 1200000

いいですねぇ。これで、Railsの暗闇が暴けますね。パチパチパチ。だから早くruby-1.9.2 にも、適用してくださいな。パッチは、下記のようにに当たってました。

sakae@solaris:~/ruby-1.8.6$ grep -l DTRACE *.c
eval.c
gc.c
object.c
tracer.c
sakae@solaris:~/ruby-1.8.6$ ls *trace*
dtrace.d  dtrace.h  dtrace.o  tracer.c  tracer.o
sakae@solaris:~/ruby-1.8.6$ more dtrace.d
/* -*- Mode: C -*- */

provider ruby {
    probe function__entry(char*, char*, char*, int);
    probe function__return(char*, char*, char*, int);
    probe raise(char*, char*, int);
    probe rescue(char*, int);
    probe line(char*, int);

    /* gc probes */
    probe gc__begin();
    probe gc__end();

    /* Some initial memory type probes */
    probe object__create__start(char*, char*, int);
    probe object__create__done(char*, char*, int);
    probe object__free(char*);

    probe ruby__probe(char*, char*);
};

#pragma D attributes Evolving/Evolving/Common provider ruby provider
#pragma D attributes Private/Private/Common provider ruby module
#pragma D attributes Private/Private/Common provider ruby function
#pragma D attributes Evolving/Evolving/Common provider ruby name
#pragma D attributes Evolving/Evolving/Common provider ruby args

ツボな所に針を埋め込んでますねぇ。しかもその針が用途に合わせて選ばれているよ。 作者さんは、ひょっとして鍼灸師? 1.9.2だと、これらに プラスして、仮想マシンにも埋め込む? いえいえ、仮想マシンは、あの人がカリカリ にチューニングしてますから不要とおっしゃるかな?