【Google App Engine】 TaskQueueは信用できないで御座候

　ajn#4、面白かったで御座候。浅海先生、荒川さん、おつかれさまで御座候。今回は、TaskQueueが信用できない話をするで御座候。（ところで、御座候って書くと何かいいことあるの？）

TaskQueueは必ず実行されるが正常終了するとは限らない

　TaskQueueはたしかに必ず起動される。例えば、"Request was aborted after waiting too long・・"というエラーになったとしても、正しく起動されるまでリトライされる。
　しかし、起動してから30秒を超えた場合に、com.google.apphosting.api.DeadlineExceededExceptionやcom.google.apphosting.runtime.HardDeadlineExceededErrorが発生すると、そのTaskは強制終了となってリトライされない。※Exceptionをcatchで握りつぶすのではなく、ちゃんとスローさせれば必ずリトライされる。（正確には、com.google.apphosting.api.DeadlineExceededExceptionの後、300ms～400msでHardDeadlineExceededErrorになって強制終了する。300ms～400msでは出来ることは限られるが、何らかの救済処理を追記できるかもしれない。また、com.google.apphosting.utils.servlet.TransactionCleanupFilterというのもある。これらの動作については、30秒後の後を見て得たものが詳しい。）

　（※）2010/3/8追記　Exceptionを握りつぶさないで、最後までスローしてあげると、必ず再実行されるが、Task Queue sometimes leave tasks unexecuted for a few minutesにあるとおり、起動するのに数分間かかる場合があるという。皆さん、スターよろしくお願いします。m(_ _)m

　TaskQueueが正常終了するとは限らない原因（リトライはされるが）はDeadlineExceededExceptionであるが、さらに、そのときの負荷状況によって発生したりしなかったりすることが問題を複雑にしている。ある条件下でテストして成功したとしても、実行環境の負荷状況は刻々と変化しており、次にテストしたときには成功するかどうかわからない。つまり、今日成功したものが明日は失敗するということも普通に起こる。これがTaskQueueが信用できないという意味である。
　

実際のテスト結果

　例えば、Taskを複数件登録するという実験をすると、※１のように、最初の10件までは問題なく完了するのだが、それ以上になるとエラーになる。
　ちなみに、1Taskで、500文字StringをBatch PUTで500個実行すると、以下の理由でうまくいかないので、300文字StringをBatch PUTで100個実行するようにしている。

• DatastoreService#get(List)は500件まで。
  
• Entity#setProperty(key, value)のvalue文字列(String)は500文字まで。
  
• DatastoreTimeoutExceptionの場合は5秒sleepし無限に再実行する。（warningログは出力する。）
  
• 同じキーのインデックスが既に登録されている場合は再度putしないようにする。
  
• 500件put時に下記エラー。件数ではなくて、一度にputするサイズが大きすぎるのかも？
  

  ---

  SEVERE: The request to API call datastore_v3.Put() was too large.
  

  ---

  
  

• 上記対策をコーディングしてテスト
  
  • 最大文字数500文字（日本語）、バッチput500件では"The request to API call datastore_v3.Put() was too large."エラー発生。
    
  • 最大文字数250文字（日本語）、バッチput500件では"The request to API call datastore_v3.Put() was too large."エラー発生。
    
  • 最大文字数100文字（日本語）、バッチput500件では"DatastoreTimeoutException"が１回発生し、リトライで正常終了。
    
  • 最大文字数100文字（日本語）、バッチput300件では"DatastoreTimeoutException"が２回発生し、リトライで正常終了。
    
  • 最大文字数100文字（日本語）、バッチput100件ではエラー発生せず正常終了。(11.2秒、バッチgetも100件)
    
  • 最大文字数100文字（日本語）、バッチput100件、バッチget500件ではエラー発生せず正常終了。(10.8秒)
    
  • ちなみにバッチput501件を実行すると、下記エラーとなった。(local環境だと501件が登録できてしまったが、GAEだとやはりエラーとなった。)
    
    • java.lang.IllegalArgumentException: cannot put more than 500 entities in a single call
      

• バッチputは100件のまま、最大文字数を変えてテストする。
  
  • 最大文字数200文字（日本語）ではエラー発生せず正常終了。(11.5秒)
    
  • 最大文字数300文字（日本語）ではエラー発生せず正常終了。(12.5秒)
    
  • 最大文字数400文字（日本語）では"DatastoreTimeoutException"が１回発生し、リトライで正常終了。(20.7秒)
    
  • 最大文字数500文字（日本語）では"DatastoreTimeoutException"が２回発生し、リトライで正常終了。(27.6秒)
  
  
