Tomcat 7/Java 7 で Java EE 風の Web アプリケーション (Hibernate 4+Spring+Quartz+JSF+Facelets+Richfaces) のいくつか (約 15) のインスタンスを実行すると、奇妙ではあるが重大な問題が発生します。
システムは正常に動作しますが、アプリケーションのすべてのインスタンスが同時に大幅に変化した後、突然応答時間が長くなります。基本的にアプリケーションは引き続き動作しますが、応答時間は約 3 倍長くなります。
これは、2 つの例のインスタンスの 2 つの特定の短いワークフロー/アクション (ログイン、セミナーのリストへのアクセス、このリストの ajax 更新、ログアウト。下の行は ajax 更新の要求時間のみ) の応答時間を示す 2 つの図です。アプリケーションの:
ご覧のとおり、アプリケーションの両方のインスタンスがまったく同時に「爆発」し、低速のままです。サーバーを再起動すると、すべてが正常に戻ります。アプリケーションのすべてのインスタンスが同時に「爆発」します。
セッション データをデータベースに保存し、これをクラスタリングに使用します。セッションのサイズと数を確認したところ、どちらもかなり低くなっています (つまり、他のアプリケーションを使用する他のサーバーでは、より多くのセッションが存在することがあります)。クラスター内の他の Tomcat は通常、さらに数時間高速のままであり、このランダムな時間が経過すると、それも「停止」します。jconsole でヒープ サイズを確認したところ、メイン ヒープは 2.5 ～ 1 GB のサイズのままでした。db 接続プールは基本的に空き接続とスレッド プールでいっぱいです。最大ヒープ サイズは 5 GB で、十分な perm gen スペースも利用できます。負荷は特に高くありません。メイン CPU の負荷は約 5% です。サーバーはスワップしません。問題が同じままである VM にアプリケーションを追加でデプロイしたため、ハードウェアの問題でもありません。
もうどこを見ればいいのかわかりません。アイデアがありません。誰かがどこを見るべきか考えていますか?
2013-02-21 更新: 新しいデータ!
アプリケーションにさらに 2 つのタイミング トレースを追加しました。測定に関しては、監視システムは 2 つのタスクを実行するサーブレットを呼び出し、サーバー上でそれぞれの実行時間を測定し、応答としてかかった時間を書き込みます。これらの値は、監視システムによって記録されます。
興味深い新事実がいくつかあります。アプリケーションのホット再デプロイにより、現在の Tomcat 上のこの単一のインスタンスが狂ってしまいます。これは生の CPU 計算パフォーマンスにも影響するようです (以下を参照)。この個別コンテキスト爆発は、ランダムに発生する全体コンテキスト爆発とは異なります。
いくつかのデータについて：
最初に個々の行:
- 水色は、クライアントで測定された小さなワークフロー (詳細は上記を参照) の合計実行時間です。
- 赤は水色の「一部」であり、クライアントで測定された、そのワークフローの特別なステップを実行するのにかかった時間です
- ダークブルーはアプリケーションで測定され、Hibernate を介して DB からエンティティのリストを読み取り、そのリストを反復処理して、遅延コレクションと遅延エンティティを取得します。
- Green は、浮動小数点演算と整数演算を使用する小さな CPU ベンチマークです。オブジェクトの割り当てがない限り、ゴミはありません。
爆発の個々の段階について説明します。各画像に 3 つの黒い点を付けました。最初のものは、多かれ少なかれ 1 つのアプリケーション インスタンスでの「小さな」爆発です。
この小さな爆発の後、「ビッグバン」が発生し、その Tomcat 上のすべてのアプリケーション インスタンスが爆発します (2 番目のドット)。この爆発はすべての高レベル操作 (リクエスト処理、DB アクセス) に影響しますが、CPU ベンチマークには影響しないことに注意してください。両方のシステムで低いままです。
その後、context.xml ファイルに触れて、Inst1 をホット再デプロイしました。先に述べたように、このインスタンスは爆発から完全に破壊されています (水色の線はチャートから外れています - 約 18 秒の位置にあります)。a) この再デプロイは Inst2 にまったく影響を与えず、b) Inst1 の raw DB アクセスも影響を受けないことに注意してください。ただし、CPU が突然遅くなったように見えます! . これはクレイジーだと私は言います。
更新の更新 Tomcat のリーク防止リスナーは、アプリケーションがアンデプロイされたときに、古い ThreadLocals または Threads について泣き言を言いません。明らかにクリーンアップの問題があるようですが (これはビッグバンに直接関係していないと思います)、Tomcat にはヒントがありません。
2013-02-25 更新: アプリケーション環境と Quartz スケジュール
アプリケーション環境はあまり洗練されていません。ネットワーク コンポーネントは別として (私はそれらについて十分に知りません)、基本的に 1 つのアプリケーション サーバー (Linux) と 2 つのデータベース サーバー (MySQL 5 および MSSQL 2008) があります。主な負荷は MSSQL サーバー上にあり、もう 1 つは単にセッションを格納する場所として機能します。
アプリケーション サーバーは、2 つの Tomcat 間のロード バランサーとして Apache を実行します。したがって、同じハードウェア (2 つの Tomcatインスタンス) で実行されている 2 つの JVM があります。この構成は、アプリケーション サーバーがアプリケーションを問題なく実行できるため (何年も前から) 負荷を実際に分散するためではなく、ダウンタイムなしで小さなアプリケーションの更新を可能にするために使用します。問題の Web アプリケーションは、Tomcat ごとに約 15 のコンテキストで、さまざまな顧客用の個別のコンテキストとしてデプロイされます。(私の投稿では、「インスタンス」と「コンテキスト」を混同しているようです。ここオフィスでは、それらはしばしば同義語として使用され、通常、同僚が話していることを魔法のように知っています。悪い、本当に申し訳ありません。)
より良い表現で状況を明確にするために、私が投稿した図は、同じ JVM 上の同じアプリケーションの 2 つの異なるコンテキストの応答時間を示しています。ビッグバンは 1 つの JVM のすべてのコンテキストに影響しますが、他の JVM では発生しません (Tomcat が爆発する順序はランダムです)。ホット再デプロイ後、1 つの Tomcat インスタンスの 1 つのコンテキストが異常になります (そのコンテキストの CPU が一見遅くなるなど、おかしな副作用がすべて発生します)。
システム全体の負荷はかなり低いです。これは、約 30 人のアクティブ ユーザーが同時に使用する、社内のコア ビジネス関連のソフトウェアです。アプリケーション固有のリクエスト (サーバー タッチ) は現在、1 分あたり約 130 です。単一のリクエストの数は少ないですが、リクエスト自体がデータベースに対して数百回の選択を必要とすることが多いため、かなり高価です。しかし、通常はすべてが完全に受け入れられます。アプリケーションは、大規模な無限キャッシュも作成しません。一部のルックアップ データはキャッシュされますが、短時間だけです。
上記で、アプリケーションを実行できるサーバーは数年間問題なく動作すると書きました。問題を見つける最善の方法は、最初に問題が発生した時期を正確に把握し、この期間に何が変更されたか (アプリケーション自体、関連するライブラリまたはインフラストラクチャ) を確認することであることはわかっていますが、問題は次のとおりです。問題が最初に発生した時期がわからないということです。その準最適な (存在しないという意味での) アプリケーション監視と呼びましょう... :-/
一部の側面を除外しましたが、アプリケーションは過去数か月の間に数回更新されたため、古いバージョンを単純に展開することはできません。機能変更以外の最大の更新は、JSP から Facelets への切り替えです。それでも、「何か」がすべての問題の原因であるに違いありませんが、たとえば Facelets が純粋な DB クエリ時間に影響を与える理由はわかりません。
石英
Quartz のスケジュールについては、合計 8 つのジョブがあります。それらのほとんどは 1 日に 1 回だけ実行され、大量のデータの同期を処理する必要があります (「ビッグ データが大きい」のように「大きい」ということは絶対にありません。平均的なユーザーが通常の日常業務で見ている以上のものです)。ただし、これらのジョブはもちろん夜間に実行され、問題は日中に発生します。ここでは詳細な仕事のリストは省略します (有益であれば、もちろん詳細を提供できます)。ジョブのソース コードは、過去数か月間変更されていません。爆発がジョブと一致するかどうかは既に確認しましたが、結果はせいぜい決定的ではありません. 実際には一致していないと思いますが、毎分実行されるジョブがいくつかあるため、まだ除外することはできません. 私の意見では、毎分実行される実際のジョブはかなり軽量です。
ただし、現在、個々のジョブ実行のログを有効にして、各ジョブ実行の開始と終了のタイムスタンプを正確に確認できるようにしています。おそらく、これはより多くの洞察を提供します。
2013 年 2 月 28 日更新: JSF のフェーズとタイミング
JSF phae リスナーを手動でアプリケーションに追加しました。サンプル呼び出し (ajax 更新) を実行したところ、これが得られたものです (左: 通常実行中の Tomcat インスタンス、右: ビッグバン後の Tomcat インスタンス - 数値は両方の Tomcat からほぼ同時に取得され、ミリ秒単位です):
- RESTORE_VIEW: 17 対 46
- APPLY_REQUEST_VALUES: 170 対 486
- PROCESS_VALIDATIONS: 78 対 321
- UPDATE_MODEL_VALUES: 75 対 307
- RENDER_RESPONSE: 1059 対 4162
ajax リフレッシュ自体は、検索フォームとその検索結果に属します。また、アプリケーションの最も外側の要求フィルターと Web フローがその作業を開始する間に別の遅延があります。Web フローのFlowExecutionListenerAdapter特定のフェーズでかかった時間を測定する があります。このリスナーは、展開されていない Tomcat での完全な要求の合計 1632 ミリ秒のうち、「送信された要求」(私が知る限り、最初の Web フロー イベント) に対して 1405 ミリ秒を報告するため、約 200 ミリ秒のオーバーヘッドを見積もっています。
しかし、爆発した Tomcat では、送信されたリクエストに対して 5332 ミリ秒 (すべての JSF フェーズがその 5 秒で発生することを意味します) が報告され、合計リクエスト時間は 7105 ミリ秒です。したがって、送信された Web フローのリクエスト以外のすべてに対して、最大で約 2 秒のオーバーヘッドが発生します。 .
私の測定フィルターの下には、フィルターチェーンが含まれていますorg.ajax4jsf.webapp.BaseFilter、Spring サーブレットが呼び出されます。
2013-06-05 更新: ここ数週間のすべての出来事
小規模でかなり遅い更新です...アプリケーションのパフォーマンスはしばらくたってもまだ悪く、動作は不安定なままです. プロファイリングはまだあまり役に立ちませんでした。分析が難しい膨大な量のデータが生成されただけです。(実稼働システムのパフォーマンス データを調べたり、プロファイリングしたりしてみてください... ため息) いくつかのテスト (ソフトウェアの特定の部分を切り取る、他のアプリケーションをアンデプロイするなど) を実施したところ、実際にはアプリケーション全体に影響するいくつかの改善がありました。私たちのデフォルトのフラッシュモードは でEntityManagerありAUTO、ビューのレンダリング中に、フラッシュが必要かどうかのチェックを常に含めて、多くのフェッチと選択が発行されます。
そこで、フラッシュ モードをCOMMITduring に設定する JSF フェーズ リスナーを作成しましRENDER_RESPONSEた。これにより、全体的なパフォーマンスが大幅に向上しましたそして、問題をいくらか軽減したようです。
しかし、私たちのアプリケーション監視は、一部の tomcat インスタンスの一部のコンテキストで、完全に常軌を逸した結果とパフォーマンスをもたらし続けています。1 秒以内に完了するはずのアクション (実際には展開後に完了) に 4 秒以上かかるアクションのように。(これらの数値はブラウザーの手動タイミングでサポートされているため、問題を引き起こすのは監視ではありません)。
たとえば、次の図を参照してください。
この図は、同じコンテキスト (同じデータベース、同じ構成、同じ jar を意味する) を実行している 2 つの tomcat インスタンスを示しています。ここでも青い線は、純粋な DB 読み取り操作 (エンティティのリストをフェッチし、それらを反復処理し、コレクションと関連データを遅延フェッチする) にかかった時間です。青緑色の線と赤い線は、それぞれいくつかのビューをレンダリングし、ajax の更新を行うことによって測定されます。青緑色と赤色の 2 つのリクエストによってレンダリングされたデータは、青色の線でクエリされたものとほとんど同じです。
インスタンス 1 の 0700 付近 (右) では、純粋な DB 時間の大幅な増加があり、実際のレンダリング応答時間にも影響しているように見えますが、Tomcat 1 のみです。両方の tomcat が同じ物理ハードウェア上で実行されているサーバーまたはネットワーク。Java ドメインのソフトウェアの問題である必要があります。
前回のテスト中に興味深いことがわかりました。すべての応答に「X-Powered-By: JSF/1.2, JSF/1.2」というヘッダーが含まれています。一部 (WebFlow によって生成されるリダイレクト応答) には、「JSF/1.2」が 3 回含まれています。
これらのヘッダーを設定するコード部分をたどりましたが、このヘッダーが初めて設定されたときは、このスタックが原因です。
... at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)
at org.springframework.faces.webflow.FlowFacesContext.newInstance(FlowFacesContext.java:81)
at org.springframework.faces.webflow.FlowFacesContextLifecycleListener.requestSubmitted(FlowFacesContextLifecycleListener.java:37)
at org.springframework.webflow.engine.impl.FlowExecutionListeners.fireRequestSubmitted(FlowExecutionListeners.java:89)
at org.springframework.webflow.engine.impl.FlowExecutionImpl.resume(FlowExecutionImpl.java:255)
at org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:169)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:183)
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
... several thousands ;) more
このヘッダーが 2 回目に設定される
at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)
at org.springframework.faces.webflow.FacesContextHelper.getFacesContext(FacesContextHelper.java:46)
at org.springframework.faces.richfaces.RichFacesAjaxHandler.isAjaxRequestInternal(RichFacesAjaxHandler.java:55)
at org.springframework.js.ajax.AbstractAjaxHandler.isAjaxRequest(AbstractAjaxHandler.java:19)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.createServletExternalContext(FlowHandlerAdapter.java:216)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:182)
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
これが問題を示しているかどうかはわかりませんが、サーバーで実行されている他のアプリケーションではこれに気付かなかったので、これはいくつかのヒントになるかもしれません. そのフレームワーク コードが何をしているのか、私にはまったくわかりません (確かに、私はまだそれに飛び込んでいませんでした)...おそらく誰かが考えを持っていますか? それとも行き止まりに陥っていますか？
付録
私の CPU ベンチマーク コードは、Math.tan を計算し、結果の値を使用してサーブレット インスタンス (揮発性/同期化されていない) のいくつかのフィールドを変更し、次にいくつかの生の整数計算を実行するループで構成されています。これはそれほど洗練されたものではありませんが、まあ... チャートに何かを示しているようですが、それが何を示しているかはわかりません。HotSpot がすべての貴重なコードを最適化するのを防ぐために、フィールドの更新を行います ;)
long time2 = System.nanoTime();
for (int i = 0; i < 5000000; i++) {
double tan = Math.tan(i);
if (tan < 0) {
this.l1++;
} else {
this.l2++;
}
}
for (int i = 1; i < 7500; i++) {
int n = i;
while (n != 1) {
this.steps++;
if (n % 2 == 0) {
n /= 2;
} else {
n = n * 3 + 1;
}
}
}
// This execution time is written to the client.
time2 = System.nanoTime() - time2;
