omoが書いたよ

Ridela : Interface Definition Language over Ruby

もう少し変更に強く、かつラクに実装する方法はないものかと考え、 ためしに Ruby のライブラリとして実装してみました。 Rake や RSpec など、 Ruby の世界ではライブラリとして疑似言語を実装する流儀があります。 専用の文法やパーサを用意するわけではないけれど、文法のトリックと心の目の力で Ruby のコードを独自言語に見たてようというわけです。

ためしてみると案外あっさりできたので、公開してみることにしました。 "Ridela" と命名。 http://github.com/ceplus/ridela/ からダウンロードできます。

たとえば以下のように IDL (に見えなくもない Ruby のコード) を書くことができます。

require 'ridela'
require 'ridela/vce'

ns = Ridela::namespace(:hello) do |l|
  l.interface(:DemoProtocol) do
    l.method(:Say, :flow=>:s2c) do
      l.args([:message, :string, {:length => 256}], [:count, :int]) 
    end
  end
end

Ridela::VCE::Writer.new(ns).write(STDOUT)

いかがでしょうか。IDL に見えないこともないですよね？ (心の目を駆使してくださいね!) 最後の行では VCE 用の インターフェイス定義 XML を出力しています。

いまのところ VCE を使っている人以外に役立つものではありません。 ただ Ridela はコード生成部分と IDL のオブジェクトモデルを分離してありますから、 IDL のようなものが手軽に使いたい時には使い道があるかもしれません。 私も、たとえば SWIG 相当のツールの基盤として使えないかと考えています。 今は文法(API)を保守的に倒してありますが、 実際に使って様子をみながら、もう少しかっこよくしたいですね。

興味のある方はごらんください。それでは。

なぜ自分で性能を測るのか

世の中にはプロファイラという便利な道具があるのに、 どうしてプログラマはみずから性能をはかるためのコードを書くのでしょうか。 性能にうるさい人にインタビューするなど、少し調べてみました。

おおよそ以下のような理由があるようです。

• いつも測りたい
• すぐに測りたい
• 測りたいものを測りたい
• 測れないものを測りたい

1. いつも測りたい

コンパイラ標準のプロファイラを使うには、コンパイルオプションなど設定を変える必要があります。 標準プロファイラを有効にしたコードは動きが遅いため、そのまま開発を続けるには無理があります。 結果として、標準プロファイラは速度が遅いときだけピンポイントで利用する非常用ツールに留まっています。

遅いコードをある種のバグ(性能バグ)だと考え、 「バグはなるべく早期に発見すべき」という原則を適用してみましょう。 体感できるほど遅くなるまで性能バグを放置しておくのは、この原則に反しています。 早い段階で性能バグの兆候をとらえ修正の手をうつ方が、 問題が大きくなってから手をうつよりずっと確実で安くあがります。

日常的に性能を監視できない標準プロファイラは、こうした早期解決の役に立ちません。 面倒でもプロファイラを自作するのは、常に動かしておけるくらい負担が少ない測定の仕組みが欲しいからなのです。 自作したプロファイラが標準プロファイラより高性能なのは、 測定する網羅性や粒度が限られているからです。 フレームレートの測定はわかりやすい例でしょう。 関数すべての実行回数と時間を数える標準プロファイラに対し、 フレームレートの測定はほとんどタダみたいなものですよね。

フレームレートは指標として粗すぎるかもしれませんが、 粒度の大きな測定のポイントは他にも色々あります。 たとえば描画、衝突判定、物理計算といった単位で性能(実行時間)を測れば、 ごく少い負担で有意義な指標を集めることができるでしょう。

2. すぐに測りたい

コンパイラ標準のプロファイラは、 プログラムの実行が終わってはじめて測定結果を見ることができます。 しかし、特にゲームのように毎フレーム負荷の変化するアプリケーションでは、 実行中のあるタイミングで急激に負荷が増すことがあります。 たとえば特定の視点で描画すべきモデルが多くなりすぎたり、 特定のイベントでうっかり重い初期化が動いたり、 接続断でのログアウトだけがなぜか重かったり。 プログラマはその瞬間を見逃さず、いま何が起きたのかを知りたいわけです。