• QueueにTaskを溜めてみる。
  500文字の文章(+3文字)を、最大文字数300文字（日本語）、バッチput100件でインデックス登録処理を実行する。
  
  • 一度に3件登録した場合、エラー発生せず3件とも正常終了。
    
  • 一度に100件登録した場合 、
    
    • 最初の10件まではエラー発生せず正常終了。(※１）
      
    • 11件目からDatastoreTimeoutExceptionが発生し始める。
      また、com.google.apphosting.api.DeadlineExceededException: This request (b0dadab42eb7da0a) started at 2010/01/18 06:33:21.954 UTC and was still executing at 2010/01/18 06:33:51.109 UTC.
      との30秒超過エラーが発生。(Errorログ)
      
    • このあたりから"Request was aborted ..."ログが出始める。
      
    • 12件目からDatastoreTimeoutException、DeadlineExceededExceptionの後、
      com.google.apphosting.runtime.HardDeadlineExceededError: This request (9e9803f05d46a8c5) started at 2010/01/18 06:33:32.729 UTC and was still executing at 2010/01/18 06:34:03.487 UTC.
      とのCriticalログが発生。
      
    • 以降はDatastoreTimeoutException、DeadlineExceededException、HardDeadlineExceededErrorが頻発。
      
    • 時々正常終了する場合もあるが、"This request used a high amount of CPU, and was roughly 1.1 times over the average request CPU limit. High CPU requests have a small quota, and if you exceed this quota, your app will be temporarily disabled."とのWarningログが出力されている。

StoneSkippingによる対応策
　
　ということで、TaskQueueは信用できないものとして、別途Memcacheで管理するという方法を考えてみた。（Memcacheも信用できないという話はあるが・・）
　下図のように、べき等性をもつTaskを1件づつ繰り返し実行することで全件を処理するが、Taskは不完全終了してもいいように、Memcacheにおいて情報を管理するというところがポイントである。これを勝手にStone Skippingと名づけている。川辺の石投げ遊びで3段とびとかやって遊んだやつだ。Cronだけだと最短で1分間隔でしか動かせないので、Taskの数段飛びで対応するようにしている。

　
　①　クライアントからのリクエストはMemcacheに登録する（※１）
　②　cronが最初のTaskを起動、未完了の文字列を拾ってINDEX登録。登録成功でMemcacheから消す。(※２）
　③　パラメータに文字列指定して次のTaskを登録する（URLは最大2038 文字なのでたぶん大丈夫）
※１　Memcacheの排他制御は必要。（参考）Memcacheでスピンロックを実装してTask Queue処理結果を集約してみるテストCommentsAdd Star
　　Max１MBなので最大1000件とする。
　　それを超える場合はKeyを＋１する。
※２　未完了のものを再実行する際は、途中までPUT成功しているものを読み飛ばす

INDEX生成実験
　

　これは、全文検索（SuffixArray)用INDEX生成のために実際に用いて実験したもの。

• Store Skipping方式で500文字(日本語)×100件の文字列のSuffix Arrayを作成する。
  
• Indexの最大長は200文字、バッチputは最大100件。
  
  • 500文字 / 100件 = 5回バッチputを実行する。
    
• Index作成要求Servletに100回リクエストを投げる。１リクエストするたびに、200msスリープする。
  
• cronは1分間隔で実行。
  

結果

• Index作成要求100件リクエスト(Memcache書き込み) : 1分4秒
  
• Index作成(datastore書き込み) : 1時間以上 (1時間10分で100件中60件登録完了)
  
  • com.google.apphosting.api.やcom.google.apphosting.runtime.HardDeadlineExceededErrorが多発。
    
    • 100件のバッチputが途中まで実行された後上記エラー発生。
      
    • 60件目あたりから、バッチputが1回も実行されないで上記エラー発生。
      
  • キューにタスクが3件たまることもあり。（※）
    
    • おそらく同じdoc,itemに対する処理。

　実行時間がかかりすぎるため、cronの実行間隔やPUTする文字列の長さなど、いろいろ調整することで、リトライが発生しないようにする改善は必要だと思われる。とりあえずは、これで確実に保存できることを確認できた。
　クライアントから登録する際にかかった時間が1分4秒であった点も大きい成果である。

＜※追記＞
# Task実行が1分以内に完了しないとcronによって多重に起動されてしまう。
# 今回の実験では、TaskQueueにTaskが65個溜まり、CPU TimeのDaily Quotaが限界値まで達してしまった。
# Memcacheにおいて、Task起動数管理（起動で＋１、終了で－１）を行う必要がある。また、異常終了（DeadlineExceededException）発生時には、HardDeadlineExceededErrorまでの300ms以内に－１を実行する。そして、1個以上起動されない仕組みにする。
＜※追記 01/28＞
再テスト

• 改善内容
  
  • インデックス作成対象文字列を500文字から100文字に変更。
    
  • cronの実行間隔を1分から2分に変更。
    
  • QueueにTaskが登録されている場合、cronからTaskを登録しない。（最大１TASK)
    
  • インデックス作成対象文字列の最後に番号を付加し、インデックスの内容が各リクエストで別々になるようにした。
    
• 結果
  
  • 100文字 * 100件処理にかかった時間 : 3分4秒
    
  • 1タスクの処理時間 : 1.1秒～2.6秒
    
  • 2個のインスタンスが交互に処理を行い、タスク終了後、次のタスクはすぐに処理が実行されている。

# 同じ文字列を登録するとINDEXが肥大化してしまい、100リクエストを処理するのに約12分かかってしまった。実際にはそれぞれのリクエストで文字列は異なるので、このようなことにはならないと思われる。上記のテスト結果が標準的な数値だと思う。

