dtrace
Goで覗くシステムプログラミングの世界 なんてのを見つけておいたので、ちまちまと読んでいる。１回目で、御多分に漏れず、環境を 作ってる。オイラーの嫌いなGUIバージョン。
そのインテリ何とかでdebuggerを使えるようにしてる。ソース見学が主目的なんで、かかせない。CUIな人はどうやるか？
ぐぐったら、 go言語のデバッガ（delveとgdb)とcore dumpが出てきた。 delveが定評があるようだ。
なんてを見つけて、これはもう入れる鹿。何処に入れるかな。debian様の所だな。golangから goを落としてきて、/my/goに突っ込んだ。MySQLのパクりです。PATHを通した後、
export GOROOT=/my/go export GOPATH=/home/sakae/godev
こんな設定を書いたよ。続いて、dlvって言う、go用のdebuggerを入れる。
[debian ~]$ cd godev/src/ [debian src]$ go get -u -v github.com/derekparker/delve/cmd/dlv [debian src]$ ls ../bin/ dlv
dlvは、/my/go/binの中へ移動しといた。
そして、CUIの開発環境、emacs用に、go-mode, go-dlvを入れる。 試運転。
M-x dlv RET
Run dlv (like this): dlv debug hello.go
=======================================================================
(dlv) b main.main:1
Breakpoint 1 set at 0x47b68f for main.main() ./hello.go:6
(dlv) c
> main.main() ./hello.go:6 (hits goroutine(1):1 total:1) (PC: 0x47b68f)
1: package main
2:
3: import "fmt"
4:
5: func main() {
=> 6: fmt.Println("Hello World")
7: }
8:
後は適当にsコマンドで潜って行って、履歴を辿ってみた。
(dlv) bt 0 0x00000000004330b0 in sync.runtime_procPin at /my/go/src/runtime/proc.go:4453 1 0x000000000045a712 in sync.(*Pool).pin at /my/go/src/sync/pool.go:174 2 0x000000000045a3ef in sync.(*Pool).Get at /my/go/src/sync/pool.go:121 3 0x0000000000474291 in fmt.newPrinter at /my/go/src/fmt/print.go:133 4 0x0000000000474686 in fmt.Fprintln at /my/go/src/fmt/print.go:246 5 0x00000000004747b7 in fmt.Println at /my/go/src/fmt/print.go:257 6 0x000000000047b737 in main.main at ./hello.go:6 7 0x0000000000427a6a in runtime.main at /my/go/src/runtime/proc.go:185 8 0x000000000044d391 in runtime.goexit at /my/go/src/runtime/asm_amd64.s:2197
FreeBSD, OpenBSD RAMDISK
今までないがしろにしてた FreeBSD 11.0 で、がしがしとコンパイルしたくなった。 （何故かは後述） 心配はSSDの劣化。そんな事はRAMDISK上でやればおｋ。どうやるか探してみる。頼みの綱はmanね。
[fb11: ~]$ man -k ramdisk apropos: /usr/local/man/mandoc.db: No such file or directory apropos: nothing appropriate
メンテナンスがされてませんなあ。うろ覚えでramdiskの材料になりそうな、 mdconfigを調べてみる。例が有った。起動のたびにやるのは面倒。まあ、起動スクリプトに 書いておけば済む話ですけど。
mdconfig -s 1g -u md10
newfs -U /dev/md10
mount /dev/md10 /tmp
chmod 1777 /tmp
Linuxに対抗してるBSD属なら、きっと、tmpfs なんてのが有るに違いないと思い立ち、man したらビンゴでした。以下、要約。
Alternatively, to load the driver as a module at boot time, place the
following line in loader.conf(5):
tmpfs_load="YES"
To mount a tmpfs memory file system:
mount -t tmpfs tmpfs /tmp
SEE ALSO
nmount(2), unmount(2), fstab(5), mdmfs(8), mount(8)
続いて、自動化って事で、fstabを見ておく。
# tmpfs.
tmpfs /tmp tmpfs rw,size=1g,mode=1777 0 0
#
# UFS file system on a swap-backed md(4). /dev/md10 is
# automatically created. If it is "md", a unit number
# will be automatically selected.
md10 /scratch mfs rw,-s1g 0 0
なんだ、ここにもmdconfig系の例が載ってたな。で、リナに合わせておけば管理が楽って事で tmpfsを採用しといた。
ついでに、OpenBSDではどうやるか調べてみた。tmpfsもmdconfigも無いというすっきりしたOS なんですねぇ。最後の頼みとfstabをmanしたら、ひっそりと例が出てた。
[ob: ~]$ cat /etc/fstab : swap /tmp mfs rw,nodev,nosuid,-s=2048000 0 0
これで無事に動いている。
[ob: ~]$ df -h Filesystem Size Used Avail Capacity Mounted on /dev/wd0a 15.3G 8.4G 6.1G 58% / mfs:27502 968M 167M 753M 18% /tmp
同じ塩梅でCentOSのそれを調べてみたけど、何も記述無し。唯一引っ掛かったのは、 ram(4)だけって不親切さ。だめじゃんLinux。もっとドキュメントを充実させてよ。
python with dtrace
Instrumenting CPython with DTrace and SystemTap なんてのを見つけたの。3.6バージョンから、dtraceが使えるそうだ。
dtraceったら、Solarisにみなもとを発し、FreeBSDが今は本場になってるね。 BSD界隈四方山話でも、dtraceの 話題でもちきりになってるからね。
そんなこんなので、FreeBSDでpython 3.6.1 を動かす、プロジェクト始動です。
configure に、--with-dtrace を付けて実行。続いて、make。
[fb11: Python-3.6.1]$ make
/usr/sbin/dtrace -o Include/pydtrace_probes.h -h -s
dtrace: option requires an argument -- s
Usage: dtrace [-32|-64] [-aACeFGhHlqSvVwZ] [-b bufsz] [-c cmd] [-D name[=def]]
[-I path] [-L path] [-o output] [-p pid] [-s script] [-U name]
[-x opt[=val]] [-X a|c|s|t]
:
訳の分からないエラーが出てきた。違、親切なメッセージによると、-s に続いて、スクリプトを 期待してるけど、来なかったって事ですな。これは、きっとMakefileがGUNに毒されているに 違いない。諦めて、gmakeしましょ。
Modules/symtablemodule.o Modules/xxsubtype.o -lutil -lm Python/ceval.o: In function `_PyEval_EvalFrameDefault': /tmp/Python-3.6.1/Python/ceval.c:1042: undefined reference to `__dtraceenabled_python___function__entry' Python/ceval.o: In function `dtrace_function_entry': /tmp/Python-3.6.1/Python/ceval.c:5451: undefined reference to `__dtrace_python___function__entry' Python/ceval.o: In function `_PyEval_EvalFrameDefault': /tmp/Python-3.6.1/Python/ceval.c:1166: undefined reference to `__dtraceenabled_python___line' : /tmp/Python-3.6.1/Modules/gcmodule.c:1078: undefined reference to `__dtrace_python___gc__done' cc: error: linker command failed with exit code 1 (use -v to see invocation) gmake: *** [Makefile:736: Programs/_freeze_importlib] Error 1
なんと言う事か。そんなの無いと言ってる。Makefileをちょっこりと覗いてみると、
DTRACE_OBJSがPYTHON_OBJSの一員に加わっているにも関わらず、定義されていなかったので、 下記のように追加した。
DTRACE= /usr/sbin/dtrace DFLAGS= DTRACE_HEADERS= Include/pydtrace_probes.h DTRACE_OBJS= Python/pydtrace.o
これで、ceval.cの方のエラーは消えたけど、gcの方は相変わらず残っている。しょうがないので、 泣く泣くgcの方は諦めた。
/tmp/Python-3.6.1/Modules/gcmodule.c:929: undefined reference to `__dtraceenabled_python___gc__start' /tmp/Python-3.6.1/Modules/gcmodule.c:930: undefined reference to `__dtrace_python___gc__start' /tmp/Python-3.6.1/Modules/gcmodule.c:1077: undefined reference to `__dtraceenabled_python___gc__done' /tmp/Python-3.6.1/Modules/gcmodule.c:1078: undefined reference to `__dtrace_python___gc__done'
尚、gccでコンパイルしないといけないかと思い、gcc-4.9.4_1を入れ
CC=gcc49 ./configre --with-dtrace
した環境でやってみたけど、同様なエラーだった。
取り合えず走らせておいて、どんなプローブが取れるか調べてみる。
[fb11: ~]$ sudo dtrace -l -m python3.6 ID PROVIDER MODULE FUNCTION NAME dtrace: failed to match :python3.6::: No probe matches description [fb11: ~]$ ps a PID TT STAT TIME COMMAND 20550 2 I+ 0:00.02 python3.6
完敗した。打つ手無し。
ruby with dtrace
pythonがダメでもrubyならどうだ？ 確かdtraceをサポートしてたはず。何もしなくても dtraceが組み込まれる仕様になってた。
ルビマに紹介が有ったぞ。
[fb11: ~]$ sudo dtrace -l -m ruby ID PROVIDER MODULE FUNCTION NAME 60544 ruby20577 ruby rb_ary_drop array-create 60545 ruby20577 ruby rb_ary_product array-create 60546 ruby20577 ruby rb_ary_repeated_combination array-create 60547 ruby20577 ruby rb_ary_repeated_permutation array-create : 60604 ruby20577 ruby dsymbol_alloc symbol-create
[fb11: tmp]$ cat t.rb
class Foo
def hello
end
def world
end
end
foo = Foo.new
100.times { foo.hello }
10000.times { foo.world }
[fb11: tmp]$ cat x.d
ruby$target:::method-entry
/copyinstr(arg2) == "t.rb"/
{
@[copyinstr(arg0), copyinstr(arg1)] = count();
}
[fb11: tmp]$ sudo dtrace -q -s x.d -c"ruby t.rb" Foo hello 100 Foo world 10000
[fb11: tmp]$ sudo dtrace -l -m ruby | cut -c 35-
FUNCTION NAME
rb_ary_drop array-create
rb_ary_product array-create
rb_ary_repeated_combination array-create
rb_ary_repeated_permutation array-create
rb_ary_combination array-create
rb_ary_permutation array-create
rb_ary_sample array-create
rb_ary_and array-create
rb_ary_diff array-create
rb_ary_times array-create
rb_ary_slice_bang array-create
rb_ary_reject array-create
empty_ary_alloc array-create
rb_ary_to_ary array-create
rb_ary_subseq array-create
rb_assoc_new array-create
rb_ary_new array-create
ary_new array-create
vm_call0_body cmethod-entry
vm_call_cfunc cmethod-entry
vm_exec_core cmethod-entry
vm_call0_body cmethod-return
vm_call_cfunc cmethod-return
vm_exec cmethod-return
rb_vm_pop_cfunc_frame cmethod-return
vm_exec_core cmethod-return
rb_require_internal find-require-entry
rb_require_internal find-require-return
gc_start gc-mark-begin
gc_start gc-mark-end
gc_sweep_step gc-sweep-begin
gc_sweep_step gc-sweep-end
m_core_hash_from_ary hash-create
vm_exec_core hash-create
empty_hash_alloc hash-create
rb_f_load load-entry
rb_f_load load-return
rb_clear_method_cache_by_class method-cache-clear
invoke_iseq_block_from_c method-entry
vm_exec_core method-entry
hook_before_rewind method-return
invoke_iseq_block_from_c method-return
vm_exec_core method-return
rb_obj_alloc object-create
yycompile0 parse-begin
yycompile0 parse-end
setup_exception raise
rb_require_internal require-entry
rb_require_internal require-return
rb_str_slice_bang string-create
rb_str_prepend_multi string-create
rb_str_concat_multi string-create
empty_str_alloc string-create
rb_str_ellipsize string-create
str_upto_each string-create
rb_str_concat_literals string-create
rb_str_resurrect string-create
str_new_static string-create
str_new0 string-create
register_static_symid_str symbol-create
dsymbol_alloc symbol-create
60個を超えるプローブが埋めてあるな。喜べpythonに勝ったよ。
超簡単なruby語を動かして、プローブしてみた。何故か、別プロセスとして、同じrubyが 動いていないと、データ取りが失敗する。
[fb11: tmp]$ cat x.d
ruby$target:::*
{
printf("%s", copyinstr(arg1));
}
実行
[fb11: tmp]$ sudo dtrace -s x.d -c "ruby -v" > LOG dtrace: script 'x.d' matched 61 probes dtrace: pid 7602 has exited
ログの記録
[fb11: tmp]$ head -n 5 LOG
ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-freebsd11.0]
CPU ID FUNCTION:NAME
1 60622 ary_new:array-create
1 60622 ary_new:array-create
1 60622 ary_new:array-create
[fb11: tmp]$ tail -n 5 LOG
1 60663 str_new0:string-create ruby
1 60664 register_static_symid_str:symbol-create ruby
1 60663 str_new0:string-create ruby
1 60663 str_new0:string-create ruby
[fb11: tmp]$ wc LOG
7058 22548 373395 LOG
ぐだぐだ、色々なやつが呼ばれてる。
python with stap
をやってみたけど、失敗。
Red Hat Enterprise Linux 7 SystemTap ビギナーズガイド
CentOS 6.6 に Systemtap をインストールして動かす
どうも、ユーザープロセスのものをプローブするには、stap-serverを動かせとか、 カーネルは特別なオプションが付いていないといけないとか、制限きつ過ぎ。
grep CONFIG_UTRACE /boot/config-`uname -r`
etc
from dtrace toolkit
FreeBSDのパッケージに、dtrace-toolkitなんてのが有り、インストールすると、これらは Solaris基準のものだから、注意してねって注意された。
動くのか、本場のやつを試してみた。システムコールの状況を報告してくれるやつっぽい。 どうやら、無変更で動いた、万歳！
[fb11: tmp]$ sudo ./py_syscalls.d -c "python3.6 rnd.py" Tracing... Hit Ctrl-C to end. pg~f+7EH.S Calls for PID 953, FILE TYPE NAME COUNT python3.6 syscall __getcwd 1 python3.6 syscall exit 1 python3.6 syscall fcntl 1 python3.6 syscall getegid 1 python3.6 syscall geteuid 1 python3.6 syscall getgid 1 python3.6 syscall getpid 1 python3.6 syscall getuid 1 python3.6 syscall sigaltstack 1 python3.6 syscall write 1 python3.6 syscall clock_gettime 2 python3.6 syscall readlink 2 python3.6 syscall access 3 python3.6 syscall dup 3 python3.6 syscall __sysctl 5 python3.6 syscall fstatfs 7 python3.6 syscall lstat 10 python3.6 syscall open 11 python3.6 syscall ioctl 13 python3.6 syscall getdirentries 15 python3.6 syscall munmap 15 python3.6 syscall sigaction 35 python3.6 syscall openat 42 python3.6 syscall mmap 43 python3.6 syscall lseek 47 python3.6 syscall close 54 python3.6 syscall sigprocmask 70 python3.6 syscall read 74 python3.6 syscall fstat 84 python3.6 syscall stat 184
と、叫ぶのは、時期尚早。わざわざpyって冠詞が付いているんだから、pythonっぽい情報も 同時収録するようになってる。が、上で見たように、既に諦めた部分は、どんなやつを 動かしてもだめでした。
[fb11: tmp]$ cat py_syscalls.d
#!/usr/sbin/dtrace -Zs
:
#pragma D option quiet
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
}
python$target:::function-entry
{
@calls[basename(copyinstr(arg0)), "func", copyinstr(arg1)] = count();
}
syscall:::entry
/pid == $target/
{
@calls[basename(execname), "syscall", probefunc] = count();
}
dtrace:::END
{
printf("\nCalls for PID %d,\n\n", $target);
printf(" %-32s %-10s %-22s %8s\n", "FILE", "TYPE", "NAME", "COUNT");
printa(" %-32s %-10s %-22s %@8d\n", @calls);
}
PIPE屋さん
pythonが動かずプチ悔しいので、得意のパイプ屋さんになって憂さ晴らししましょ。あのmatzさんもパイプ言語を 作るぐらいですから、みんな大好き。（なはず）
[fb11: tmp]$ truss python3.6 rnd.py | cut -d'(' -f1 | sort | uniq -c
:
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
exit(0x0)
process exit, rval = 0
1 pg~f+7EH.S
FreeBSDでは、straceの代わりにtrussがpkgを追加する事なく使える。で、普通に使ったら データがパイプを流れずに、裏街道のERR道を流れてきた。STDERRに流れるデータも、 パイプに押し込んでやる。
[fb11: tmp]$ truss python3.6 rnd.py |& cut -d'(' -f1 | sort | uniq -c
:
191 stat
3 sysarch
1 thr_self
1 write
DTRACEに合わせるように、最後に件数でソートした。
[fb11: tmp]$ truss python3.6 rnd.py |& cut -d'(' -f1 | sort | uniq -c | sort -n
:
65 mmap
77 sigprocmask
78 read
92 fstat
191 stat
FreeBSDには、まだ他に使えるツールが有る。そう、ktraceで情報収集出来るんだ。
[fb11: tmp]$ sudo ktrace -tc python3.6 rnd.py pg~f+7EH.S
ktrace.outって言う結果ファイルが出来るんで、kdumpを使って確認。
[fb11: tmp]$ sudo kdump : 1052 python3.6 CALL read(0x3,0x802a1b481,0x1) 1052 python3.6 RET read 0 1052 python3.6 CALL close(0x3) 1052 python3.6 RET close 0
後は、楽しいパイプ屋さん。
[fb11: tmp]$ sudo kdump|grep CALL|cut -d' ' -f7|cut -d'(' -f1|sort|uniq -c|sort -n
:
70 mmap
76 read
77 sigprocmask
90 fstat
184 stat
こんな事は、awkの出番だろうと言われるかも知れない。これぐらになると、どうしても スクリプトを書く必要が出てくるよな。面倒。パイプを少しずつ伸長してく方が楽でいいな。
まあ、パイプを信号が流れて、その間で信号が加工されていくって、電子回路そのもの じゃないですか。昔は得意だったから、その血が今も流れているんだろうね。
ラジオなら、同調回路、高周波増幅、周波数変換、狭帯域フィルター、中間周波数増幅、検波、低周波増幅 みたいに、信号が流れるからね。でもね、高1中2形式って、今の世の中では古すぎないかい。
次はおまけ。
dtrace-toolkitにruby版も提供されてた。そのままでは動かず、function-entryの所を、method-entryに変更 したら、上で取り上げたt.rbからデータを収集してくれたぞ。パイプを使って、使われているFILEを抜き出してみた。
[fb11: tmp]$ sudo ./rb_syscalls.d -c "ruby t.rb" | cut -d ' ' -f2|sort|uniq -c|sort -nr 52 specification.rb 37 ruby 16 rubygems.rb 12 basic_specification.rb 9 version.rb 9 requirement.rb 8 stub_specification.rb 8 defaults.rb 7 dependency.rb 6 platform.rb 5 monitor.rb 3 path_support.rb 2 t.rb 1 rbconfig.rb 1 kernel_require.rb 1 kernel_gem.rb
rubyはファイルじゃないけど、syscallの対象という分類になってた。 指定したスクリプト以外に、色々なスクリプトが裏で動いていて、面白いですよ。こういう 秘密のツールは、DHHのレールを世界に拡散するために発展したんだろうね。
あのこーいちさんは、くっくぱっどで大規模rubyに挑戦されてるとか。秘密の道具として こういうのを嫁入り道具にされたに違いない。
ああ、 「OpenBSD 6.1」リリース、arm64もサポート ゆっくりと、やって来たな。そのうちに入れてみるかな。