結論から述べますと、辞書引き機能の処理時間の表示(Ni postulis *** sekundon.)が誤っていたので、修正しました。実際の処理時間より不当に小さい値が表示されていて、実害がないとはいえご迷惑をお掛けしました。お詫び致します。フレームワークFaktroの上で心温まる開発作業をしているのですが、どうにも現行処理との性能差が酷いので調べてみたら発覚した次第です。
以下は謎の処理時間についての後始末の次第です。
飲酒コーディングの脅威
見ろ、処理時間がゴミのようだ
処理ディスパッチ・セッション・ログなどの基底処理のみを行い、単純な(ほぼ)静的ページをTTに通すだけのトリビアルなトランザクションを回すだけで0.05秒程掛かるというのは、まあmod_perl環境ではないので仕方がないと思っていました。Benchmarkを回してみると単純な素性構造の単一化が1400回/秒程度なので、文毎に構文解析を細切れにして行えば現実的な性能が出るとも思っていました。
しかし単純な辞書引きでも(辞書の動的ローディングと、辞書引き処理の動的ローディング・コンパイルの時間が加算されるとはいえ)0.2秒前後が掛かるようになりました。一方、現行版として書き散らしたコードが自称する処理時間は、0.02秒という値です。開発効率の向上という大義名分があれど、「現行の約10倍遅くなりました」というのは容易に許されるものではありません。Faktroの上で整然と書いたコードにしてみれば、現行版の処理時間はムスカ大佐に言わせれば「ゴミのよう」な時間に過ぎません。これはおかしい。いくらなんでも出来過ぎじゃないでしょうか。
名状しがたい謎の処理
ということで、今更ながらに自分のプログラムの高性能さに疑問を持った私は、早速現行版のプログラムを眺めました。Faktroは自身の構成クラス群のローディング・コンパイルの後、レンダリングを行う直前までの時間を計測しているので、それなりに不正確な値が出るとは思っていましたが、現行版はこの「入り口と出口」がさらに甘いタイミングであるように疑ったからです。
しかし、処理時間を求める処理を見たその瞬間に、私はその目を疑いましたね。何と2点間のtimes関数の差分を求めるという、到底理解しがたい謎の処理を行っていたのです。きっと麦酒片手にコーディングしていたか、或いは寝ている間に妖精さんが悪戯をしたのだと思います。
速攻で直しましたが……
驚いた私は、すぐさま処理を直してテストして本番環境に反映しました。今では0.3秒前後の値を出すようになりました。しかしながら、いかんせんこの値も入り口と出口の刻み方が甘めであるため、早いところFaktroに基づいた辞書引きに差し替えたいものです。