2016-10-21 11 views
6

アプリエンジンで実行されているアプリからの周期的な、しかし一貫した待ち時間スパイクに気付きました。最初はネットワークが遅いかもしれないと思っていましたが、アプリの統計ではそうはならないことが確認されました。低負荷でのアプリエンジン一貫性のある待ち時間の急上昇

私は現在、私は次のように使用している、のSDKの古いバージョンと新しいバージョンを使用して、待ち時間のスパイクを再現することができました:

  • のApp Engine SDK:1.9.42
  • のGoogleクラウドエンドポイント:1.9.42
  • 客観化:5.1.13
  • Appstatsの(デバッグネットワークの待ち時間に)

だからアプリの利用状況はかなりlでありますOW、最後の30日間で、私は0.04の要求の下で、一般的に第二だ:

ほとんどの作業は、同様に1つのインスタンスで行われ

requests per second

enter image description here

は、ほとんどの操作待ち時間が下にもあります非常に多くのリクエストが10〜30倍長くなります。

Latency density distribution

5% of requests take 23 seconds or longer...

だから私はそれだけでネットワークレイテンシでなければなりません考え出したが、遅くなり、操作のすべてのappstatはこれを反証。 Datastoreとネットワークは常に信頼性が高く評価されています。ここでは30秒を引き継ぐ遅い要求の解剖学は、次のとおりです。ハイレベルで enter image description here

私のコードはかなりつまらないです:それは簡単です。ここ

app stats of operation taking 31 seconds

は、通常のリクエストの解剖学的構造がありますいくつかのネットワークコールを行い、クラウドデータストアからデータをセーブ/リードするapi。全体のソースはgithub hereにあります。アプリは、単一の自動スケーリングアプリエンジンインスタンスで実行され、ウォームアップされます。先月doesntのオーバー

CPUの使用率は、刺激的なものを示しているように見えるのいずれか: enter image description here

それも、コードかかわらず、でも迅速な操作のために、時間の巨大な割合は、CPUに費やされていることを確認するために本当に奇妙ですいくつかのオブジェクトを作成し、永続させ、JSONを返します。私はCPUがパフォーマンスを定期的に低下させる可能性のある別のアプリによってCPUがアプリケーションエンジンのインスタンスに固定されているのかどうか疑問に思っています。

マイappengine.xmlの設定は次のようになります。

<?xml version="1.0" encoding="utf-8"?> 
<appengine-web-app xmlns="http://appengine.google.com/ns/1.0"> 
    <application>sauce-sync</application> 
    <version>1</version> 
    <threadsafe>true</threadsafe> 
    <automatic-scaling> 
     <!-- always keep an instance up in order to keep startup time low--> 
     <min-idle-instances>1</min-idle-instances> 
    </automatic-scaling> 
</appengine-web-app> 

そして、私のweb.xmlは次のようになります。

