はじめに

コードが野放しに増大すると、メンテナンスや修正が難しくなることがあります。コードベース全体に対して、データストアの使用のプロファイリングや「監査データ」（特定の行を変更したユーザーの特定など）の追加といった機能を実装するのが、非常に難しい場合もあります。どうしたらソースすべてを監視できるでしょうか。どうしたら他のデベロッパーが後でコードを拡張するときに、ミスを事前に防げるでしょうか。

背景

アプリケーションのグローバルな動作のうち、ビジネス ロジックと関係のない部分を変更したいことはよくあります。目標は、大きな変更を、ほんの少しのリスクとコード変更で行うことです。また、パフォーマンスに関するデータのログ出力など、横断的関心事をアプリケーション全体に適用したい場合もあります。デベロッパーがどのような高レベル API（モデルかデータストアか、Django か WebOb か）を使用しているかにかかわらず、この目標をグローバルに達成したいと思います。

使用するモジュールは api_proxy_map です。これは、高レベル API の呼び出しを適切なサービス実装に委任する、RPC サービスの低レベル レジストリです。api_proxy_map を変更する従来の方法は、このモジュールにモンキーパッチを適用し、そのメイン エントリ ポイント apiproxy_stub_map.MakeSyncCall を置き換えることです。この方法がうまくいく場合もありますが、危険性がないわけではありません。ユニット テストを簡単にするため、他のモジュールで MakeSyncCall メソッドを挿入し、そのメソッドにローカル参照を格納することがあります。この方法なら、テストにモックを代用するのは簡単です。

memcache モジュールは、この手法を使用した良い例です。しかし残念ながら、これはパッチを適用する前にどのような memcache-Client を作成しても、変更内容は完全に無視されてしまうということでもあります。たとえば、パッチが適用される前にスクリプトで memcache モジュールをインポートした場合がそうです。そのようなリファレンスを探し出して修正する作業は煩雑ですし、新しいバージョンの SDK（または他の目的で使用する他の外部開発ツール ライブラリ）で今後新たな静的依存関係を使用しないという保証はありません。

幸運にも、モンキーパッチとは別の方法があります。SDK のバージョン 1.1.8 では、api_proxy_map に新しいメカニズムとしてフックという概念を採り入れています。そのため、デベロッパーはメソッドを定義する場合、下記のように MakeSyncCall と同じシグネチャを使用できます。

def hook(service, call, request, response):
    ...

また、シグネチャをランタイムに登録する場合は、下記のメソッドのいずれかを使うことができます。

apiproxy_stub_map.apiproxy.GetPreCallHooks().Append('unique_name', hook, 'optional_api_identifier')
apiproxy_stub_map.apiproxy.GetPostCallHooks().Append('unique_name', hook, 'optional_api_identifier')
apiproxy_stub_map.apiproxy.GetPreCallHooks().Push('unique_name', hook, 'optional_api_identifier')
apiproxy_stub_map.apiproxy.GetPostCallHooks().Push('unique_name', hook, 'optional_api_identifier')

フックには 2 種類あります。PreCallHook は RPC を呼び出す前に実行され、PostCallHook は RPC を呼び出した後に実行されます。オプションの API 識別子を指定して、特定の型の RPC（データストアや memcache）に対してだけフックを呼び出すようにすることもできます。apiproxy には複数のフックを登録できます。Append は新しいフックを既存フックのリストの末尾に追加し、Push はフックをリストの先頭に追加します。

例

具体例を見て、データストアのプロファイリングを実装してみましょう。考え方としては、データベースでモデルの型ごとに統計情報を自動収集します。put/get/query/delete のカウンタを分離したいのですが、データにアクセスするモデル クラスやハンドラは修正したくありません。パフォーマンス上の理由から、結果は一切データストアに書き込まないようにします。その代わり、memcache で間に合わせの（不正確で存続時間も短い）統計情報を収集し、詳細な情報はロギング ステートメントに入れます。各データストア処理で生成されたログ エントリは、抽出してオフラインで解析することができます。