TaskQueueはスケールしない！？５


　最後に、こちらの記事の続編で、ajn#3の宿題の報告を行う。
　前回の実験では、どんなにがんばってもvmが4つしか起動できなかったのだが、今回の実験では、いわゆる「あっため」を行うことで、vmのインスタンス数を増やしてみようという試みだ。

実験１：vmのインスタンスをとにかく増やす

• Warmerサーブレットを作成。sleepしてレスポンスにuuidを返す。
  
• クライアント側はJMeterを使用してテスト。
  
  • スレッド数、Ramp-Up期間、ループ回数をいろいろ調整して実行してみる。
    

---

• sleepを１秒に設定してテスト
  
  • -> サーバ側に"Request was aborted ..."が所々発生。
    
  • -> 何件かクライアントにエラーで返ってくる。
    
  • -> インスタンスが４個から増えない。
    
• sleepを３秒にしてみる。
  
  • -> DeadlineExceededExceptionが発生し正常終了しない。
    
• sleepを２秒にしてみる。
  
  • -> サーバ側"Request was aborted ..."の発生件数が増えた。
    
  • -> インスタンスが４個から増えない。
    
  • -> 戻りがエラーの場合の件数が増えた。(60リクエスト中、エラー41件)
    
• sleepを５００ミリ秒にしてみる。
  
  • -> インスタンスが１個しか起動しない。
    (スレッド数60、Ramp-Up期間120秒、ループ回数1,2,4共全て)
    
• sleepを８００ミリ秒にしてみる。
  
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数4でインスタンス４個起動。
    
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数6でインスタンス１０個起動！（ループ回数8でもインスタンス１０個）
    
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数12でインスタンス１１個起動。
    
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数16でインスタンス１２個起動。
    
  • -> エラー戻りはなし。
    
  • -> サーバ側の"Request was aborted ..."もなし。
    
  • -> しかし、いくつか結果が返ってこなかった。
    
• sleepを９００ミリ秒にしてみる。
  
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数6でインスタンス９個起動。
    
  • -> スレッド数60、Ramp-Up期間60秒、ループ回数8でインスタンス１２個起動。
    
  • -> エラー戻りはなし。
    
  • -> サーバ側の"Request was aborted ..."もなし。
    
  • -> しかし、いくつか結果が返ってこなかった。
    
• ※１リクエストの処理を１秒未満にすると、順調にスケールするようです。

PDF生成実験

事前にあっため処理を行うと、インスタンス数が増えた分は有効。ただし、処理時間は1分15秒(インスタンス4個）が1分（インスタンス9個）になる程度。インスタンス9個でも主に稼動しているのは4個であった。（1タスク10ページ、total=700ページ）。
あっためても実質４つしか実行されないのは、この絵のなかのリクエストキューに実行単位の境界があって、その境界を越えて実行することができないからではないかと推測している。（By WdWeaver)

---

実験２：あっためてからPDF生成

• 1タスク50ページの処理は重いせいか、1分少々で処理完了する場合もあったが、4分くらいかかることもあり、不安定。
  
• 1タスクの負荷を減らして10ページ程度とすると、処理時間が安定した。
  
• precompilation設定は有効と思えるが、1タスク50ページの条件で試したため誤差の範囲かもしれない。論理的には有効のはず。。。
• あっため処理30秒では不十分。60秒はすべき。もう少しあっため時間を延ばした場合の実験要。
  

• JMeterで、Warmerサーブレット(900msスリープ処理)を30秒(スレッド数30、ループ回数8)を実行した後、大量ページPDF生成処理を行う。
  
  • -> あっため処理をしながらPDF生成処理を行った場合、"Request was aborted ..."ログが多発した。
    

---

• 1タスク50ページ、total=700ページを実行(タスク数14個)
  
  • 実行時間 : 3分54秒
    
  • インスタンス数 : 3個
    
  • "Request was aborted ..."ログ : 51件
    
• 同じ条件で、precompilation設定を行って実行する。
  
  • 実行時間 : 2分38秒
    
  • インスタンス数 : 7個
    
  • "Request was aborted ..."ログ : 25件
    
• 1タスク10ページにし、total=700ページを実行(タスク数70個)(precompilation設定有効)
  
  • 実行時間 : 1分8秒
    
  • インスタンス数 : 6個
    
    • メインに実行しているインスタンスは4個で、残り2個は1処理と3処理。
      
  • "Request was aborted ..."ログ : 122件
    
• 1タスク10ページの上記条件で、あっため処理をしない場合
  
  • 実行時間 : 1分15秒
    
  • インスタンス数 : 4個
    
  • "Request was aborted ..."ログ : 123件
    
• また1タスク10ページの上記条件で、あっため処理を60秒行った場合
  
  • 実行時間 : 1分00秒
    
  • インスタンス数 : 9個
    
  • "Request was aborted ..."ログ : 88件

ちなみに
1タスク10ページ、total=1000ページを実行(タスク数100個)(あっため処理30秒)

• 実行時間 : 1分42秒
  
• インスタンス数 : 6個
  
• "Request was aborted ..."ログ : 166件