月曜日, 11月 23, 2009

【Google App Engine】 TaskQueueのスケーラビリティを阻害している原因について このエントリーを含むはてなブックマーク


Request was aborted after waiting too long が出る理由

 前記事の実行結果を見てもらえばわかるとおり、"Request was aborted after waiting too long・・"というエラーのせいで、処理が中断されてリトライが頻発しているものが多くある。これがTaskQueueのスケーラビリティを阻害しているのは間違いない。これは、queryの実行時間が10秒を超えると出るようである。(PDF生成処理Taskでは10秒を超えるものがあるのでtaskの経過時間というよりqueryの実行時間によるのだと思う。たぶん)
 別にquotaを上回るような処理を流したつもりはないのになぜ出るのか。
 この現象については、ココでも質問されているが、Googleからの返事はまだない。

total queue execution rateの定義

 Taskの実行時間が10秒を超えるとキャンセルされる、とはどこにも書いていないので、エラーメッセージにあるとおり、何かしらquotaを上回る処理があって、それが原因で待ちが発生して、これ以上待つのは無理だからキャンセルされた、というふうに理解していた。quotaといっても、ココにあるように、いろいろあるが、私は、total queue execution rateが一番あやしいと思っている。
 MLでJamesさんが自己レスしているが、total queue execution rate が 20 task invocations per second というのは、dequeueするtaskの数ではなく、処理可能なquery数ということらしい。つまり、taskqueueを使って処理できるのは最大20qps/sということ。これなら(納得はできないが)理解はできる。

 この件に関して、ありがたいことに、ひがさんからコメントいただいた。このあたりの話は、GAE Nightでいろいろ聞くことにしよう。

 あのwarningは、リクエスト処理中に後続のリクエストが来てqueueにつまれ10秒以内に処理されなかったときに発生します。

 つまり、AppEgnineは30秒ルール以外にも、負荷が集中するときには、10秒以内に処理しないければいけないという10秒ルールも存在するのです。

 10秒ルールを守ったとしても完璧にスケールするかはまた別の話ですが、今のAppEngineの能力を最も引き出せるということはいえると思います。


エラーが発生する原因

 「Request was aborted after waiting too long 」が出る原因を考えてみた。

 仮定1)同じインスタンス(同じVM上アプリ)に複数のリクエストが入ろうとして待たされている。
 仮定2)spin up(アプリケーションの起動)までに時間がかかるのが原因。例えば、cold start時には、まっさらなVMにクラスをロードする時間などが余分にかかる。それが加算される。
 
 これを突き止めるために、以下の実験をやってみた。

実験1) 同じvmであればEnQueueしなおしてすぐに終了させるようにするとどうなるか
実験2) 新規のvmhashの場合、一回目はすぐに終了させるとどうなるか



 同じVMであるかどうかは、こちらの記事にあるとおり、Runtime.getRuntime().hashCode()を比較することで判別するようにした。(memcacheを使ってhashcodeを管理する)

 そしたら、hashcodeが重なってた(下図)ので、こちらの記事のように、ServletContext+UUIDで判別するようにした。