事後にまとまった測定結果を見ることしかできない標準プロファイラは、 こうした目的に役立ちません。 刻一刻と変化する負荷を監視し、プログラマがその様子を逐次知ることができるプロファイラが必要です。

ただ負荷を表示するだけでなく、 負荷が閾値を越えた瞬間にプレイを中断して実行状態を診断できる「アラート機能」は 逐次監視を支援する役に立つでしょう(と同僚に教わりました)。

3. 測りたいものを測りたい

あたりまえですね...ここでの意図は、「アプリケーション固有の指標で測りたい」ということです。 コンパイラ標準のプロファイラは「関数呼び出し」を単位に性能を測りますが、 これがいつも望ましい単位とは限りません。複数の関数の合計時間が必要な指標かもしれないし、 同じ関数の実行時間についても特殊な内訳が知りたいかもしれません。

たとえば 3D のモデルデータをロード、または描画するケースを考えてみます。 私が知りたいのはモデル毎のロード時間(または描画時間)ですが、 これを標準プロファイラは教えてくれません。 どんなモデルをロードするのにも同じ関数を使うからです。

プログラムがデータ駆動になるほど、関数単位という指標は必要な指標とかけ離れてしまいます。 最も極端な例はスクリプト言語のインタプリタでしょう。 データであるスクリプトを実行するインタプリタをプロファイルしたところで、 それがなぜ遅いのかはわかりません。 VM::invokeMethod() が遅い...と言われても途方に来れるだけです。 スクリプト言語に言語固有のプロファイラが必要なように、 データにはその特徴に合わせた性能測定が必要です。

データ駆動の他にもアプリケーション固有の指標はあります。 たとえば、イベント駆動と状態マシンスタイルのコードでログイン処理開始から ログイン処理完了までの時間を測るのにはプロファイラが使えません。 ある状態に遷移した時刻から別の状態に遷移した時刻までの時間を、 プログラマ自身で測る必要があります。

「いつも測りたい」を達成するために測る大まかな実行時間は、 同時に「測りたいもの」でもあります。 個々の関数の実行時間より、 巨視的な視点での「描画が xx ミリ秒」や「IO が xx ミリ秒」といった指標を 知りたいことは、往々にしてあるのです。

4. 測れないものを測りたい

これもあたりまえの言い方になってしまいました。「測定漏れをなくしたい」という意図です。 コンパイラ標準のプロファイラには測れないものがあります。 たとえば GPU や IO のようにプロセスの外側で費された時間はわかりません。 バイナリで提供されたサードパーティ製品の実行時間の内訳もわかりません。 またネットワークをまたぐプログラムでは、通信の遅延をプロファイラではかることはできません。 こうした処理の時間はプロファイラの表示に表れないこともあるため、 「なんとなく遅いけど原因がよくわからない」という事態になりがちです。

怪しい関数の出入口で実時間を測るなど測定方法を工夫すれば、 こうした問題をいくらか回避することができます。 また、IO のスループットや描画頂点数のように実行時間以外の指標を測ることで、 間接的に問題をつきとめることができるかもしれません。

世の中のプロファイルツール

コンパイラ標準のプロファイラ以外にも、世間には色々なプロファイラが出回っているようです。 グラフィクスまわりでは先の NVIDIA-PerfHUD をはじめ、 ATI 社の GPU PerfStudio 、 Microsoft 社の PIX 、などが知られています。

Java VM は JVMTI と 呼ばれるプロファイラ用 API を公開しています。API だけでなく、 強力な GUI を備えた VisualVM といった実装もあります。 これは時間プロファイラやヒーププロファイラを備えています。 計測に限らない運用時の監視機構として JMX <http://java.sun.com/javase/technologies/core/mntr-mgmt/javamanagement/> というフレームワークも持っています。

OS の機能として提供され、システム全体の性能を測るプロファイラもあります。 OProfile , DTrace , ETW などが知られています。 DTrace や ETW はプログラマビリティを備えており、自作プロファイラの動機の多くを吸収してくれそうです。 top や sar といった UNIX コマンドも広い意味ではプロファイラと言えます。

IBM developerWorks の記事 Java run-time monitoring シリーズ は、 特にサーバ側での性能測定(ここではモニタリングと呼んでいます)を考えるうえで参考になりました。

