psyntax.pp の Hello, World を高速化しようその1

scheme mosh

ここ数日 Hello, World の高速化のためにプロファイラの精度を上げるべく作業をしていた。
無名の closure でもソースコード上の位置が記録されたりとかまあいろいろがんばりました。

time%        msec      calls   name                              location
  27         3600        190   (<proc> x y)                      compiler-with-library.scm:8437
   8         1150     143356   (<proc> i)
   8         1070       4039   (pass3/$lambda iform loca...)     compiler-with-library.scm:9192
   5          700          -   (<top-level>)
   4          550       8456   (pass3/$call iform locals...)     compiler-with-library.scm:9043
   3          500     197791   (<proc> s)                        compiler-with-library.scm:9661

以下作業ログ。

  1. おおざっぱにコメントアウトを２分法で行ったところ遅いところが判明。
  2. psyntax.pp の (begin (define g$120$23359 '#f) から始まるブロックが遅い。
  3. コンパイル自体が遅いのが理由ではないことが分かったのでログで (sys-gettimeofday) を挟んで２分法でさらに絞り込もうと思う。
  4. いらない部分をそぎ落とした psyntax-mosh.pp.1 32秒
  5. コードをみやすくするために set! を置換して改行を入れる 32秒
  6. コードが 600 行あるので 3 箇所にログを入れてみる。
  7. 何も実行していない段階で一つ前のブロックから32秒も経っている。これはコンパイルが遅いことを意味するのだろうか。
  8. たぶんコンパイルが遅いのだが念のためログをとってみる。
  9. compile =32196 eval = 0 ビンゴです。
  10. コンパイルするようなコードを書こう。 psyntax.compile
  11. これの実行には 18秒。
  12. lambda の body を空にしてみる。これが理論限界。
  13. 0 sec
  14. -p でプロファイラを実行
time%        msec      calls   name
   8         1770    1636539   set-cons
   1          310    1644841   set-union
   1          230     618504   $map1
   0           10       4151   pass3/find-sets
  1. 確かにコンパイラ内で遅い。ただ総実行時間が18秒なのにどこに行った？
  2. まずはプロファイラを疑おう。簡単なスクリプトを書いて確かめる。
  3. set-cons を 1636539 回呼ぶ。
  4. (set-cons 1 '()) 0.8sec
  5. (set-cons 'a '(1 2)) 0.75sec
  6. リスト長4 => 0.74
  7. リスト長8 => 0.78
  8. リスト長16 => 0.94
  9. リスト長32 => 1.482
  10. リスト長64 => 1.732
  11. リスト長128 => 3.009
  12. リスト長256 => 5.251
  13. これだな。考えなければいけないこと
    1. set-cons を呼ぶ回数を減らせないか。そもそも呼ぶ必要があるのか。
      1. これが一番手だな。
    2. C++で書いたらもっと速くなるよね。
    3. Gauche でも set-cons 測定したら？（ある程度の限界値が見えるはず）
      1. Gauche は4倍速かった。
  14. set-cons はどこから呼び出されているか。
    1. set-union からのみ呼ばれている。これは internal define にすべきだな。
  15. set-union はどこからよばれる？
    1. pass3/$call
    2. pass3/$lambda
    3. pass3/$receive
    4. pass3/$let
    5. pass3/$letrec
  16. pass3/$lambda で今回は呼ばれまくっている。
    1. 引数のメモ化は使えないか
    2. どういう文脈で使われているか。少しでも回数を減らせないか。
    3. find/free で can-frees が使われている。
    4. set-cons/ set-union は1回の呼び出しで指数的に呼び出しが増える。
  17. 本当に set-cons が遅いのか怪しくなってきた。
  18. vmcpp のコンパイラだけ変更したい。
  19. cond-expand を実装しよう。
  20. pass3/$lambda の set-cons/set-union を '() で置き換える。
  21. 実行時間にほぼ変化なし。つまり間違っていたと。
  22. -p でも詳しい情報得られず。
  23. さてここで問題はなんだろうか？
    1. コンパイラが遅いことが分かっているのにプロファイラがそれを検知できていないことだ。
  24. 匿名クロージャもプロファイル対象にしよう。
  25. シグナルハンドラが stop しても動いているような気がする。
  26. プロファイラで合計を出すところで hashtable->alist が C のスタックオーバーフローを起こしている。
  27. これは map 内で使われている apply がC的に再帰しているからだ。これを改める方法は分かっている。
  28. いろいろたまってきたので整理しよう
    1. 結果に nil が含まれる件を修正する
    2. applyが再帰している件
    3. プロファイラを整形して動かす。
      1. 無名クロージャのソースを表示する
      2. コンパイラのどこかでソース情報が失われているので調べる。
      3. source-info の形式どうする？(name file . line)
      4. プリコンパイル済みのコードもソースコード情報を。
        1. set-source-info 相当が Gauche にあるか？。それが問題。
      5. make-closure-source-info
      6. ChangeLog ソースの所在を明らかに。
      7. source-info がとれているかもきちんと見る。
  29. 帰ったらやること。
    1. Gauche でソース情報がうめ込めるか？
      1. まずは library.scm でエラーを起こしてソースコード情報が表示されるかをチェック。
      2. 表示されるようであれば OK 。だめなら探る。
      3. だめだった。つまり。
    2. □compiler-with-library で prittey printer を使おう
    3. フルパスやめようぜ。
    4. ■←applyの再帰版を作る。 rev 119
    5. プロファイラに含まれていない手続きがあるね。
    6. あ。。。 callHash_ に含まれていないのって getCompilerしてロードしたものでは？
    7. srfiの件問題点をまとめよう。
    8. 起動時に http-get などを登録できるように g000001 さんからの提案
  30. returnCode をインスタンス変数にする
  31. pc_ の順序を変える
  32. うまくいかなかったら rev 117 に戻す。
  33. getProfileResult の冗長な部分を直す。
  34. □ display closure に時間がかかっているので display closure の命令にソースコード情報を埋め込みたい
    1. □ display 命令は主に let で使われるので let の src コード情報がどこまできているのかを調べる。
  35. □ display closure をプロファイラの結果に含めてしまうから問題がややこしくなる。
  36. レジスタを1つ増やして display closure ではなく本当に call された closure だけをあつめる方法を追加しよう。
  37. うまくいった。