【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 」が出る原因を考えてみた。

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

実験１）　同じvmであればEnQueueしなおしてすぐに終了させるようにするとどうなるか
実験２）　新規の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ごとだと仮定１（複数のTASKが同じVM（マシン）で実行される）は起こらないので、実験１は行わない。実験２のみ行う。
  
• 以上の条件で、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回
    
    • 実験２)新しいインスタンスの場合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ログが出力され、リトライされているようだ。
    
  • 仮定２）cold startの場合はQueueに再度処理を登録し直して自分は終了する、という方法は、しない場合と比べて速くなった。
    
    • cold startの場合は処理時間が10秒を超えてリトライされていたためと推測される。
      
  • インスタンスは4～5個立ち上がるが、同時に処理を行うのは最大4個。
    
  • 1タスクあたりの処理時間が4秒～6秒以下の場合、Taskの同時処理数が4個で安定する。
    10秒近くなるとTask同時処理数が減ってくるため、総処理時間が遅くなる。
    
  • 1タスクあたりの処理時間を4秒～6秒とすると、総処理時間が最も速くなった。

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