uftrace for erlang
東大の授業
前回見つけたgdbの上級コース。東大の大規模ソフトウェアを手探る って授業の資料の一部だった。CPU実験と称して、世界に一つしかないアーキテクチャのCPUを設計したりする授業が有ったりして、楽しい限りだ。これぞ大学の授業だよな。
uftrace を使ってプログラムの中身を解析 こんな面白い物が有るなんて、ちっとも知りませんでしたよ。
道具を与えて、大規模ソフトウェアを手探る(教科書) って例を示し、後は自分で課題を見つけてチェレンジしろ。
pthread
前回やった、数値積分でPIを求めるやつ、もう少し遊んでみる。
gnuplot> set xrange [0:1] gnuplot> plot 4 / (1 + x * x)
まずは、どんなグラフになるかだな。積分範囲が0から1の間ってんで、そのように指示。そして関数のグラフを書いてみる。x=0の時、yは4になった。x=1の時のyは2だ。なだらかな右下がりの曲線だ。この曲線の下側の面積がPIになるって事らしい。
ああ、gnuplotが気を効かせて、Y軸の範囲を2から4にオートスケールしちゃったけど、この場合の面積は、Yが0からの曲線の下側の面積ね。世には人を惑わすグラフが横行してるんで注意。
雑に面積を求めると。えいやってんで、台形と思っちゃえ。そうすると、台形が90度傾いているって事で。上辺が2下辺が4で高さ(X軸方向ね)が1と見做せるから、(上辺+下辺)/2 で計算出来る。答えは3だ。ゆとり教育の時代なら、PIの値は3ですよって答えれば、大変良くできましたって事になるだろう。
台形じゃなくて、長方形と見做してみたらどうだろう。x=0.5の時の高さyを求めると(カーソルを動かすと、右下に数値が出て来るので、それを読み取る)3.19ぐらいになった(真値は、4/(1 + 0.5 * 0.5))。そう、昔のエジプト人並みの精度だな。ゆとり教育より進んでるぞ。
これを発展させて、コンピューターに計算させたのが前回のやつだ。縦に切り刻んで短冊を作りそれを合計するって方法ね。4つのコンピュータを使って、手分けして面積を求めるって方法。
下記は、4つに分割(ってか、4とおきに)した合計値を求めるように、calcにちょっと手をいれてみた。
pthread_mutex_lock(&gl); printf("%d %.20g\n", myN, pH * lw); gA += pH * lw; pthread_mutex_unlock(&gl);
そして、その結果か下記だ。
sakae@pen:/tmp$ ./a.out 2 0.7853981633982218824 3 0.78539816338932788575 1 0.78539816340669998951 0 0.78539816439833010087 PI = 3.1415926545925803026 sakae@pen:/tmp$ ./a.out 1 0.78539816340669998951 2 0.7853981633982218824 0 0.78539816439833010087 3 0.78539816338932788575 PI = 3.1415926545925794144
実行の度にスレッドの順番が変わっている。どういう順番になるかは神のみが知るって言う不確かな世界だ。ここに難しさが有るんだな。
again banner
前前回だかにやったバナーの件。どうもダイナミックに設定されてる。それで少し追ってみた。 起動してる所で止めて、変数を確認。
(gdb) p erts_system_version $1 = "Erlang/OTP 23%s [erts-11.2] [source] [64-bit] [smp:%beu:%beu] [ds:%beu:%b\ eu:%beu] [async-threads:%d] [hipe]\n"
呼んでる所
erts_print_system_version(fmtfn_t to, void *arg, Process *c_p) { : erts_schedulers_state(&total, &online, &active, &dirty_cpu, &dirty_cpu_onln, NULL, &dirty_io, NULL); : return erts_print(to, arg, erts_system_version, rc_str , total, online , dirty_cpu, dirty_cpu_onln, dirty_io , erts_async_max_threads );
色々試したら、erlの中からも確認出来る方法を見つけた。
5> erlang:system_info(system_version). "Erlang/OTP 23 [erts-11.2] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe]\n"
追っていこうとしたら
[New thread 213939] [Switching to thread 616396] (gdb) c Continuing. Thread 2 received signal SIGSTOP, Stopped (signal). [Switching to thread 364622] (gdb) c Continuing. Thread 3 received signal SIGSTOP, Stopped (signal). [Switching to thread 226134]
このようにSIGSTOPで止められる事しきり。
(gdb) info handle Signal Stop Print Pass to program Description : SIGSTOP Yes Yes Yes Stopped (signal)
SIGNALが発生した時gdbはどうふるまうかのテーブルが用意されてる。 そして、それを変更出来るとな。 シグナル
(gdb) handle SIGSTOP nostop noprint Signal Stop Print Pass to program Description SIGSTOP No No Yes Stopped (signal)
これで一々止められる事が無くなった。
(gdb) c Continuing. Thread 5 hit Breakpoint 3, erts_printf_format (fn=0x16bcfaf0 <erts_write_ds>, a\ rg=0x58c40068, fmt=0x3694802d <erts_system_version> "Erlang/OTP 21%s [erts-10.2\ ] [source] [smp:%beu:%beu] [ds:%beu:%beu:%beu] [async-threads:%d]\n", ap=0x6b8c\ 48e8 "y#\233\026\001") at common/erl_printf_format.c:466
app
Erlang Programming に面白い例が出ていた。さんざやった数値積分だ。例を引用させて頂く。
midpoint(M, M, W, A) -> A * W; midpoint(N, M, W, A) -> X = (N + 0.5) * W, midpoint(N + 1, M, W, A + 4.0 / (1.0 + X * X)). midpoint(N) -> midpoint(0, N, 1.0 / N, 0.0).
Nは分割数、Wは小区間の幅、Aは面積。Mは分割数まで達したかの確認用だ。
1> c(para). {ok,para} 2> para:midpoint(1). 3.2 3> para:midpoint(2). 3.1623529411764704 4> para:midpoint(4). 3.1468005183939427 5> para:midpoint(8). 3.142894729591689 6> para:midpoint(100). 3.1416009869231254
trace / debug
ReconTrace で Erlang VM のトレース機能に親しむ
1> c(para). {ok,para} 2> c(recon_trace). {ok,recon_trace} 3> recon_trace:calls({para, '_', '_'}, {100,100}). 9 4> para:midpoint(2). 3.1623529411764704 15:58:26.860188 <0.76.0> para:midpoint(2) 15:58:26.867012 <0.76.0> para:midpoint(0, 2, 0.5, 0.0) 15:58:26.868409 <0.76.0> para:midpoint(1, 2, 0.5, 3.764705882352941) 15:58:26.872357 <0.76.0> para:midpoint(2, 2, 0.5, 6.324705882352941)
recon_trace
のscopeがデフォではglobalになってたけど、それでは使い難いのでlocalに変更しておいた。
erlの機能だけでやるなら、Erlangでのトレースとdbgの使用 を参考にする。
1> c(para). {ok,para} 2> dbg:start(). {ok,<0.83.0>} 4> dbg:tracer(). {ok,<0.83.0>} 6> dbg:tpl(para, '_', '_', []). {ok,[{matched,nonode@nohost,9}]} 7> dbg:p(all, c). {ok,[{matched,nonode@nohost,39}]} 8> 8> para:midpoint(4). (<0.85.0>) call para:midpoint(4) (<0.85.0>) call para:midpoint(0,4,0.25,0.0) (<0.85.0>) call para:midpoint(1,4,0.25,3.9384615384615387) (<0.85.0>) call para:midpoint(2,4,0.25,7.445310853530032) (<0.85.0>) call para:midpoint(3,4,0.25,10.321715347912054) (<0.85.0>) call para:midpoint(4,4,0.25,12.58720207357577) 3.1468005183939427
emacs
emacsはするめいかのように、噛めば噛む程美味しくなる。んで、使い難さを解消する技を見つけてみる。
BPをセット出来ないんですけど
emacs -f gdb してgdbのセッションに入った時、C-x SPACE で、BPを張れる事になっている。が、オイラーの所でそれをやると、mini-bufferに、Mark set (rectangle mode) ってなってしまい、BBを置けないんだ。
試しに、C-h k C-x SPACE すると、
C-x SPC runs the command rectangle-mark-mode (found in global-map), which is an interactive autoloaded compiled Lisp function in ‘rect.el’. :
こんな説明が出てきた。ちなみに、テンポラリィーなBPを置くキーシーケンスは。
C-x C-a C-t runs the command gud-tbreak (found in global-map), which is an interactive compiled Lisp function. It is bound to <menu-bar> <debug> <tbreak>, C-x C-a C-t. (gud-tbreak ARG) Set temporary breakpoint at current line.
こんな説明が出てくるし、ちゃんとgdbにセットされる。はて、どうしたものか?
Debugger:run のWindowで、C-h m したら、C-c C-b が有るよと言われて、それを見たら
C-c C-b runs the command gud-break (found in gud-mode-map), which is an interactive compiled Lisp function. It is bound to <menu-bar> <debug> <break>, C-c C-b, C-x C-a C-b. (gud-break ARG)
詳しい事はgud.elを見ろとな。
(defcustom gud-key-prefix "\C-x\C-a" "Prefix of all GUD commands valid in C buffers." :type 'key-sequence :group 'gud) : (gud-def gud-break "break %f:%l" "\C-b" "Set breakpoint at current line.") (gud-def gud-tbreak "tbreak %f:%l" "\C-t" "Set temporary breakpoint at current line.")
最近の仕様変更かな?
対応するカッコへ飛んでけ
lisp/scheme の上なら、そんなの簡単なんだけど、C語の上だと大変。ええ、コードを読んでた時、長い if (..) { … } に出会ったのさ。問題は 中カッコの方。最初そういう区別をしないで、ggしたら、 C-M-n C-M-p こんなのばかりが引っかかってきて往生したよ。
やりたい事は、viの%コマンド相当。viなら { の所にカーソルを置いて、% を叩くと、対応する } の所へ飛んでくれる。ggで検索してみたけど、これを紹介してる人はいなかった。ひょっとしてvimには無いから紹介しようが無いのかな。オイラーはviと言いつつvimだったりするデストリは大嫌いです。
で、M-x viper-mode する。初回起動時には、初心者モードにするとか聴かれるので、恒久的に最高クラスを選んだ。多分 % なんて、知ってる人しか知らない隠れ機能みたいなものだから。
一度viモードになったら、M-x toggle-viper-mode で、自由にvi/emacs間を行き来出来るよ。 viモードになってる時は、ステータスラインに <V> ってのが慎ましく出てる。それから、mini-bufferでの入力時に色合いが違うので、間違う事は無いだろう。
debian:~$ cat .emacs.d/viper (setq viper-inhibit-startup-message 't) (setq viper-expert-level '5)
設定情報は、こんな所に置いてあるので、自由に変更可能。過去には vi vs. emacs の戦争があったけど、emacsの広い心で、これで安心だ。
process
erlangのプロセスについて少々。
3> i(). Pid Initial Call Heap Reds Msgs Registered Current Function Stack <0.0.0> erl_init:start/2 376 2028 0 init init:loop/1 3 : <0.46.0> application_master:init/4 376 45 0 application_master:main_loop/2 8
ビローンと横に長い出力なんで、unix風に言うと ps awxl ぐらいかな。で、これがまたunix風に言うと、pid 1 に相当するのかな。applicationmasterのソースは何処よ? ガサ入れしてみる。
debian:otp_src_23.3$ grep -Irl application_master . : ./lib/kernel/doc/xml/kernel_app.xml ./lib/kernel/src/application_master.erl
しっかりコメントが入ったソースで、400行ぐらいだった。少し読んでみるかな。
uftrace for erlang
冒頭の東大授業のページを見ていたら、uftraceなんて言う(Linuxでしか動かないアプリ)が紹介されてた。今やっているerlangはOSだから、これを適用したら、起動時からのログが苦労なく入手出来るのではなかろうか。
OSと言えばその仕組みの勉強の為xv6なんて言うMIT提供のキットをやってみた事が有った。でも、それに飽き足らず、本物のOSであるOpenBSDをboot時から追えるようにした。qemuにOpenBSDを入れておき、gdbとqemuのタイアップで追うという方法。
qemu上のOpenBSDが立ち上がるのが少々遅い事を我慢すれば、ちゃんと使えて面白い。リナみたいに、kernelのdebug準備だとか言って構える必要も無いので、東大生にもやってみて欲しい所だ。
話を戻して、まずは-pg付きのerlangを作るのだな。
debian:otp_src_23.3$ CFLAGS=" -O0 -pg" ./configure --prefix=/home/sakae/MINE --without-wx
最初、CFLAGS=" -pg" だけでconfigureしたんだ。そしたらCFLAGSには、-O を必ず付けてくださいって注意されたよ。そんなものなのか。
make[4]: Entering directory '/home/sakae/MINE/otp_src_23.3/erts/lib_src' GEN obj/i686-pc-linux-gnu/opt/depend.mk CC /home/sakae/MINE/otp_src_23.3/erts/lib_src/yielding_c_fun/i686-pc-linux-gnu/simple_c_gc.o gcc: error: -pg and -fomit-frame-pointer are incompatible
へぇー、両立しないオプションなんだ。そんな事教科書に書いてなかったぞ。まあ、それが現実よ。
debian:otp_src_23.3$ find -name Makefile | xargs grep -l fomit ./erts/lib_src/i686-pc-linux-gnu/Makefile ./erts/emulator/i686-pc-linux-gnu/Makefile ./lib/wx/c_src/Makefile
動かすのが先決なので直接Makefileを編集すると言う暴挙に出て見る。まずは被害エリアの調査だな。幸いな事に、編集すべきMakefileは2つだ。wxは使わないって事にしたんだけど、何故か、それ用にMakefileが出来上がっている。
ifeq ($(CC)-$(OMIT_FP), gcc-true) CFLAGS += -fomit-frame-pointer endif
ちゃんとconfigure –help すればomitオプションをomit出来るオプションが見つかっただろうんいね。そんなの後の祭りって事にしておこう。多分一期一会でしょうからね。
debian:~$ MINE/bin/erl Erlang/OTP 23 [erts-11.2] [source] [smp:1:1] [ds:1:1:10] [async-threads:1] [hipe] Eshell V11.2 (abort with ^G) 1> q(). ok 2> debian:~$
まずは成果物がちゃんと動くか確認する。これ、基本だからね。こういう所は絶対に手をぬくな。近頃の日本の技術者は劣化してると思うぞ。基本の励行だ。
debian:~$ cd MINE/lib/erlang/erts-11.2/bin/ debian:bin$ export BINDIR=`pwd` debian:bin$ ./erlexec Erlang/OTP 23 [erts-11.2] [source] [smp:1:1] [ds:1:1:10] [async-threads:1] [hipe]
erlを起動するshellスクリプトをすっ飛ばして、直接erlanOSをbootしてみる。これ基本励行のその2だ。どうやら、このフェーズも合格。
最後は、お楽しみの本番実行だ。
debian:bin$ uftrace record ./erlexec mcount: /home/sakae/src/uftrace/libmcount/misc.c:103:uftrace_send_message ERROR: writing shmem name to pipe: Bad file descriptor erl_child_setup closed Crash dump is being written to: erl_crash.dump...done
事故発生。事故発生。早速、事故原因調査委員会設置。まて、事故は会議室で起こっているんじゃありません。現場で起こっているんです。で、現場検証firstですよ。
こういう場合、推測してバイアスをかけてしまうのは、もっての他です。でも、元技術者のはしくれで、ついつい想像しちゃうんだよな。
管制塔との交信記録だと、uftraceが根を上げた。その巻き添えを喰って、erlangが落ちたとな。erlangが動くためのパイプ通信が詰まってしまった。雑な言い方をすると、血管が詰まってしまって、脳卒中にでもなったって事かな。
debian:bin$ ls uftrace.data/ 13691.dat 13710.dat erlexec.sym libm-2.28.so.sym 13693.dat 13711.dat info libpthread-2.28.so.sym 13698.dat 13712.dat ld-2.28.so.sym librt-2.28.so.sym 13699.dat 13713.dat libbz2.so.1.0.4.sym libtinfo.so.6.1.sym 13700.dat 13714.dat libc-2.28.so.sym libutil-2.28.so.sym 13704.dat 13715.dat libcapstone.so.3.sym libz.so.1.2.11.sym 13705.dat 13716.dat libdl-2.28.so.sym sid-0e7e11d4d0be12ca.map 13706.dat 13717.dat libdw-0.176.so.sym sid-200785a376217813.map 13707.dat beam.smp.sym libelf-0.176.so.sym sid-9532c1547ea39a02.map 13708.dat default.opts libgcc_s.so.1.sym task.txt 13709.dat erl_child_setup.sym liblzma.so.5.2.4.sym
ボイスレコーダーならぬ、uftraceの記録が有るんで、検証。 まて、その前にuftraceの公式記録を確認しておくか。
debian:bin$ uftrace info # system information # ================== # program version : v0.9.4-245-g4c442 ( i386 dwarf python luajit tui perf sc # recorded on : Fri May 21 06:00:28 2021 # cmdline : uftrace record ./erlexec # cpu info : Intel(R) Celeron(R) CPU 900 @ 2.20GHz # number of cpus : 1 / 1 (online / possible) # memory info : 0.2 / 2.7 GB (free / total) # system load : 1.09 / 0.38 / 0.40 (1 / 5 / 15 min) # kernel version : Linux 4.19.0-16-686 # hostname : debian # distro : "Debian GNU/Linux 10 (buster)" # # process information # =================== # number of tasks : 19 # task list : 13691(beam.smp), 13693(beam.smp), 13698(beam.smp), 13699 # exe image : /home/sakae/MINE/lib/erlang/erts-11.2/bin/erlexec # build id : 27f35a8426c779891e1df0db92c81a81f041e270 # pattern : regex # exit status : exited with code: 1 # elapsed time : 42.894554711 sec # cpu time : 34.905 / 5.904 sec (sys / user) # context switch : 437 / 21309 (voluntary / involuntary) # max rss : 21936 KB # page fault : 3 / 7818 (major / minor) # disk iops : 712 / 816 (read / write)
次は、ボイスレコーダーの中身の検証。人間が読んで参考になりそうなやつ。
debian:uftrace.data$ cat task.txt SESS timestamp=4177.539279697 pid=13691 sid=200785a376217813 exename="/home/sakae/MINE/lib/erlang/erts-11.2/bin/erlexec" TASK timestamp=4177.539504649 tid=13691 pid=13691 SESS timestamp=4177.551406610 pid=13691 sid=0e7e11d4d0be12ca exename="/home/sakae/MINE/lib/erlang/erts-11.2/bin/beam.smp" TASK timestamp=4177.551614731 tid=13691 pid=13691 TASK timestamp=4177.638808873 tid=13693 pid=13691 TASK timestamp=4182.609856863 tid=13698 pid=13691 TASK timestamp=4182.896699261 tid=13699 pid=13691 FORK timestamp=4184.146091194 pid=13700 ppid=13691 SESS timestamp=4184.154620821 pid=13700 sid=9532c1547ea39a02 exename="/home/sakae/MINE/lib/erlang/erts-11.2/bin/erl_child_setup" TASK timestamp=4184.156299132 tid=13700 pid=13700 TASK timestamp=4186.733596120 tid=13704 pid=13691 TASK timestamp=4186.735374861 tid=13705 pid=13691 TASK timestamp=4186.737899555 tid=13706 pid=13691 TASK timestamp=4186.741189621 tid=13707 pid=13691 :
erlexec -> beam.smp -> erl_child_setup
と言う具合に動いてるんだな。何か、虎は死して皮を残す って、語句が浮かんできたわい(と、負け惜しみの嘆き節)。
sid-xxxxxx.map なんてのも見るべき点が無いしね。
まて、もう少し公式記録が有るぞ
debian:bin$ uftrace report Total time Self time Calls Function ========== ========== ========== ==================== 2.008 m 221.952 us 17 thr_wrapper 1.003 m 93.267 ms 1189 erts_schedule 45.584 s 13.494 ms 427 scheduler_wait 45.279 s 3.145 ms 11 erts_dirty_process_main 44.197 s 162.371 us 10 sched_dirty_io_thread_func 36.506 s 3.660 ms 334 erts_check_io 36.285 s 208.522 ms 334 check_fd_events 33.661 s 111.386 ms 2 process_main 33.646 s 39.949 us 1 sched_thread_func 30.041 s 161.398 us 2 main 23.259 s 23.259 s 137 syscall 23.197 s 899.478 us 81 wait__ 22.998 s 92.120 us 34 erts_tse_twait :
結果表示まで随分待たされました。その点、下記は垂れ流しなんで、直ぐに表示を初めてくれます。
debian:bin$ uftrace replay # DURATION TID FUNCTION [ 13691] | main() { [ 13691] | get_env() { 7.472 us [ 13691] | getenv(); 15.923 us [ 13691] | } /* get_env */ 1.466 us [ 13691] | free_env_val(); [ 13691] | initial_argv_massage() { :
それはいいんだけど、ページをめくっていくのがめんどくさい。ユーザーが必要ならlessとかを挟むから、余計なお節介は、せんといて(と、あけすけな大阪のおばちゃん風)。
ああ、文句を言う前に、何はなくともmanしろと。–no-pager こんなオプションが有った。どちらをデフォにするかは、作者さんの気持ち一つですよ。
debian:bin$ uftrace --no-pager replay >ZLOg debian:bin$ wc ZLOg 21448464 144944661 1439997556 ZLOg
何と1.4Gのログになりましたよ。とんでもない記録だな。折角なので、最後の方の記録を公開しとくね。
15.317 s [ 13704] | } /* erl_crash_dump_v */ [ 13704] | erts_exit_epilogue() { [ 13704] | sys_tty_reset() { 2.864 us [ 13704] | fcntl64(); 1.955 us [ 13704] | fcntl64(); 9.917 us [ 13704] | } /* sys_tty_reset */ uftrace stopped tracing with remaining functions ================================================ task: 13691 [2] erts_sys_main_thread [1] erl_start [0] main task: 13693 [1] signal_dispatcher_thread_func [0] thr_wrapper :
おまけで、reportの結果を元に、呼び出し回数でsortしてみた。
debian:bin$ sort -nr -k 5 ZRport.log | head 2.417 s 2.417 s 1488319 ethr_native_atomic32_read 4.235 s 2.952 s 837815 ethr_atomic_read 5.760 s 2.225 s 720896 erts_ptab_pix2intptr_nob 991.284 ms 991.284 ms 678105 ethr_native_atomic32_set 1.035 s 1.035 s 623237 ethr_cfence__ 4.841 s 3.038 s 552203 ethr_atomic32_read_acqb 5.821 s 1.606 s 524288 erts_pix2proc 2.037 s 1.407 s 407483 printf_putc 624.984 ms 624.984 ms 407402 putc_unlocked 1.622 s 1.121 s 342425 ethr_atomic_set
ここまでは、苦労なくやってこれた。後は発展系で、uftraceしたい所だけを制御するって方法が開示されてた。 uftrace を使ってプログラムの中身を解析/リバースエンジニアリングする (2) gnumericへ適用編
今度はこれを試してみるかな。長くなってきたので、一端筆を置く。
debian:bin$ file erl_crash.dump erl_crash.dump: ASCII text, with very long lines debian:bin$ lv erl_crash.dump
erlangの断末魔であるクラッシュダンプも見ておくか。これはこれで、面白いな。
debian:bin$ grep '^=' erl_crash.dump =erl_crash_dump:0.5 =scheduler:1 =dirty_cpu_scheduler:2 =dirty_cpu_run_queue =dirty_io_scheduler:3 : =dirty_io_run_queue =memory =hash_table:atom_tab =index_table:atom_tab : =allocated_areas =allocator:sys_alloc =allocator:temp_alloc[0] : =proc:<0.0.0> =proc:<0.1.0> =proc:<0.2.0> : =loaded_modules =mod:erts_code_purger =mod:erl_init =mod:init =mod:prim_buffer : =literals =atoms =end
これを見ると、内部がどうなってるか知る手がかりになるな。こういうのを不幸中の幸いって言うんだな。