実験結果


 前記事の全文検索アプリを使って実験した結果、以下のようになった。

  • 1タスク500件、一度に4タスク登録。(合計20タスク)
    • 全データ検索まで : 1分41秒
    • 1タスクの処理時間 : 5~7秒
    • ただし、初期起動の場合は8~9秒
    • RuntimeのhashCodeが同じでも、違うuuidが最初に起動する場合、8~9秒かかる。
    • "Request was aborted ..."が1回出現。
  • 起動チェックをRuntimeのhashCodeでなく、uuidで行う。
  • uuidごとだと仮定1(複数のTASKが同じVM(マシン)で実行される)は起こらないので、実験1は行わない。実験2のみ行う。
  • 以上の条件で、1タスク500件、一度に4タスク登録。(合計20タスク)
    • 全データ検索まで : 1分4秒
    • 1タスクの処理時間 : 6~7秒
    • 起動インスタンス : 4個
    • "Request was aborted ..."のWarningログは1回も出力されていない。
  • 1タスク500件、一度に8タスク登録。(合計20タスク)
    • 全データ検索まで : 1分6秒
    • 1タスクの処理時間 : 6~7秒
    • 起動インスタンス : 4個
    • "Request was aborted ..."のWarningログは1回も出力されていない。
  • 1タスク500件、一度に16タスク登録。(合計20タスク)
    • 全データ検索まで : 1分34秒
    • 1タスクの処理時間 : 6~7秒
    • 起動インスタンス : 5個
    • "Request was aborted ..."のWarningログは1回も出力されていない。
  • 1タスク1000件、一度に4タスク登録。(合計10タスク)
    • 最初にリクエストして約5分経過しても、1個のタスクも終了しない。
    • 新しいインスタンス起動 : 22回
      • 実験2)新しいインスタンスの場合QueueにTaskを登録し直してすぐに終了する、という処理は正常にできている。
    • "Request was aborted ..." : 18回
    • なぜかQueueのTaskが4個から9個に増えた。(プログラムバグ?)
  • TaskQueueの設定を変えてテスト。rate=10, bucket size=10に設定。
    • 4タスク : 1分4秒
    • 8タスク : 58秒
    • 16タスク : 1分12秒
      • 16タスクの場合のみ"Request was aborted ..."のWarningログが数件出力されている。
  • TaskQueueの設定を変えてテスト。rate=10, bucket size=20に設定。
    • 4タスク : 1分5秒
    • 8タスク : 1分
    • 16タスク : 1分22秒
      • 8,16タスクの場合"Request was aborted ..."のWarningログが数件出力されている。
  • 1タスクあたりの処理件数を変えてテスト。(TaskQueueの設定 : rate=10, bucket size=10、一度に4タスク登録)
    • 700件(合計15タスク) : 2分54秒
      • 1タスクの処理時間 : 8秒~10秒弱(10秒は超えていない)
      • "Request was aborted ..." : 4回
    • 600件(合計17タスク) : 1分57秒
      • 1タスクの処理時間 : 7秒~8秒
      • "Request was aborted ..." : 2回
    • 400件(合計25タスク) : 57秒
      • 1タスクの処理時間 : 4秒~6秒
      • "Request was aborted ..." : なし
    • 300件(合計34タスク) : 1分2秒
      • 1タスクの処理時間 : 4秒~5秒
      • "Request was aborted ..." : なし
    • 200件(合計50タスク) : 1分16秒
      • 1タスクの処理時間 : 2秒~3秒
      • "Request was aborted ..." : なし
  • まとめ
    • uuidごと(ServletContextごと)にcold startされている。
    • Taskの処理時間が10秒を過ぎると"Request was aborted ..."とWarningログが出力され、リトライされているようだ。
    • 仮定2)cold startの場合はQueueに再度処理を登録し直して自分は終了する、という方法は、しない場合と比べて速くなった。
      • cold startの場合は処理時間が10秒を超えてリトライされていたためと推測される。
    • インスタンスは4~5個立ち上がるが、同時に処理を行うのは最大4個。
    • 1タスクあたりの処理時間が4秒~6秒以下の場合、Taskの同時処理数が4個で安定する。
      10秒近くなるとTask同時処理数が減ってくるため、総処理時間が遅くなる。
    • 1タスクあたりの処理時間を4秒~6秒とすると、総処理時間が最も速くなった。


 エラーメッセージは出ないようになったが、相変わらずインスタンスの最大が4つというところが納得いかない。

1 件のコメント:

裕也 さんのコメント...

有益な情報をありがとうございます!

私はPythonなのですが、ちょうど同じ「Request was aborted ...」のエラーでTask Queueがリトライされて困っておりました。

まとめでも記載されている通りで、私のプログラムでも1タスクあたりの処理時間が短い方が、総処理時間が最も短くなりました!

本当に感謝です。ありがとうございました!

 
© 2006-2015 Virtual Technology
当サイトではGoogle Analyticsを使ってウェブサイトのトラフィック情報を収集しています。詳しくは、プライバシーポリシーを参照してください。