<web-app xmlns="http://java.sun.com/xml/ns/javaee" version="2.5"> 
    <servlet> 
     <servlet-name>SystemServiceServlet</servlet-name> 
     <servlet-class>com.google.api.server.spi.SystemServiceServlet</servlet-class> 
     <init-param> 
      <param-name>services</param-name> 
      <param-value>com.sauce.sync.SauceSyncEndpoint</param-value> 
     </init-param> 
    </servlet> 
    <servlet-mapping> 
     <servlet-name>SystemServiceServlet</servlet-name> 
     <url-pattern>/_ah/spi/*</url-pattern> 
    </servlet-mapping> 

    <!--reaper--> 
    <servlet> 
     <servlet-name>reapercron</servlet-name> 
     <servlet-class>com.sauce.sync.reaper.ReaperCronServlet</servlet-class> 
    </servlet> 
    <servlet-mapping> 
     <servlet-name>reapercron</servlet-name> 
     <url-pattern>/reapercron</url-pattern> 
    </servlet-mapping> 

    <servlet> 
     <servlet-name>reaper</servlet-name> 
     <servlet-class>com.sauce.sync.reaper.ReaperServlet</servlet-class> 
    </servlet> 
    <servlet-mapping> 
     <servlet-name>reaper</servlet-name> 
     <url-pattern>/reaper</url-pattern> 
    </servlet-mapping> 


    <welcome-file-list> 
     <welcome-file>index.html</welcome-file> 
    </welcome-file-list> 

    <filter> 
     <filter-name>ObjectifyFilter</filter-name> 
     <filter-class>com.googlecode.objectify.ObjectifyFilter</filter-class> 
    </filter> 
    <filter-mapping> 
     <filter-name>ObjectifyFilter</filter-name> 
     <url-pattern>/*</url-pattern> 
    </filter-mapping> 
</web-app> 

TLDR私は完全にこだわっていると私はどのようにわからないんだけどデバッグしたり修正したりすることができます。これは、アプリエンジン上の小規模なアプリにとってはいつものようにこれがビジネスだと思っています。

私のアプリがいくつかの二段のハードウェアを実行しているか、多くのリソースを消費しているアプリケーションを実行していることを期待しながら、常駐インスタンスをオフにすることを考えています。誰もが同様のパフォーマンスの問題にぶつかるか、アプリのプロファイルを作成する追加の方法を知っていますか?

EDIT:

私は1つの常駐インスタンス上で実行して試してみたが、私はまた、結果なしで2-4 per this questionで同時要求を設定しようとしました。ログとappstatsは、私のコードが最初に実行されるのを待って過度の時間が費やされたことを確認します。ここでは、コードの最初の行が実行される25秒前に要求がありますが、この時点でどのエンドポイント/アプリケーションエンジンが実行しているかはわかりません。

25 seconds before my code is run

再び負荷がまだ低いと、この要求は暖めインスタンス上です。

EDIT 2:

は、App Engineの+のエンドポイントがmin-idle-instancesセットとよく遊ぶdoesntの何らかの理由のように思えます。デフォルトのアプリエンジン設定に戻すと問題が解決しました。

enter image description here

+0

が潜在的に関連しています(ただし、負荷がかかると見られます):http://stackoverflow.com/questions/37307461/what-c​​an-cause-high-variability-of-untraced-time-in-app-engine-requests –

+0

いくつのインスタンスが通常アクティブですか?最小アイドルインスタンスが1に設定されていても、新しいインスタンスの到着が遅れることはありません。 – BrettJ

+0

一般に1つのインスタンスで、インスタンス数を元のグラフにグラフを添付しました。私はあまりにも、たとえ寒さのインスタンスが起動し、要求を完了するためには30秒をはるかに短く取るものの、それを示すものではないとは思わない。レイテンシが高いため、追加のノードが起動する可能性が高いようです。また、遅いリクエストはすべて、最初のインスタンスで発生します。ローディングリクエストはこれらの遅いリクエストに設定されていません。 – sauce

答えて

3

私は答えを持っていないが、私はあなたにいくつかのデバッグのヒントを提供することができます。

Appstatsが正しく報告されている場合とされていない場合があります。ただし、ログメッセージにタイムスタンプが付きます。各RPC操作の後に&の前に記録してください。それはあなたにいくつかの洞察を与えるはずです。

30秒間はウォームアップ要求とよく似ていますが、これはログにはっきりとマークする必要があります。過去に私が見つけたことの1つは、トラフィックの少ないアプリケーション(直感的には)の常駐インスタンスを設定すると、多くの要求を低温のインスタンスにルーティングする傾向があることです。デフォルトの設定を使用し、毎分1回pingとエンドポイントにcronタスクを設定します。

+0

クラウドコンソールのアプリケーション統計、ロギング、およびGoogleのトレースツールは、確認されたすべてのRPCが一般的に非常に高速です。 'loading_request = 1'のいずれかの遅い要求は起こっていません。私はあなたの他の提案を見ていきますが、私は常駐インスタンスであまりにも手を加えて試してみることはできません。私はObjectifyを愛しています: – sauce

+0

@stickfigureウォームアップ要求であれば、RPCはトレースの最後に向かってクラスタ化されませんでした(インスタンスが起動した後に呼び出されるだけなので)? –

+0

実際には直感的ではありませんが、何らかの理由でデフォルト設定が一番うまく動作するのは、しばらくの間にリクエストを読み込まなければならない場合です。¯\\ _(ツ))/ – sauce

関連する問題