profile
とある日、防寒対策を十分にして散歩をしていた所、遠方に犬の散歩をしてる人が認められた。 雪が降っても槍が降っても、散歩に連れて行ってあげないと、犬が可愛そう。女房は、この 一点で犬は飼いたくないと抜かす。ダイエットに効くと思うんだけどな。
で、その人が犬の糞を始末してる時、リードを放しちゃったものだから、さあ大変。犬は 喜びいさんで、その辺をかけづり回ってますよ。でも、その人（おばちゃんだった）の近くを ぐるぐるぐる。ちょっと遠くへ行ったかとかと思うと、また戻ってくる、なんてのの繰り返し。
おばちゃんは、犬が近くを通りかかった時、リードを踏んで犬を捕まえようとした。所が、 リードがソリみたいになって、哀れおばちゃんは、すってんころりん。起き上がれない様 だったので、救助に向かったよ。
ばつが悪そうに腕を押さえてた。取り合えず、腕を取って立たせてあげたよ。犬は近づいて きた時にリードを取ったら容易に捕まえられた。そして、おいらの顔をペロペロ。人懐こい ゴールデンレトルバー、4歳、メスでした。犬の身上は、おばちゃんが教えてくれたんだけどね。 他にも犬を飼っているけど、彼犬が一番、おてんばとか。そりゃそうだよなあ。伸び上がれば 、おいらの身長を超えてるぞ。
そして、数日後に、また散歩でそのおばちゃんに出合った。腕を三角帯で吊ってたぞ。 聞いてみると、夜になって腕が痛み出し、どうしようもなかったんで、遠方の救急病院へ 行ったとか。レントゲンを取ったら、幸い骨には異常が無かったとの事。でも動かすと 痛いので、固定してもらったそうな。
災難ですな。
gauche
前々回、pureで196の回文数をやった時、プロファイラーが無くて、職人芸的にホットスポットの 予想をつけて行った。この科学が発達してる現在、それじゃ余りに古風過ぎる。 例のHaskell本にもプロファイルの章が立てられているぐらいだから、プロファイルは今や 当たり前の事なんだろう。
だったら、pureはhaskellのお友達なんだから、haskellでプロファイリングしてみれば良いじゃんって なるけど、今回はちょっと目先を変えて、他の言語でやってみる。この所ご無沙汰してる gaucheなんてのは、どうだろう。プロファイラーなんて付いているのか？ 論よりman（infoだけど) したら、出てきた。
自分のスクリプトのスピードが十分に出ないというときには、 性能を改善するポイント として考えられる点がいくつかあります。 どんなときでも、実行時間を食いつぶしているコード部分を見つけるというの を先ず最初に やるのがよいでしょう。Gauche にはこの作業を補助する基本的 なツールが2つあります。 組込のサンプリングプロファイラ(これについては次 の節で説明します)を使えば各手続きで どれほどの時間がかかり、その手続き が何回呼ばれたかを表示できます。 gauche.time モジュール (gauche.time - 時間の計測) ではコードの中の特定の部分の実行に かかる時間を 測定するためのAPIが提供されています。
それより前に、pureのコードをgaucheに移植しておかんとな。
(use srfi-13)
(define (nx n)
(+ n (string->number (string-reverse (number->string n)))))
(define (cp n)
(string=? (number->string n) (string-reverse (number->string n))))
(define (ex n c)
(when (= 0 (mod c 100))
(print c " " (string-length (number->string n)))))
(define (go n c)
(if (or (cp n) (= c 10000))
(cons n c)
(begin (ex n c) (go (nx n) (+ c 1)))))
(define (mil n)
(go n 0))
(mil 196)
まんまの移植です。pureみたいな癖が無いので楽だった。ああ、string-reverseとかの stringに特化したのはSRFI-13に入っているのを知らなくて、最初自前で書いちゃったのは 内緒だ。gaucheはscheme界のpythonみたいに現場で鍛えられているから、欲しい物は 大概揃っているな。まずは、infoの目録を探してみるものだ。
実行は簡単。コマンドラインでプロファイルしてねって、お願いするだけだ。
[sakae@pcbsd ~/src]$ gosh -ptime mil.scm
:
Profiler statistics (total 15 samples, 0.15 seconds)
num time/ total
Name calls call(ms) samples
---------------------------------------------------+------+-------+-----------
number->string 30102 0.0037 11( 73%)
open-output-string 20001 0.0010 2( 13%)
compiled-code-finish-builder 76 0.1316 1( 7%)
inliner/- 27 0.3704 1( 7%)
string-pointer-prev! 41720210 0.0000 0( 0%)
integer? 20216 0.0000 0( 0%)
make-string-pointer 20001 0.0000 0( 0%)
:
10ms毎にプログラムに割り込んで、プロファイルを取っているとの事。よって手続きが 消費した時間は、あくまで傾向との事。それに対して、呼び出し回数はきちんとカウント してるそうだ。
はっきり、くっきりしましたなあ。数値を文字列に変換する部分で圧倒的に時間を喰って いる。
「論より run 」これがパフォーマンスチューニングの第一法則です。 Scheme のような高級言語では、何がパフォーマンスに強い影響を 与えるかはことのほか その実装に大きく依存し、ある処理系では とても安価な操作が別の処理系ではとても高価に なり得ます。 「ソースコードの2割が実行時間の8割を消費する」というのも古くから 言われています。 実際の実行時間に大した影響を及ぼさないところを 下手にいじくってプログラムをわかり づらくすることは避けましょう。
と、先輩からの貴重な助言。pureで勘を働かせて重いと思われる手続きを現金化(キャッシュの事ね) したのは正解だったね。ここでも、一般に言われる、時は金也 ってのが成り立っているよ。
ああ、プロファイルの中に、面白いのが出てた。
pass1 917 0.0000 0( 0%) pass2/lref-eliminate 716 0.0000 0( 0%) pass3/rec 687 0.0000 0( 0%) pass2/rec 606 0.0000 0( 0%) pass2/check-constant-asm 415 0.0000 0( 0%) pass3/$LREF 378 0.0000 0( 0%) pass2/$LREF 333 0.0000 0( 0%) pass4/scan/$LREF 315 0.0000 0( 0%) pass5/$LREF 294 0.0000 0( 0%)
これって、shiroさんCPUへのコンパイラーが働いているんだな。それはそうと、上記のCPUに 負荷をかけるコードは、計算の進度を表示するようになってた。このコードを取り除いて 、プロファイルすると、
Profiler statistics (total 756 samples, 7.5600000000000005 seconds)
num time/ total
Name calls call(ms) samples
---------------------------------------------------+------+-------+-----------
number->string 30002 0.2017 605( 80%)
string-reverse 20001 0.0435 87( 12%)
string-pointer-prev! 41720210 0.0000 32( 4%)
string->number 10000 0.0240 24( 3%)
open-output-string 20001 0.0025 5( 1%)
get-output-string 20001 0.0010 2( 0%)
nx 10000 0.0010 1( 0%)
もう、決定的に時間を喰っている所が明確になったわい。それじゃ、profileの外側にあるOS からはどのように見えているか？ 30分走らせた後のtopの結果
last pid: 4718; load averages: 1.10, 1.04, 0.90 up 0+01:46:32 11:03:42 43 processes: 2 running, 41 sleeping CPU: 99.6% user, 0.0% nice, 0.4% system, 0.0% interrupt, 0.0% idle Mem: 30M Active, 24M Inact, 90M Wired, 67M Buf, 589M Free Swap: 1024M Total, 1024M Free PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND 2185 sakae 1 103 0 15628K 8124K RUN 31:11 100.00% gosh 1599 root 2 52 10 40064K 6004K piperd 0:03 0.00% vmtoolsd :
pureはメモリーを湯水のように使って、swapまで使いきろうって勢いだったけど、goshは 慎ましいな。さすが、日本製ソフトじゃわい。昔からの日本人の美徳がしっかり息づいていますよ。 まあ、その代わり、計算は進んでいませんでしたけどね。
ついでなんで、pureのメモリー乗っ取り証拠を出しておきます。
last pid: 16287; load averages: 0.95, 0.91, 0.64 up 0+03:58:13 14:59:39 43 processes: 2 running, 41 sleeping CPU: 92.9% user, 0.0% nice, 5.9% system, 1.2% interrupt, 0.0% idle Mem: 538M Active, 61M Inact, 113M Wired, 21M Cache, 84M Buf Swap: 1024M Total, 454M Used, 569M Free, 44% Inuse, 1888K Out PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND 15121 sakae 1 102 0 1110M 591M RUN 14:31 100.00% pure :
こいういいちゃもんを付けてはいけません。gaucheの設計思想として、メモリーが貧弱な 環境（組み込み系とか）でも、そこそこ動くってのが有ったはず。rubyに対するmruby みたいなものか。
そうだ、rubyでプロファイル出来るか、この際だからやってみるか。
ruby
rubyでプロファイルってどうやるの？ 長年rubyにお世話になってたけど、使った事無かったなあ。 ぐぐったら、 library profile とか ruby debug なんてのが出てきた。 Rubyプログラミングを始めるための基礎知識とインストール には、紹介されるかなあ？ irbの紹介は有ったけどね。
で、種にするって言うか試供品のスクリプトを書かなければ。どう書くじゃないけど、 そのまま移植しちゃったら、StackOverflowを喰らいそうだな。命令的に書くか。 ずっと関数型で書いていたんで、脳が関数型言語にすっかり侵されてて、さっと出て こないぞ。困ったものだ。えっと、命令型ったら、変数に代入するように書けばいいんか。 それも有るけど、再帰は禁止を忘れちゃいけないよ。
def cp (n)
return true if n.to_s == n.to_s.reverse
return false
end
def nx (n)
n + n.to_s.reverse.to_i
end
def ex (n,c)
puts c.to_s + ' ' + n.to_s.size.to_s if c % 100 == 0
end
def mil (n)
c = 0
while (c <= 10000) do
return n,c if cp(n)
ex(n,c)
n = nx(n)
c += 1
end
end
mil 196
最後のmilを駆動する所が括弧無しになっちゃったけど、まあ、いいか。
[sakae@pcbsd ~/src/t]$ ruby -r profile mil.rb
:
% cumulative self self total
time seconds seconds calls ms/call ms/call name
56.16 12.90 12.90 10001 1.29 1.29 String#to_i
39.93 22.07 9.17 30052 0.31 0.31 Bignum#to_s
1.29 22.37 0.30 10001 0.03 0.63 Object#cp
0.99 22.59 0.23 10001 0.02 1.63 Object#nx
0.71 22.76 0.16 1 164.06 22968.75 Object#mil
0.24 22.81 0.05 10001 0.01 0.01 Object#ex
0.17 22.85 0.04 20002 0.00 0.00 String#reverse
:
全体の実行時間は、10000手で、47秒だった。pureの場合は39秒だったから、pureの勝ちって 事でいいですかね？ まてまて、OS対する迷惑度も評価しておけ。pureの場合は、形振り かまわずメモリー(とswap)を使いまくっていたからなあ。rubyの場合はいかに？
last pid: 50590; load averages: 1.00, 1.00, 0.86 up 0+02:05:54 08:25:40 43 processes: 1 running, 42 sleeping CPU: 98.8% user, 0.0% nice, 1.2% system, 0.0% interrupt, 0.0% idle Mem: 33M Active, 255M Inact, 112M Wired, 84M Buf, 333M Free Swap: 1024M Total, 1024M Free PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND 48148 sakae 2 21 0 19988K 13820K select 30:38 100.00% ruby
30分を経過したから、実行を打ち切った。まだまだ、swapに手を出す事は無さそう。rubyは やっぱり日本製とあって、慎ましいな。何もかもを暴力的に奪っていかないから。ちなみに、 この時点の進度は、37600手15629桁まで、試行してました。
ああ、どの時点でswapが働くか想像するに、上記のtopの結果に出てる、Wiredの112Mが 目安になるかな。この値はリアルメモリー中でOS領域等のswapしてもらっては困る領域を 示している。
dmesgで出て来る、avail memory = 764035072 (728 MB) から、Wiredの値を引いたものが、 ユーザーランド側で使えるメモリー。その中で、やりくりしてよって争奪戦になる訳だ。 ユーザーが余りにも無体なメモリー要求をすると、うざいユーザーって事で、神(OS)に殺される 運命が待っているんだな。皆の者、心せいって訳か。
chicken
親子丼である、chicken schemeでもプロファイル出来るかと思って調べたら、出来るって 回答だった。gaucheからソースを移植せんとな。移植はすぐに終わった。
(use numbers) (define mod modulo)
これを追加しただけ。ナンバーは、bigintをサポートする為。modは無かったので、あだ名を 付けてあげた。gaucheと親和性が高いのかな。
[sakae@fb10 ~/src/scm]$ csc -v -profile mil.scm /usr/local/bin/chicken mil.scm -output-file mil.c -verbose -profile cc mil.c -o mil.o -c -fno-strict-aliasing -fwrapv -DHAVE_CHICKEN_CONFIG_H -DC_ENABLE_PTABLES -O2 -pipe -fno-strict-aliasing -I"/usr/local/include/chicken" rm mil.c cc mil.o -o mil -L"/usr/local/lib" -Wl,-R"/usr/local/lib" -lchicken -lm -lpthread rm mil.o
プロファイルをやるときは、コンパイル時に指定する。-vで、コンパイル手順を列記させた けど、ccまでは、-profile相当が届いていない。と言う事は、chickenサイドで、プローブを 埋め込んでいるんだな。
[sakae@fb10 ~/src/scm]$ ./mil [sakae@fb10 ~/src/scm]$ chicken-profile PROFILE.2990 reading `PROFILE.2990' ... procedure calls seconds average percent ------------------------------------------- go 5001 54.869 0.010 100.000 mil 1 54.869 54.869 100.000 cp 5001 28.175 0.005 51.348 nx 5000 19.745 0.003 35.985 ex 5000 0.189 0.000 0.344
走らせると、プロファイルログが出来るので、それを引数に解析プログラムを呼び出す。 5000手を実行した結果だけど、分子成分の結果しか表示しないのね。これはこれで、有りだな。 どうせ分子レベルでしか、改良出来ないんだから。
[sakae@fb10 ~/src/scm]$ cat PROFILE.2990 (nx 5000 19745.0) (cp 5001 28175.0) (ex 5000 189.0) (go 5001 54870.0) (mil 1 54870.0)
scheme的だなあ。
python
rubyときたら、近頃はpythonって事で、pythonの事情を確認。
Python プロファイラー ってのは、勿論有りましたよ。そして更に更に、いろいろなその手のツールを調査した方が おられました。
その結果が、 Pythonコードのプロファイリング って事で、まとめてありました。
プロファイルも見える化が進んでいるんですなあ。さすが使う人が多いとツールもいろいろ 出てくるものだと感心しますよ。そのうちに、どれか試してみよっと。
他の言語、例えばsbclとかocamlとかjavaでも、プロファイル出来るの？ ここで挙げた言語って 、SD誌で取り上げられていた関数型言語ってくくりの記事からなんだけどね。
javaは(おいらに取っちゃ）どうでもいいんで調べなかったけど、sbclとかocamlには、ちゃんと プロファイラーが付属してるようでしたよ。
code
gaucheにしろrubyにしろ、数値を文字列にするのが重い。何故？そりゃ、割り算をしてるからだろう。 逆演算になる文字列を数値にするのは、掛け算が必要。どちらが大変かと言うと、そりゃ割り算 だわな。どうやって、数値を文字列に変換する？
gosh> (div-and-mod 123 10) 12 3
123を文字列にしたかったら、取り合えず、123を10で割る。余りの３が一の桁。商の12を再び10で割る。 余りの2は十の桁。。。こんな具合にやって行けば、文字列に直せる。（はず)
折角なので、schemeのコードと対面しとくか。
gosh> (disasm number->string)
Disassemble not applicable for #<subr number->string>
gosh> (disasm cp)
CLOSURE #<closure cp>
=== main_code (name=cp, code=0x852bdc8, size=17, const=4 stack=14):
args: #f
0 PRE-CALL(1) 5
2 LREF0-PUSH ; n
3 GREF-CALL(1) #<identifier user#number->string>; (number->string n)
5 PUSH-PRE-CALL(1) 14
7 PRE-CALL(1) 12
9 LREF0-PUSH ; n
10 GREF-CALL(1) #<identifier user#number->string>; (number->string n)
12 PUSH-GREF-CALL(1) #<identifier user#string-reverse>; (string-reverse (number->string n))
14 PUSH-GREF-TAIL-CALL(2) #<identifier user#string=?>; (string=? (number->string n) (string-rev ...
16 RET
number->stringは、残念ながらこれ以上分解出来ないって言われた。オイラーが定義したやつは shiroさんCPUのアセンブラーが見えるんだけどね。
しょうがない。これ以上分解出来ないというシステム作り付けのコードに分け入ってみるか。 これって、これ以上分解出来ないという原子核を分解して量子の世界へ入って行くようなものだな。 気分は量子物理学者かな。
[sakae@pcbsd ~/src/Gauche]$ grep 'number->string' `find . -type f` | lv : ./src/libnum.scm:(define-cproc number->string ./src/libobj.scm:(define-method x->string ((obj <number>)) (number->string obj)) ./src/number.c: and number->string operations. :
まずは、大枠で探してみます。そうするとそれっぽいのが引っかかってきました。で、libnum.scmを 見てみます。
(define-cproc number->string
(obj :optional (radix::<fixnum> 10) (use-upper? #f)) :fast-flonum :constant
(result (Scm_NumberToString obj radix
(?: (SCM_FALSEP use_upperP)
0
SCM_NUMBER_FORMAT_USE_UPPER))))
取り扱い説明書を見ると、ｎ進数に変換出来るよってのと10進以上の場合アルファベットを大文字指定 出来るよなんて事が説明してありました。よって、見てる所は、ここに間違いない。これって、 C語への中継してんだな。ご本尊様は、Scm_NumberToStringか。きっと、number.cに置いて あるのだろうな。
/* API */
ScmObj Scm_NumberToString(ScmObj obj, int radix, u_long flags)
{
ScmPort *p = SCM_PORT(Scm_MakeOutputStringPort(TRUE));
ScmNumberFormat fmt;
Scm_NumberFormatInit(&fmt);
fmt.flags = flags;
fmt.radix = radix;
Scm_PrintNumber(p, obj, &fmt);
return Scm_GetOutputString(p, 0);
}
玉ねぎの皮を剥くように、どんどん剥いて行きます。今度は、Scm_PrintNumberだな。 これを経由して、print_numberにたどり着いた。今の場合、bigintなので
} else if (SCM_BIGNUMP(obj)) {
ScmObj s = Scm_BignumToString(SCM_BIGNUM(obj), radix, use_upper);
Scm_Puts(SCM_STRING(s), port);
return SCM_STRING_BODY_LENGTH(SCM_STRING_BODY(s));
Scm_BignumToStringを探すと、舞台はbignum.cに移る。
ScmObj Scm_BignumToString(const ScmBignum *b, int radix, int use_upper)
{
static const char ltab[] = "0123456789abcdefghijklmnopqrstuvwxyz";
static const char utab[] = "0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ";
const char *tab = use_upper? utab : ltab;
ScmObj h = SCM_NIL, t = SCM_NIL;
if (radix < 2 || radix > 36)
Scm_Error("radix out of range: %d", radix);
ScmBignum *q = SCM_BIGNUM(Scm_BignumCopy(b));
for (;q->size > 0;) {
long rem = bignum_sdiv(q, radix);
SCM_ASSERT(rem >= 0 && rem < radix);
SCM_APPEND1(h, t, SCM_MAKE_CHAR(tab[rem]));
for (; q->values[q->size-1] == 0 && q->size > 0; q->size--)
;
}
if (q->sign < 0) SCM_APPEND1(h, t, SCM_MAKE_CHAR('-'));
return Scm_ListToString(Scm_ReverseX(h));
}
やっと、ここまで辿り付いたぞ。思った通りでしたね。 ただ一点、おいらの見込みと違った所があった。remをAPPENDしてる事。直接文字列に するんじゃなくてListにしといて、それをひっくり返してから文字列にしてる。 内部はあくまで、consセルで通す、そして最後の最後で要求された(文字列)に変換する。 これぞ正真正銘のLisp脳！！
ここで見たコードは、gitから 頂いてきたものだけど、libの中に、r7rs.scm なんてのが入っていて、着々と準備が 進んでいるようでした。
lisp
みんな、そろそろR7RSなんですかね？ おいらも便乗して、どんな風になってるか 見ておくか。ぐぐったら、 Picrinなんてのが出てきました。 誠意開発中らしいので、見守って生きたいと思います。 開発者の記録がブログで公開されてたぞ。見ておけ。
それまでは、SDで知った、emacs上のreplである、ielmでも試してみますかね。
*** Welcome to IELM *** Type (describe-mode) for help. ELISP> (require 'cl) cl ELISP> ((lambda (x) (* x x)) 12) 144
これが、ラムダ式から始める関数型プログラミングらしいです。
そして、eshellも便利。
Welcome to the Emacs shell ~ $ cd src/Gauche/ ~/src/Gauche $ ls AUTHORS README examples mkinstalldirs COPYING acinclude.m4 ext rpmfiles-common.txt ChangeLog aclocal.m4 framework.sh rpmfiles-encoding.txt DIST compile gc rpmfiles-gdbm.txt DIST_EXCLUDE config.guess install-sh src Gauche.spec config.rpath lib string HACKING config.sub libsrc test INSTALL.in configure.ac ltmain.sh winnt Makefile.in depcomp m4 wirebuildlibs NEWS doc missing
おまけ
おいらは関数脳になっちゃってたけど、一般の人は命令型脳に調教されているはず。 初めてコンピュータに触れた時に使ったのはBASICです（一体、何時の時代の事だ？）とか、 perlでしたとか、rubyでしたとかJSでしたとか、とか。
そんな人達を関数脳に洗脳するため、SDで特集をやってた訳だけど、同志に巡り合えなかった 不幸な人は、 LLerのための関数指向入門でもご覧になって 雰囲気を感じてください。
その後のJuliia
入れてから暫くたったので、最新に追いついておこうと思って、再コンパイルしてみたら
[sakae@manjaro julia]$ make make[2]: stat: /home/sakae/julia/usr/lib/libopenlibm.so: Too many levels of symbolic links cp: cannot stat '/home/sakae/julia/usr/lib/libopenlibm.so.0.1.0': Too many levels of symbolic links Makefile:45: recipe for target 'install' failed make[3]: *** [install] Error 1 Makefile:641: recipe for target '/home/sakae/julia/usr/lib/libopenlibm.so' failed make[2]: *** [/home/sakae/julia/usr/lib/libopenlibm.so] Error 2 Makefile:43: recipe for target 'julia-release' failed make[1]: *** [julia-release] Error 2 Makefile:32: recipe for target 'release' failed make: *** [release] Error 2
こんなエラーに見舞われたよ。リンクが深すぎるってそりや自分自身にリンクするって技でも 繰り出しているんですかね？ Schemeとかだと、こういうのを検出して文句を上手に言って くるけど、無骨なOSじゃそこまで親切な振る舞いはしてくれんのか。
[sakae@manjaro julia]$ rm usr/lib/libopenlibm.so
[sakae@manjaro julia]$ rm usr/lib/libopenlibm.so.0.1.0
[sakae@manjaro julia]$ make
CC src/jltypes.o
:
しょうがないので、該当者を抹殺してあげたよ。どうせDNAが有るんでcloneは簡単に作れるからね。 そうしておいてmakeしたら、何事も無かったようにコンパイルが継続したよ。
こういう事が有るんで、もしのも為にキャッシュとしてusr以下をtgzしときましょ。