more dtrace
先週の事だけど、春の陽気に誘われて税務署へ確定申告に行ってきた。別にFXで大儲けした訳 でもないので、そこん所誤解なきように。って、誤解する人も居ないよね。
この確定申告は、2/15からなんだけど、それ以前にも出来るようだ。期日前に申告したものは 税務署預かりになるとか。わざわざ税務署に出向かなくても、ブラウザーを使って家からも 出来ますよと、酷税庁のHPではさんざん宣伝してる。
でも、ネットでやろうとすると、悪名高き住基カードであらかじめ登録しておいてカード リーダーが必要。それがいやなら、家のプリンターに書類を打ち出してから郵送せいという 事になる。プリンターに打ち出す時に、PDFに変換するようなのだけど、アドビのやつしか 使えないようだ。おいらこの点で萎えましたよ。だって、アドビ製は、重い、でかい、メンテが 大変と３拍子揃ってますから、PCには入れていないんだ。この為だけにインストールするっての も、いやなんで断念したんだ。大体、PDFリーダーにJavaScriptをサポートする必要なんて あるんかいだ。国が執り行う事業なのにアドビ指定とは、いかがなものかと思うぞ。
我等がしもべである税務署職員がちゃんと働いているかの視察も兼ねて、午後１時ぴったりに 税務署へ行きましたよ。そしたら、丁度受付が始まった所でした。申告内容によって３種類に 分類してました。おいらが投入されたQueueは、前に２人並んでました。この時点で、Load averageが ２ですか。よく見てると、Queueによって進行スピードが違います。文句を言ってる人も いましたよ。
ほどなくして、おいらの番がきました。まずは、英数字８文字以上のパスワードを登録して ください、ですって。急に言われても、そんなの出てこんよ。ちょいと考えこんでいたら、 みなさん、生年月日とイニシャルを組み合わせてますよ、だってさ。おいおい、そんな誘導 するなよ。セキュリティーに対するリテラシーがゼロだぜ。こんなんじゃだめだろうに。
それが済んだら、基本情報やら、個別情報を入力して終わり。あっけないぐらい簡単に 終了しました。
帰りしなQueueを確認したら、ロードアベレージが３０ぐらいになってました。中には 腰の曲がった、おじいちゃん、おばあちゃんも混じってます。かわいそうに、ずっと 立たされたままなんですかね。せめて椅子を用意してあげる等の気配りは出来んのかね。 金を返してやるんだから、少しぐらいは我慢しろと言ってるようで腹が立ちましたよ。
more dtrace
昔、fortless とか言う過激な名前の言語をSunの人が作ってました。何故過激？ 私の推測ですが、fortran lessから来てると思うんだ。fortranより覚える事が 少なくて済む、やさしい言語って事でしょうか。
だったら、
Javaless ==> ruby
とかでしょうね。
more dtraceなら、いいでしょうか。もう少し dtraceのtoolKitを冒険してみます。 えっと、前回は、dtraceとrubyのコラボーションを見ましたが、いろいろな言語で dtrace出来るように、世界の好き者が頑張っています。
sakae@solaris:/opt/DTT/Code$ ls C Java JavaScript Perl Php Python Readme Ruby Shell Tcl
いろいろありますねぇ。JavaScriptにまであるって、ちょっとびっくりです。 そんじゃ、試してみますかね。
jruby は、どうかな？
jrubyって、dtrace上は、rubyの仲間？ それともjava派？
ruby族かと思って試してみたら、dtraceしてくれんかった。jrubyって皮を被って ますね。
sakae@solaris:~/DTRACE$ file /usr/bin/jruby /usr/bin/jruby: 実行可能 /bin/bash スクリプト
皮を調べてみたら、cygwinでも起動出来るようになってたよ。MS世界への侵略作戦だな。 Javaのオプションを渡せるように、Jオプションも用意してるあたり、用意周到だな。
sakae@solaris:~/DTRACE$ jruby -J
Usage: java [-options] class [args...]
(to execute a class)
or java [-options] -jar jarfile [args...]
(to execute a jar file)
where options include:
-d32 use a 32-bit data model if available
-d64 use a 64-bit data model if available
-client to select the "client" VM
-server to select the "server" VM
-hotspot is a synonym for the "client" VM [deprecated]
The default VM is client.
:
これを見てて思い出したんだけど、clojureを起動する時、-server オプションを 付けると、劇的に実行スピードが上がるとか。
そんじゃ、jrubyをJava族としてdtraceしてみます。Java用のdtraceスクリプトも いろいろ用意されてます。どんなのがあるかと言うと
Readme j_classflow.d j_flow.d j_package.d j_syscolors.d j_calldist.d j_cpudist.d j_flowtime.d j_profile.d j_thread.d j_calls.d j_cputime.d j_methodcalls.d j_stat.d j_who.d j_calltime.d j_events.d j_objnew.d j_syscalls.d
sakae@solaris:/opt/DTT/Java$ lv j_package.d
#!/usr/sbin/dtrace -Zs
/*
* j_package.d - count Java class loads by package using DTrace.
* Written for the Java hotspot DTrace provider.
*/
:
こんなのを選んでみました。Java用のdtraceを有効にするには、被測定javaプログラムに オプションを渡す必要があります。さて、行ってみよー。
sakae@solaris:~/DTRACE$ jruby -J-XX:+ExtendedDTraceProbes func_slow.rb Function A Function B Function C
実行結果は
sakae@solaris:/opt/DTT/Java$ pfexec ./j_package.d
Tracing... Hit Ctrl-C to end.
^C
PID LOADS PACKAGE
15981 1 com/sun/jmx/remote/util
15981 1 java/awt
:
15981 53 sun/misc
15981 59 org/jruby/gen
15981 99 java/lang
15981 115 java/util
15981 1233 org/jruby
次は、j_objnew.dの結果です。
:
16003 [C
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@ 2387
32 |@@@@@@@@@@@@@@@@@ 7877
64 |@@@@@@@@@@@@@@ 6428
128 |@@@@ 1644
256 |@ 267
512 | 39
1024 | 6
2048 | 8
4096 | 1
8192 | 2
16384 | 5
32768 | 1
65536 | 0
16003 org/jruby/RubyFixnum
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199516
64 | 0
Java object allocation count by pid and class,
PID OBJS CLASS
16003 1 $Proxy0
16003 1 [Ljava/lang/Integer;
:
16003 4390 java/util/HashMap$Entry
16003 6073 [B
16003 13782 java/lang/String
16003 18665 [C
16003 1199516 org/jruby/RubyFixnum
にやにやするには、うってつけ？
もう一丁行きます。今度は、clojureを起動してプロンプトが出てくるまでの、慌しさを モニターします。
sakae@solaris:~/clojure-1.1.0$ java -XX:+ExtendedDTraceProbes -cp clojure.jar clojure.main Clojure 1.1.0 user=>
やっぱり、舞台裏は忙しかったね。ごみ集めまでしてるよ。
sakae@solaris:/opt/DTT/Java$ pfexec ./j_stat.d TIME EXEC/s THREAD/s METHOD/s OBJNEW/s CLOAD/s EXCP/s GC/s 2010 Feb 28 16:09:18 0 0 0 0 0 0 0 2010 Feb 28 16:09:19 0 0 0 0 0 0 0 2010 Feb 28 16:09:20 2 5 18697 5488 303 40 0 2010 Feb 28 16:09:21 0 0 139572 22921 283 109 2 2010 Feb 28 16:09:22 0 0 175598 31764 166 160 2 2010 Feb 28 16:09:23 0 0 145002 28572 251 251 3 2010 Feb 28 16:09:24 0 0 169840 28890 230 216 2 2010 Feb 28 16:09:25 0 0 201867 31037 95 94 2 2010 Feb 28 16:09:26 0 0 228842 36332 45 36 2 2010 Feb 28 16:09:27 0 0 162605 28748 132 48 2 2010 Feb 28 16:09:28 0 0 0 0 0 0 0
sakae@solaris:/opt/DTT/Java$ pfexec ./j_cputime.d
Tracing... Hit Ctrl-C to end.
^C
Top 10 counts,
PID TYPE NAME COUNT
16096 method clojure/lang/PersistentHashMap$BitmapIndexedNode.find 18033
16096 method java/lang/String.startsWith 19501
16096 method java/lang/Object.equals 22987
16096 method clojure/lang/PersistentHashMap.valAt 28667
16096 method java/lang/Object.<init> 32641
16096 method clojure/lang/Var.get 34344
16096 method java/lang/Integer.bitCount 38850
16096 method clojure/lang/Var.deref 43969
16096 method clojure/lang/Var.getThreadBinding 43980
0 total - 1251112
Top 10 on-CPU times (us),
PID TYPE NAME TOTAL
16096 gc GC 104117
Top 10 exclusive method on-CPU times (us),
PID TYPE NAME TOTAL
16096 method clojure/lang/Var.getThreadBinding 189635
16096 method clojure/lang/PersistentHashMap$BitmapIndexedNode.find 209275
16096 method clojure/core$refer__5598.doInvoke 217686
16096 method java/lang/ClassLoader.defineClass1 219943
16096 method clojure/core$filter_key__5559.invoke 243346
16096 method clojure/lang/PersistentHashMap.valAt 251209
16096 method clojure/lang/Var.get 285749
16096 method clojure/lang/PersistentHashMap$BitmapIndexedNode.assoc 295069
16096 method clojure/lang/Var.deref 367520
0 total - 12770646
Top 10 inclusive method on-CPU times (us),
PID TYPE NAME TOTAL
16096 method clojure/core__init.<clinit> 5794047
16096 method clojure/lang/RestFn.invoke 7358242
16096 method clojure/lang/RT.doInit 10464696
16096 method java/lang/ClassLoader.loadClass 10800377
16096 method clojure/lang/RT.loadClassForName 10899812
16096 method clojure/lang/RT.<clinit> 10969485
16096 method java/lang/Class.forName0 11013430
16096 method java/lang/Class.forName 11023724
16096 method clojure/main.<clinit> 11135560
16096 method clojure/lang/RT.load 20094494
きりがないので、これぐらいにしといたる。 そうそう、Java屋さんには、dtraceのJava版であるbtraceの方が馴染みがあって、良いかも 知れません。D言語の代わりにjavaで書けるみたい。だったら、絶対にコマンド名は jtraceだと思うんだけど、JDKの中にある、J接頭語とぶつかるのを避けるために、頭が ｂなんだそうです。そして、ｂはこじつけがましく、byte code から頂いてきたとか。
次は、えーーと、、
FreeBSDでもdtraceする
Netを検索してみると、FreeBSD 7.1から、dtraceがサポートされたようだ。でも、こう いう機能は誰でも使うわけではないので、常にenableになってはいない。 使うためには、kernelを再構築してから再起動し、モジュールをロードすると言う手順が 必要みたい。好き者用だな。そんじゃ、やってみんべぇー。
options KDTRACE_HOOKS # all architectures #options KDTRACE_FRAME # amd64-only
上記を追加する。FreeBSD 8.0では、KDTRACE_HOOKSはコメントになってた。
$ cd /usr/obj/usr/src/sys/GENERIC/ $ make clean $ cd /usr/src $ make buildkernel WITH_CTF=1 $ make installkernel
WITH_CTF=1が肝らしい。これを忘れると、ロード時にエラーになるとか。何だろうと思って 探ってみると、Makefile.inc1に
# -DNO_CTF do not run the DTrace CTF conversion tools on built objects
こんな記述が見つかった。察してあげる事にします。 私の仮想PCでは、コンパイルに30分かかった。マシンが速くなるのと、コンパイル負荷が 増大するのと何時も追いかけっこしてて、時間短縮は出来ないなあ、と、天を仰ぐのでした。 新しいkernelで再起動してから、モジュールをロードします。
[sakae@cdr ~]$ sudo kldload dtraceall [sakae@cdr ~]$ kldstat Id Refs Address Size Name 1 37 0xc0400000 c5e710 kernel 2 2 0xc105f000 567d0 sound.ko 3 1 0xc10b6000 8c44 snd_es137x.ko 4 1 0xc10bf000 4e7c vmxnet.ko 5 1 0xc3405000 2000 star_saver.ko 6 1 0xc3424000 4000 vmmemctl.ko 7 1 0xc354c000 2000 dtraceall.ko 8 1 0xc354e000 3000 profile.ko 9 10 0xc3552000 3000 opensolaris.ko 10 3 0xc3555000 4000 cyclic.ko 11 8 0xc355a000 137000 dtrace.ko 12 1 0xc3716000 f000 systrace.ko 13 1 0xc3725000 2000 sdt.ko 14 1 0xc3727000 2000 lockstat.ko 15 1 0xc3735000 4000 fbt.ko 16 1 0xc3759000 3000 dtnfsclient.ko 17 1 0xc375c000 2000 dtmalloc.ko
dtrace関係は、Idが７以降のものです。なんともろにopensolarisなんてモジュールも ロードされてます。そんじゃ、幾つプローブが有るか調べてみます。
[sakae@cdr ~]$ sudo dtrace -l | wc -l 40022
opensolarisでは、6万個ありましたから、FreeBSDは大分少ないですね。人材が不足してて 設置が進まないのでしょうか？ プローブ設置し隊に立候補し鯛ぞ。
dtraceToolKitを、FreeBSDにも持ってきました。installと言うもろな名前のインストーラ が付属してます。が、スクリプトがksh語で書かれていたので、所定の場所に収めるのは 諦めました。適当に潜って、実験してみます。
[root@cdr /usr/home/sakae/DTraceToolkit-0.99/Kernel]# ./modcalls.d dtrace: script './modcalls.d' matched 19104 probes ^C opensolaris 10 vmmemctl 6948 star_saver 46785 kernel 46823481
スクリプトを起動して暫く放置しておきました。そして止めてみました。どうやら、 カーネルモジュールの呼び出し回数をカウントしてたようです。star_saverってのは、コンソール 用のスクリーンセーバーです。(お星様が、キラキラします)結構な回数、呼ばれているの ちょっとびっくりです。
[root@cdr /usr/home/sakae/DTraceToolkit-0.99/Proc]# ./syscallbyproc.d dtrace: script './syscallbyproc.d' matched 505 probes ^C syslogd 38 env 40 which 50 rm 52 grep 92 id 124 bash 125 uname 141 mkdir 143 expr 192 touch 196 awk 213 patch 275 sed 335 sudo 616 true 684 md5 784 sha256 784 chmod 790 chown 867 gmake 1104 make 1186 dtrace 2752 sh 3073 unzip 5333 vmtoolsd 8246 cc 16172 screen 16551 sshd 20066 ld 27030 as 28159 cc1 154206
これは、裏でとあるportsをコンパイルしてた時の、プロセス（コマンド）毎の システムコール状況です。portsのコンパイルとは言え、いろいろなコマンドが 駆使されてますねえ。
[root@cdr /usr/home/sakae/DTraceToolkit-0.99/Proc]# ./pidpersec.d dtrace: failed to compile script ./pidpersec.d: line 48: probe description proc:::exec-suc
一方、FreeBSDには、まだ移植されていないプローブもあり、そういうのは、dtrace自身 が失敗に終わってしまいます。グスン。
で、FreeBSDでも動きそうなプローブを使って、何か作ってみます。超簡単なやつで、へぇー と面白そうなもの、
#!/usr/sbin/dtrace -s
syscall::exec*:entry { @num[execname] = count(); }
このD言語は、コマンドの呼び出し回数をカウントするものです。これを使って、ruby 1.8.6(with dtrace) をインストールする過程で発行されるコマンドを調べてみました。なお、FreeBSD8.0では 、何故かext/opensslのコンパイルに失敗するので、あらかじめ除外してます。
==== configure ==== make 1 groff 2 cc 3 gcc 527 sh 2723 ==== make ==== sh 7 miniruby 33 gcc 192 make 791 ==== make test ==== make 1 miniruby 1 sh 2 ruby 8 ==== make install ==== sh 1 make 7
(私の常用shellであるbashがそれぞれ１回カウントされてましたが、結果からは除外しています)
configureで思いの他、gccが呼び出されているのには、ちょいとびっくりしましただ。 また、minirubyがけなげに活躍してますね。(親の)rubyが出来ちゃうと、ポィって 捨てられちゃう不憫な子なんですけどね。
こうして出来たdtrace入りrubyですが、FreeBSDでは残念ながらdtraceしてくれませんでした。 また、javaもdtraceしてくれませんでした。移植版と言ってもopensolaris のように、すらすらとはいかないんですね。
それじゃ最後に、FreeBSDでのdtrace関係者にお集まり頂きます。但し、都合により/sys 以下だけにしますね。
[sakae@cdr /sys]$ find . -name '*.c' | xargs grep -l DTRACE ./amd64/amd64/local_apic.c ./amd64/amd64/trap.c ./cddl/contrib/opensolaris/uts/common/dtrace/dtrace.c ./cddl/contrib/opensolaris/uts/common/dtrace/fasttrap.c ./cddl/contrib/opensolaris/uts/common/dtrace/lockstat.c ./cddl/contrib/opensolaris/uts/common/dtrace/profile.c ./cddl/contrib/opensolaris/uts/common/dtrace/sdt_subr.c ./cddl/contrib/opensolaris/uts/common/dtrace/systrace.c ./cddl/contrib/opensolaris/uts/common/fs/zfs/arc.c ./cddl/contrib/opensolaris/uts/common/fs/zfs/dsl_pool.c ./cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c ./cddl/contrib/opensolaris/uts/common/fs/zfs/zil.c ./cddl/dev/prototype.c ./cddl/dev/dtmalloc/dtmalloc.c ./cddl/dev/dtrace/dtrace_debug.c ./cddl/dev/dtrace/dtrace_ioctl.c ./cddl/dev/dtrace/dtrace_load.c ./cddl/dev/dtrace/dtrace_vtime.c ./cddl/dev/dtrace/amd64/dtrace_isa.c ./cddl/dev/dtrace/amd64/dtrace_subr.c ./cddl/dev/dtrace/i386/dtrace_isa.c ./cddl/dev/dtrace/i386/dtrace_subr.c ./cddl/dev/fbt/fbt.c ./cddl/dev/lockstat/lockstat.c ./cddl/dev/profile/profile.c ./cddl/dev/sdt/sdt.c ./cddl/dev/systrace/systrace.c ./contrib/ngatm/netnatm/msg/privmsg.c ./i386/i386/local_apic.c ./i386/i386/trap.c ./i386/isa/clock.c ./kern/kern_dtrace.c ./kern/kern_exec.c ./kern/kern_exit.c ./kern/kern_fork.c ./kern/kern_lock.c ./kern/kern_lockstat.c ./kern/kern_malloc.c ./kern/kern_mutex.c ./kern/kern_rmlock.c ./kern/kern_rwlock.c ./kern/kern_sdt.c ./kern/kern_sx.c ./kern/sched_4bsd.c ./kern/sched_ule.c ./kern/vfs_cache.c ./nfsclient/nfs_bio.c ./nfsclient/nfs_kdtrace.c ./nfsclient/nfs_krpc.c ./nfsclient/nfs_subs.c ./nfsclient/nfs_vnops.c ./pc98/cbus/clock.c
あれ、FreeBSDって、sparc等もサポートしてるんですが、まだ移植されて いないですね。誰か、sparcな石が入ったワークステーションを寄付して ください。そしたら、移植するよ。