Confluence Data Center を利用していると、サーバーが高負荷になる場合が有ります。高負荷時に原因を調査する方法をまとめました。

プロセスを確認する

Confluence をインストールしているサーバーが高負荷になっていても、必ずしも Confluence が原因ではない事も有ります。どのプロセスが CPU リソースを利用しているかを確認しましょう。Linux の場合は、Top コマンドで確認できます。下記の例では、CPU が 73% 利用されていて最も CPU を利用しているが Confluence で CPU 利用率 300% となっています。コア数が多い場合はこの様に 100% を超えます。下記の様に、Confluence のプロセスが他のプロセスに比べて CPUの利用率が多い場合は、Confluence が原因でサーバーが高負荷になっているので、Confluence の調査をします。

Confluence の調査

このドキュメントでは Confluence が高負荷になっている場合に原因を特定するのに役立つ方法をご紹介します。どれが効果を発揮するかはケースバイケースです。メモリーが不足している場合は GC ログを確認すれば解りますし、ユーザーマクロの処理が重い場合など特定のページのレンダリングに CPU リソースが利用されている場合は、アプリケーション・ログを確認すれば解ります。こちらは、両方を実施する事をお薦めします。スレッドダンプは手間がかかるので GC ログ、アプリケーション・ログを見ても原因を特定できない場合に実施する事をお薦めします。

GC ログを確認する

GC というのは Garbage Collector の略で、ヒープメモリー中の不要なオブジェクトを削除して作業用の領域を確保する処理です。Java の場合はメモリー不足の場合など定期的にこれが実行されます。Confluence の場合、以下のディレクトリに gc-yyyy-MM-dd_hh_mm_ss.log という形式で GC ログが出力されます。

これを分析する事で、メモリーの状況を確認する事ができます。GC ログの分析は、無料で利用可能な GCViewer が便利です。

GC が定期的に実施された結果、メモリーの使用量は下記の様に常に増減を繰り返します。下記はヒープメモリーが 4GB で、利用量は 1.5GB ～ 3GB の間で増減を繰り返しています。これが理想的な状態です。GC が働いた時に 1GB 以下まで利用量が下がっています。ヒープ全体の 1/3 以下まで下がる状態が推奨されています。

Open

上記のグラフは GC View の表示項目のうち以下の項目を表示しています。

• Full GC Lines

• Total Heap

• Used Heap

Open

下記の例は極端な例ですが、このような状態の場合は、CPU高負荷の原因は メモリーの不足による GC 処理という事になります。この例ではヒープメモリーが 384MB しか有りません。GC を実施しても空きメモリーを確保できないため、GC を小刻みに繰り返します。黒い線は Full GC という特殊な GC で、Java の処理を全て停止して、メモリー全体スキャンして空き領域を確保しようとします。この Full GC が起きると、Confluence は無応答な状態となり CPU の負荷も高くなります。大規模なシステムですと、16GB のヒープを確保してもメモリーが足りず、Full GC を繰り返す事も有ります。

アプリケーション・ログを確認する

Confluence のベースになっている Tomcat には、処理時間がしきい値を超えている「遅い」処理が有った場合に警告する仕組みが有ります。デフォルトでは、60秒 になっています。しきい値を超えている場合は以下のファイルに警告情報が出力されます。

また、バージョンが古い場合は、以下のファイルとなります。

に以下の様な、 ログ傾向

上記は、Atlasisan のドキュメント　Confluence Unresponsive due to stuck Workbox Notifications threads の抜粋です。上記は https://example.atlassian.com/rest/mywork/latest/status/notification/count?_=1541562126288 という URL へのリクエストの処理が、60秒を超えているという意味です。Confluence のレスポンスは数秒が通常ですので、60秒を超えているのは異常と言えます。CPU の負荷が高い場合で、GC が正常だった場合、上記の様な特定の処理が CPU リソースを消費している事が有ります。ご注意頂きたいのは、CPU の負荷が高いために遅くなっている場合も有ります。最初に警告された処理に原因があると考えます。以下が、Confluence で CPU を消費するユーザーのリクエストの例です。

• マクロを多用したページの閲覧。

  • 通常の利用では発生しませんが、例えば User List マクロで confluence-users を指定しますと、全ユーザーの一覧を出力する事になるので、ユーザー数が多い場合は重くなります。

• 子ページ、添付ファイルが大量に有るページを子ページ、添付ファイルも含めてコピーする場合。

• スクリプトで大量データの検索などの処理に時間を要する REST API の要求を連続して実行する場合。

• スペースのエクスポート

スレッドダンプを確認する

上記でも解らない場合はスレッドダンプを取得します。スレッドダンプは以下のコマンドで取得できます。

Confluence の プロセス ID は、ps コマンドで取得できます。

上記の実行例には

が2つ有りますが、２つ目は 最後の方に synchrony.core と表示されているので 共同編集のプロセスです。本体の プロセス IDは 2715 です。このプロセス ID を元に kill コマンドを実行します。-3 を付ければ、Confluence が停止する事は有りません。実行すると、

にスレッドダンプが出力されます。

下記のコマンドで、スレッド別の CPU 利用状況を調べます。(下記は実行結果を抜粋しています）

上記の例では、スレッド 3206 が 71.4%CPU を利用している事が解ります。3206 は 16進数では、c86 なのでスレッドダンプから nid=0xc86 を探します。今回は、下記のコンパイラースレッドが CPU を消費している事が解りました。Confluence の起動処理中にデータを取得した事が原因だと考えられます。

実際の例では、当該スレッドが下記の様なロジックの実行の場合がほとんどです。この情報を元に調査を進めます。