Tomcat プロセスの CPU 使用率が高い場合のトラブルシューティング記録を記録する

この記事では主にTomcatプロセスを記録し、TCP接続が多すぎることによるCPU使用率の過剰のトラブルシューティング記録を示します。

問題の説明

Linux では、Tomcat Web サービスの CPU 使用率が非常に高く、トップには 200% を超える値が表示されます。リクエストに応答できませんでした。再起動を繰り返しても同じ現象が起こります。

トラブルシューティング

1. プロセス情報を取得する

jvm プロセスは、jdk が提供する jps コマンドを通じて簡単に確認できます。

jps-pid

2. jstack情報を表示する

jstack pid

待機ロック状態のlog4jスレッドブロックが多数あることが判明

org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=12, line=201 (コンパイルされたフレーム)

関連情報を検索したところ、log4j 1.x バージョンにデッドロックの問題があることがわかりました。

問題が見つかったので、log4j の設定を調整し、エラーレベルのログのみをオンにして、Tomcat を再起動しました。このとき、スタック内のブロックスレッドは消えますが、プロセスの CPU 使用率は依然として高いままです。

3. さらなる調査

各スレッドの CPU 使用率を分析するには、Java プロセス内の各スレッドの CPU 使用率を計算する、偉大な神様が寄稿したスクリプトを導入する必要があります。

#!/bin/bash

タイプセット top=${1:-10}
タイプセット pid=${2:-$(pgrep -u $USER java)}
タイプセット tmp_file=/tmp/java_${pid}_$$.trace

$JAVA_HOME/bin/jstack $pid > $tmp_file
ps H -eo ユーザー、pid、ppid、tid、時間、%cpu --sort=%cpu --no-headers\
    | 末尾 -$top\
    | awk -v "pid=$pid" '$2==pid{print $4"\t"$6}'\
    | 行を読み取り中;
する
    タイプセット nid=$(echo "$line"|awk '{printf("0x%x",$1)}')
    タイプセット cpu=$(echo "$line"|awk '{print $2}')
    awk -v "cpu=$cpu" '/nid='"$nid"'/,/^$/{print $0"\t"(isF++?"":"cpu="cpu"%");}' $tmp_file
終わり

rm -f $tmp_file

スクリプトの適用範囲

ps の %CPU 統計は /proc/stat から取得されるため、このデータはリアルタイムではなく、OS 更新の頻度 (通常は 1 秒) に依存します。このため、表示される統計情報は jstack の情報と一致しません。ただし、この情報は、少数のスレッドからの継続的な負荷によって発生する問題のトラブルシューティングに非常に役立ちます。なぜなら、これらの固定された少数のスレッドは CPU リソースを消費し続けるからです。時間差があったとしても、いずれにせよこれらのスレッドによって発生します。

このスクリプトに加えて、より簡単な方法は、プロセスIDを見つけて、次のコマンドを使用してプロセス内の各スレッドのリソース使用量を表示することです。

トップ -H -p pid

ここから pid (スレッド ID) を取得し、16 進数に変換して、スタック情報内のオブジェクトのスレッド情報を見つけます。

上記の方法により、tomcat プロセスに対応するスレッドの累積 CPU 使用率は約 80% であることがわかります。これは、top によって示される 200% 以上よりもはるかに小さい値です。

これは、CPU を長時間占有するスレッドが存在せず、CPU を集中的に使用する短期的な計算が多数存在することを意味します。そこで、JVM メモリ不足と頻繁な GC が原因であると疑いました。

jstat -gc pid

jvm のメモリ使用量は異常ではないものの、gc 回数が大幅に増加していることがわかりました。

メモリを確認した後、ネットワークプログラムなので、さらにネットワーク接続を確認します。

4. 問題の場所

tomcat の該当ポートの TCP 接続を照会すると、多数の EASTABLISH 接続とその他の状態の接続がいくつかあり、合計で 400 を超えることがわかります。

netstat -anp | grep ポート

これらの接続のソースをさらに確認すると、Tomcat サービスのアプリケーション側に多数のバックグラウンドスレッドがあり、それがサービスを頻繁にポーリングしていたため、サービスの Tomcat 接続数がいっぱいになり、リクエストの受信を継続できなくなっていたことが判明しました。

Netstat ステータスの説明:

LISTEN: リモートTCPポートからの接続要求をリッスンする
SYN-SENT: 接続要求を送信し、一致する接続要求を待ちます（このようなステータスパケットが多数ある場合は、感染していないかどうかを確認します）
SYN-RECEIVED: 接続要求を受信・送信後、相手側が接続要求を確認するのを待つ（この状態が多い場合はフラッディングが発生していると推定される）
ESTABLISHED: オープン接続を表します
FIN-WAIT-1: リモートTCP接続中断要求、または以前の接続中断要求の確認を待機中
FIN-WAIT-2: リモートTCPからの接続中断要求を待機中
CLOSE-WAIT: ローカルユーザーからの接続中断要求を待機中
CLOSING: リモートTCPが接続が切断されたことを確認するのを待機しています
LAST-ACK: リモート TCP に送信された元の接続中断要求の確認を待機しています (これは良いことではありません。この項目が表示された場合は、攻撃されたかどうかを確認してください)
TIME-WAIT: リモートTCPが接続終了要求の確認を受信するまで十分な時間を待機します。
CLOSED: 接続ステータスなし

5. 根本原因分析

直接的なトリガー原因は、クライアントポーリング、要求例外、および継続的なポーリングです。クライアント上の新しいバックグラウンドスレッドがポーリングチームに引き続き参加し、最終的にサーバーの Tomcat 接続がいっぱいになります。

Tomcat プロセスの CPU 使用率が高い問題の記録に関するこの記事はこれで終わりです。Tomcat プロセスの CPU 使用率が高い問題に関する関連コンテンツの詳細については、123WORDPRESS.COM の以前の記事を検索するか、次の関連記事を引き続き参照してください。今後とも 123WORDPRESS.COM をよろしくお願いいたします。

以下もご興味があるかもしれません: