概要

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

背景

アプリケーションのグローバルな動作の内、ビジネス ロジックと関係のない部分を変更したいことはよくあります。その目標は、リスクもコードもほとんど増やさずに大きく変更することです。また、パフォーマンスに関するデータのロギングを、アプリケーション全体に適用したいといった、横断的な操作も必要です。デベロッパーがどのような上位レベルの API（Models 対データストア、Django 対 WebOb）を使っているかにかかわらず、この目標をグローバルに達成したいと思います。

使用するナチュラル モジュールは、上位レベルの API の呼び出しを適切なサービスの実装に代行させる、RPC サービスの下位レベル レジストリ api_proxy_map です。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 で間に合わせの（不正確で存在時間も短い）stats を収集し、詳細な情報はロギング ステートメントに入れます: 各データストアの操作で生成されたログ エントリは、抽出してオフラインで解析することができます。

最初のステップは、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 stats にアクセスできるように、忘れずに db_log.py を app.yaml に追加してください。この記事にあるすべてのソース コードについては、Google App Engine cookbook（英語）をご覧ください。