Calendar

November 2010
M T W T F S S
« Oct   Dec »
1234567
891011121314
15161718192021
22232425262728
2930  

GAE/Python で データストアのタイムアウトを設定する


はじめに

公開しているGAEアプリ GraphViz学習帳 のログを見ると、週に数回の頻度で DeadlineExceededError が発生しています。
今回はその原因と対策についてまとめてみました。

原因を調べる

まずは、エラーが発生した時の状況をスタックトレースで確認します。

(スタックトレース出力)

Traceback (most recent call last):
  File "/base/data/home/apps/graphviz-dev/1.346269318946863429/main.py", line 51, in post
    graph.put()    <-- エンティティ保存を指示
  File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/db/__init__.py", line 893, in put
    return datastore.Put(self._entity, rpc=rpc)
  File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 291, in Put
    'datastore_v3', 'Put', req, datastore_pb.PutResponse(), rpc)
  File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 194, in _MakeSyncCall
    rpc.wait()    <-- 書き込み完了を待っている
  File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 477, in wait
    self.__rpc.Wait()
  File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_rpc.py", line 112, in Wait
    rpc_completed = self._WaitImpl()
  File "/base/python_runtime/python_lib/versions/1/google/appengine/runtime/apiproxy.py", line 112, in _WaitImpl
    rpc_completed = _apphosting_runtime___python__apiproxy.Wait(self)
DeadlineExceededError  <-- 30秒経過したので例外発生!

どうやら、エンティティの書き込みが30秒以内に終わらなかったようです。

毎日数千回の書き込みをしていても発生頻度は週に数回程度なので、アプリよりシステム(データストア)側に原因がありそうです。 そもそもデータストアはたまに調子が悪くなるものらしいです。 (データストアの調子は、管理コンソールのSystem Status で確認出来ます)


補足 – スタックトレースをログ出力する方法

例外が発生したとき、スタックトレースがあれば解析が非常に楽になります。 スタックトレースは次のコードでログに残すことが出来ます。

import logging
import traceback

logging.error(traceback.format_exc())

対策

データストア書き込み失敗は仕方がないとして(本当は困るけど)、30秒もレスポンスが返ってこないのはクライアント側の操作性が悪くなるので困ります。
せめてもっと短い時間で返ってくれば、クライアントからリトライ処理で対処出来ます。

タイムアウトの設定方法

エンティティ書き込みのタイムアウトの設定はどこだろう?と Googleのドキュメントを探してみると、[Python]-[Storing Data]-[Reference]-[Function] のページの、 create_rpc のサンプルコードにそれらしいものを見つけました。

rpc = db.create_rpc(deadline=10, read_policy=db.EVENTUAL_CONSISTENCY)

# Employee is a db.Model class
q = Employee.all().fetch(10, rpc=rpc)

どうやら、deadlineを指定してRPCオブジェクトを作成し、それをデータストア操作関数に渡せば良いようです。

Put()関数の説明にも、RPCオブジェクトが渡せると書いてあります。

put(models)
Puts one or more model instances into the datastore.
Arguments:

models
  A model instance or a list of model instances to store.

rpc
  An RPC object for the API call.

ちなみに、この情報は言語設定を「English」にしないと見れません。(日本語版には書いてありません)


SDKのソースコードも確認しましたが大丈夫そうです。

(SDKのソース:google.appengine.ext.db.__init__.py より抜粋)

def put(self, **kwargs):
  ...
   rpc = datastore.GetRpcFromKwargs(kwargs)
  self._populate_internal_entity()
  return datastore.Put(self._entity, rpc=rpc)

ソースコードの修正

タイムアウトを設定出来るようにコードを修正するのは簡単です。

(before)

graph.put()

(after:タイムアウト5秒に設定)

rpc = db.create_rpc(deadline=5)
db.put(graph, rpc=rpc)

動作確認

修正版をアップロードして翌日ログを確認したら、エンティティの書き込み失敗が発生し、5秒でタイムアウトしていました。

その時のトレースバックは次の様になっていて、本記事の冒頭に載せたトレースバックとは違う内容になってます。

Traceback (most recent call last):
  File "/base/data/home/apps/graphviz-dev/1.346418957079719364/main.py", line 53, in post
    db.put(graph, rpc=rpc)
  File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/db/__init__.py", line 1338, in put
    keys = datastore.Put(entities, rpc=rpc)
  File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 293, in Put
    raise _ToDatastoreError(err)
Timeout

以上より、タイムアウト設定が有効になったことが確認出来ました。

Comments are closed.