Unfact: 侵入的性能測定ライブラリ

ちゃんと自分で色々測らにゃいかんと反省したところで、 手始めに C++ でプロファイル用のライブラリを作ってみました。 Unfact と命名。今回も github に置きました。 時間プロファイラとヒーププロファイラが入っています。 (色々野心的なゴールを設定したい気もしましたが、最初は手堅くいくことにしました。) 「侵入的」というのは、要するにソースコードに測定のフックを埋め込む必要があるということです。

ゲーム屋さんは多かれ少なかれ似たようなコードを持っていることだろうと思います。 社内にも二つありましたが、今回は習作ということもあり、自分で書きました。 (書きはじめてから存在を知ったのは秘密です...) 以下のような点でがんばってみました。

• マルチスレッド対応: データロード用のスレッドなどと混ぜても安心。
• STL 非依存: STL を使わないオレオレコードでも使える。
• アロケータ交換可能: デバッグ用のヒープだけを使って副作用の少ないプロファイリングを。
• メモリアロケータ独立なヒーププロファイラ: アロケータを作るたびにプロファイラを作る面倒から開放。
• ヘッダファイルのみで構成: ビルドの手間なし。

使ってみるとマルチスレッド対応はそれなりに便利でした。 ただスレッド関係の API を使う都合で、今のところ Windows と UNIX 系システムでしか動きません。 コンソール機向けには移植が必要です。

つかいかた: 初期化

ヒーププロファイラは、指定した区間で確保されたメモリ量を測る仕組みです。 たとえばデータをロードする関数を区間に指定すれば、 あるデータを読み込むために確保したヒープの容量を測ることができます。

Unfact の初期化は以下のように行います。(コードは適当につっこんでください。) まずマクロの参照するグローバル変数を宣言します。

// 適当なヘッダファイル
#include <unfact/extras/heap_tracing_annotation.hpp>
#include <unfact/extras/tick_tracing_annotation.hpp>
UFX_HEAP_TRACE_DECLARE();
UFX_TICK_TRACE_DECLARE();

定義をどこかに書きます。

// 適当なソースファイル
UFX_HEAP_TRACE_DEFINE();
UFX_TICK_TRACE_DEFINE();

初期化と終了:

UFX_HEAP_TRACE_INIT();
UFX_TICK_TRACE_INIT();

UFX_HEAP_TRACE_FINI();
UFX_TICK_TRACE_FINI();

つかいかた: ヒーププロファイラ

ヒーププロファイラを使うには、まずメモリアロケータをフックします。

void* operator new (std::size_t blocksize)
{
  return UFX_HEAP_TRACE_MALLOC(malloc(blocksize), blocksize);
}

void operator delete ( void* block ) throw()
{
  UFX_HEAP_TRACE_FREE(block);
  free(block);
}

new[] と delete[] などもわすれずに。

次に計測する区間を指定します。 区間は関数のスコープとして指定することができます。

AssetMap::PairType
AssetLoader::LoadSoundAsset(....)
{
  UFX_HEAP_TRACE_SCOPE(sound);
  ...
}

これで LoadSoundAsset() 内で確保されるメモリを "sound" という区間名でマークします。 関数をまたいで測定したい場合は UFX_HEAP_TRACE_PUSH(), UFX_HEAP_TRACE_POP() マクロを使います。

区間名を文字列で指定するには UFX_HEAP_TRACE_SCOPE_STR() マクロを使います。 データごとのメモリ使用量を測るのに便利です。(UFX_HEAP_TRACE_PUSH_STR() マクロもあります。)

AssetMap::PairType 
AssetLoader::LoadFrameAsset(...)
{
  UFX_HEAP_TRACE_SCOPE(frame);
  UFX_HEAP_TRACE_SCOPE_STR(name, ToScopeName(value).c_str());
  ....
}

現状のアロケート状態を出力するには UFX_HEAP_TRACE_REPORT() マクロを使います。 素の状態では標準エラー出力にダンプされます。(カスタマイズできます。)

void DebugPrintHeapStats()
{
  UFX_HEAP_TRACE_REPORT();
}

出力:

