appengineのスケールアウトの結果を吟味した

#ajn3で披露したスケールアウトの様子について、リクエストの到着時刻を元にログを並べ直すと、面白い事実が分かってきた。（ちなみにappcfgでダウンロードするログにはこの到着時刻やcpu時間等が含まれないので非常に分析しづらい。)
テスト方法についても反省点があるので、ここにメモを残そうと思う。

分析に使っている結果シートはこちら
0.5秒待ちで、120件を一気に投げてみた結果はこちら

JMeterの挙動について

設定ミス、私自身もJMeterの設定について不勉強だったため、初期値として60thread,30request/secとして設定したJMeterの挙動が、期待するものとは違った。
まず、すべてのthreadは、スピンアップした直後にリクエストを送信していた。
したがって、60reqeustが当初appengine側に送信されていた。
また、各クライアントスレッドはレスポンス待ちを行うため、次回のリクエストまで1秒以上～10秒前後未満(最大、キューのタイムアウトまで)の待ちが発生する。
以上の状況から、リクエストの間隔が一定のレベルでかかるような状況を作ることができていなかった。
負荷のかかり方が、appengine側のスループットに依存する状況(スケールの状況に依存するってこと・・・)になってしまっているため、平均すると、リクエストは11.3req/sec程度に落ち着いていた。
大体スケールしたインスタンス数(13個)になってるので、ああ、なるほどなと。
テストの系にJMeterの挙動が含まれるような形になってしまっていたのは残念。

ただ、以降に記述するとおり、最初の1秒間に実行された60個のリクエストが興味深い結果を残してくれていた。

リクエストのキューについて

インスタンスを起動したリクエスト時刻以前のリクエストを同一インスタンスで処理するパターンと、起動したリクエスト以降のリクエストのみを処理するパターンが存在していた。
リクエストのキューはおそらく物理的に複数存在し、キューに複数のインスタンスがぶら下がるようになっていると考えられる。（要するにGDDの説明通りの構成ってことかな）
これは物理的な構成を考える根拠になりそうだ。
おそらく物理的に分割されているため、キューが別々になってしまったリクエストはキューをまたがったインスタンスへ移動することはできないのだろう。
ひとつのキューにぶら下がったインスタンスで処理しきれないリクエストがRequest was abortedにつながっているように思える。
具体的にはUUIDがb8418f11-f0a4-443e-b4d8-35cad8a2cc3cのインスタンスで、少なくともキューが
全て共用されていれば、このインスタンスでも起動時刻以前のリクエストを処理していないとおかしい。

リクエストキューの個数について

ひとつのリクエストのキューに対し、40件程度詰め込まれていることが事実としてある(リクエスト時刻を巻き戻って処理しているインスタンスのリクエスト合計がちょうどこれくらい)。実はこれがquotaとリソースの利用状況との関係になるのではないかと予想が立った。
GDDの説明だと、初期状態だと1つのフロントエンドに3つのAppEngineマシンがぶら下がっている構図だ。さて、40*3とは？120だ。ちょうどfreequotaのリクエストの秒間の上限に近い値となる。
もちろん、物理的な振り分け自体はこのようにならないと思うが、利用リソースの計算としてはここを目指した設定値ではないかと考えている。

キューの割り振りについて

1つのIPからのリクエストのテストであったため、多数のIPからアクセスされる状況については分からないが、上記のリクエストキューの個数と時刻をみると、フロントエンドから、単純にリクエスト40件程度ずつラウンドロビンをしているように見える。ただ、この結果を踏まえ、0.5秒待ち、120件のリクエストを一気に投げてみた結果から、キューのサイズは可変で、フロントエンドの負荷分散ももう少し高度なことをやっていそうなことがわかった。

リクエストキューの個数と失敗数の検証

上記から予想している40個というリクエストキューのサイズと、失敗数を検証してみたい。
60件のリクエストのうち、ひとつのキューにぶら下がりスケールしていると思われるインスタンスのUUIDを抜き出し、60件のリクエストのうち、処理できた件数を集計する。
1. 52f48031-6af2-487e-9809-84fb51adde63 .. 10件
2. 988cbe3a-1751-4a09-8faf-67f51f07e6c3 .. 9件
3. b3c1eb76-277b-4e17-b713-ea9d09a875e8 .. 7件
4. eda3152a-8445-478e-876c-1460b5ebd016 .. 5件
5. 514bd79b-1b19-429d-a383-e26382144fdd .. 4件
... 全部で35件。失敗した件数が5件なので、計算は合う。
リクエストとしての処理時間から逆算した処理可能数と比較すると、少し処理した数が多いが、処理時間はフロントエンドとの通信遅延なども入った値と考えるとつじつまあわせはできそうだ。

とりあえず今日はここまで