最初のステップは、memcache からデータを収集し、冗長な情報をログに記録するためのヘルパーを作成することです。データをロックしてトランザクションのように増分する方法はないので、memcache のカウントは近似値にすぎないことに留意してください。このカウントは大体の概要を記録することを目的としており、ログにある詳細なデータこそが重要です。下記の db_log はその目的を果たしています。

def db_log(model, call, details=''):
    """Call this method whenever the database is invoked.

    Args:
        model: the model name (aka kind) that the operation is on
        call: the kind of operation (Get/Put/...)
        details: any text that should be added to the detailed log entry.
    """

    # First, let's update memcache
    if model:
        stats = memcache.get('DB_TMP_STATS')
        if stats is None: stats = {}
        key = '%s_%s' % (call, model)
        stats[key] = stats.get(key, 0) + 1
        memcache.set('DB_TMP_STATS', stats)

    # Next, let's log for some more detailed analysis
    logging.debug('DB_LOG: %s @ %s (%s)', call, model, details)

注: memcache には、incr() や decr() のように、カウントを増分するトランザクション機能があります。ただし、これらの機能は 1 つの値には有効ですが、カウンタのディクショナリには対応していません。

次は、このヘルパーをうまく使って、実際にフックを書き込んでみましょう。RPC を呼び出す前にデータを評価する PreCallHook を使用します（今回の場合は PostCallHook も同様にうまく機能します）。

def patch_appengine():
  """Apply a hook to app engine that logs db statistics."""
  def model_name_from_key(key):
      return key.path().element_list()[0].type()

  def hook(service, call, request, response):
     assert service == 'datastore_v3'
     if call == 'Put':
         for entity in request.entity_list():
             db_log(model_name_from_key(entity.key()), call)
     elif call in ('Get', 'Delete'):
         for key in request.key_list():
             db_log(model_name_from_key(key), call)
     elif call == 'RunQuery':
         kind = datastore_index.CompositeIndexForQuery(request)[1]
         db_log(kind, call)
     else:
         db_log(None, call)

     apiproxy_stub_map.apiproxy.GetPreCallHooks().Append(
         'db_log', hook, 'datastore_v3')

統計情報をブラウザに表示する非常に簡単なスクリプトを作成することもできます。

def main():
    """A very simple handler that will print the temporary statistics."""
    print 'Content-Type: text/plain'
    print ''
    print 'Mini stats'
    print '----------'
    stats = memcache.get('DB_TMP_STATS')
    if stats is None: stats = {}
    for name, count in sorted(stats.items(), key=operator.itemgetter(0)):
        print '%s : %s' % (name, count)
    print '----------'


if __name__ == "__main__":
    main()

コード記述のほとんどは、作業で使用するモデル名を指定することに割かれます。このデータの取得方法に関心のある方は、SDK の entity_pb.py モジュールと datastore_pb.py モジュールをご覧ください。これらのモジュールには、データストア RPC に使用するプロトコル バッファが含まれています。

これまでに作成したコンポーネント

• memcache（とログ）にあるデータストア情報をコンパイルするヘルパー
• ヘルパーを実行するフック
• 結果を表示する簡単なハンドラ

上記の 3 つのコンポーネントを、1 つのモジュールに格納することができます（それを db_log.py と呼びます）。次の 2 行のコードをアプリケーションに追加すれば、アプリケーションの改良が有効になります。

import db_log
db_log.patch_appengine()

このスニペットは、呼び出されるハンドラに関係なく必ず実行される場所に配置してください。たとえば、共通のメイン メソッドがある場合（Django アプリケーションの場合）は、そのメイン メソッドを定義する前に追加するとよいでしょう。また、間に合わせの memcache の統計情報にアクセスできるように、忘れずに db_log.py を app.yaml に追加してください。この記事にあるすべてのソース コードについては、Google App Engine クックブックをご覧ください。