UNFACT[TRACE]    8124:asset.frame.chara01
UNFACT[TRACE]    8750:asset.frame.chara02
UNFACT[TRACE] 1145152:asset.frame.collision
UNFACT[TRACE]     300:asset.frame.item01
UNFACT[TRACE]     190:asset.frame.item02
UNFACT[TRACE]     681:asset.frame.item03
UNFACT[TRACE]   10265:asset.frame.map
UNFACT[TRACE]   65340:asset.frame.npc01
UNFACT[TRACE]    9237:asset.frame.npc02
UNFACT[TRACE] 1248042:asset.frame
UNFACT[TRACE]   19572:asset.sound
UNFACT[TRACE]   10487:asset.texture
UNFACT[TRACE] 1278102:asset
UNFACT[TRACE] 1558548:

区間名が辞書順にソートされ、確保したメモリのバイト数が表示されます。 とても地味です...ここは改善したいところ。 (サンプルの数字やデータ名は実在のものではありません。)

なお、区間は入れ子にすることができます。親区間 (例:asset.frame) は、 子区間(asset.frame.chara01 など)と、自分自身のアロケート量の合計が表示されます。

さて、上の例をよく見ると「asset.frame.collision」が大半のメモリを使っています。 これは衝突判定用の疎なモデルなので、実モデル(asset.frame.map)より大きいのは変です。 実は、これはデータ読み込みのキャッシュが関係しています。 「asset.frame.collision」を読み込むときに、近隣のデータもメモリに先読みしているのです。 キャッシュの仕組みは結構なことですが、測定の視点では嬉しくありません。 キャッシュのメモリは別枠で数えたいですよね。

幸い、キャッシュ用に使うアロケータは外部から指定することができました。(ご都合主義っぽいけど実話。) そのアロケータにもフックを追加しましょう。 ここでは UFX_HEAP_TRACE_DISJOIN() マクロを使います。

class AllocatorStdc : public AllocatorBase
{
  ....
  virtual void * Alloc(ws::MemorySize size, ws::MemorySize alignment)
  {
    UFX_HEAP_TRACE_DISJOIN(cache);
    /* ignore alignment */
    void* p = new char[size];
    return p;
  }
  ....
};

UFX_HEAP_TRACE_DISJOIN() マクロは、区間の入れ子関係をリセットします。 上で定義した「cache」区間は asset.frame とは独立します。

UNFACT[TRACE]    8124:asset.frame.chara01
UNFACT[TRACE]    8750:asset.frame.chara02
UNFACT[TRACE]     610:asset.frame.collision
UNFACT[TRACE]     300:asset.frame.item01
UNFACT[TRACE]     190:asset.frame.item02
UNFACT[TRACE]     681:asset.frame.item03
UNFACT[TRACE]   10266:asset.frame.map
UNFACT[TRACE]    8920:asset.frame.npc01
UNFACT[TRACE]    9237:asset.frame.npc02
UNFACT[TRACE]   47082:asset.frame
UNFACT[TRACE]   19572:asset.sound
UNFACT[TRACE]   10487:asset.texture
UNFACT[TRACE]   77141:asset
UNFACT[TRACE] 1202671:cache
UNFACT[TRACE] 1558550:

実は大半のヒープがキャッシュに使われていることがわかりました。 メモリ不足の局面ではキャッシュを捨てれば良いことがわかります。 (ただし実験台に使ったコードの場合、 実際にメモリが逼迫する場面では別のデータが支配的であることがわかっています。むー...)

つかいかた: 時間プロファイラ

時間プロファイラの使い方はおおよそヒーププロファイラと同じです。 時間を測りたい関数の冒頭で、区間を定義するマクロ UFX_TICK_TRACE_SCOPE_COUNT() を使います。 関数の実行時間が、指定した区間の名前で記録されます。

void Scene::Render()
{
  UFX_TICK_TRACE_SCOPE_COUNT(render);
  ...
}
...
void Scene::Update(...)
{
  UFX_TICK_TRACE_SCOPE_COUNT(update);
   ...
}

時間をはからず、ただ区間を定義するには UFX_TICK_TRACE_SCOPE() マクロを使います。 UFX_TICK_TRACE_PUSH(), UFX_TICK_TRACE_POP() を使い、関数とは無関係に区間を定義することもできます。 特定のマップ内での処理時間を測るといった用途に使えます。

void Scene::StartGame(...)
{
  UFX_TICK_TRACE_PUSH(scene);
   ...
}

void Scene::EndGame()
{
  UFX_TICK_TRACE_POP();
   ...
}

「ログイン処理の開始から完了まで」のように、関数とは無関係の時間を測るには、 UFX_TICK_TRACE_START(), UFX_TICK_TRACE_END() を使います。

class LoginTask ... {
  ....
  void Update(...)
  {
    UFX_TICK_TRACE_SCOPE_STR(name, m_name.c_str());

    if (firstTime) { 
      UFX_TICK_TRACE_START();
    }
    
    DoUpdate();
    
    if (IsDone()) {
      UFX_TICK_TRACE_STOP();
    }
  }
  ...
};

結果のプリントは UFX_TICK_TRACE_REPORT() マクロを使います。

void DebugPrintTickStats()
{
  UFX_TICK_TRACE_REPORT();
}

各区間の呼出回数、平均所要時間が表示されます。 ヒーププロファイラと違い、子区間の合計を表示することはありません。

UNFACT[TRACE]   3187.0 (     1 times):progress.loading
UNFACT[TRACE]    187.0 (     1 times):progress.syncing
UNFACT[TRACE]      0.0 (     0 times):progress
UNFACT[TRACE]      6.9 (   269 times):game.render
UNFACT[TRACE]      3.0 (    86 times):game.update
UNFACT[TRACE]      0.0 (     0 times):game
UNFACT[TRACE]      0.0 (     0 times):

プロファイル情報の中には、フレーム毎にクリアしたいものもあります。 UFX_TICK_TRACE_CLEAR_HERE() マクロを使うと、現在の区間の計測結果をクリアします。 (UFX_TICK_TRACE_CLEAR() で全ての計測結果をクリアします。)

void DebugClearTickStats()
{
  UFX_TICK_TRACE_CLEAR_HERE();
}

その他の使いかた

UFX_* のマクロは、既存コードへの組込みを楽にするために用意したものです。 開発しながら計測すべき箇所がわかっている時には、Unfact のオブジェクトを直接操作することもできます。 たとえば各オブジェクトにヒープ計測の区間をひもづける、といった使い方も可能です。 可視化などの目的でログのデータ構造をトラバースしたいこともあるでしょう。 そのほかログの出力先、メモリアロケータは変更可能です。 詳しくはソースコードを参照ください。

いまはまだ相当にしょんぼりな出来ですが、実戦で使いながら改善していきたいと思います。 それでは。

Trac 考古学

森田です。こんにちは。

Trac という バグ管理ツールをご存知の方も多いと思います。 弊社 CE も Trac は重宝しています。プロジェクトのバグ管理だけでなく、社内共通の雑談 Wiki まで Trac です。 CE では 2006 年末まで PukiWiki を雑談 Wiki に使っていましたが、より高機能な Trac に乗り換えました。 Trac を導入してからそろそろ 2 年。 バージョンは 0.9.6 と少し古いバージョンを使っているため、最近はバージョンアップの要望もではじめています。

2 年も使っているとデータベースも膨らんできます。このデータを活かさない手はありません。 手始めに、いくつか統計をとってみることにしました。

Trac と SQLite

Trac の標準設定は、各種データを SQLite というデータベースに保存します。 SQLite のデータは単一のファイルに保存されており、コピーは簡単です。 Trac のデータディレクトリにある trac.db というファイルをコピーすればいいのです。 雑談 Wiki の trac.db は 120MB ありました。

統計をとるにはデータベースのスキーマが必要です。 SQLite でスキーマを表示するには, sqlite3 コマンドラインツールの .schema コマンドを使います。 保存するファイル名は .output コマンドで指定します.

$ sqlite3.exe trac.db
SQLite version 3.6.3
Enter ".help" for instructions
Enter SQL statements terminated with a ";"
sqlite> .output schema.txt
sqlite> .schema
sqlite> .quit

ticket、revision、wiki など、それらしいテーブル名を伺うことができるでしょう。 今回の主役は wiki テーブルです.

sqlite> select count(*) from wiki;
19253

sqlite> select count(distinct name) from wiki;
2171