JBoss（+ MySQL等のRDBMS）で構成されたアプリケーションで「動作が重い」「メモリ使用率が上がったまま下がらない」といった障害が発生した際の、汎用的な調査コマンド集。特定のアプリケーション・テーブル名には依存しない形にまとめている。
前提
- アプリケーションサーバー：JBoss（EAP/AS系。GCログ・server.logのパスはインストール構成に依存するため、以下は一例）
- DBサーバー：MySQL（5.6系を想定した記法を含むが、考え方自体は5.7/8.0系でも流用可能）
- 障害調査は基本的に「事後調査」（既にJBossを再起動済みで、当時のプロセス状態は直接見られない状態）を前提とした内容を含む
- コマンド中のパス・接続情報（
/var/log/jboss/、/var/lib/mysql/data/、mysql -u root -p等）は環境ごとに読み替えること
1. アプリケーションサーバー（JBoss）調査
1-1. 現在のJVM起動オプションの確認
GC関連のJVMオプション（PermGen/Metaspace対策、GCアルゴリズムなど）が意図した設定になっているかを確認する。過去に類似障害があり、恒久対策としてオプションを追加したことがある場合、それが実際に反映されているかの確認にも使える。
ps aux | grep java | grep -o 'CMSClassUnloadingEnabled\|UseConcMarkSweepGC\|MaxPermSize=[0-9A-Za-z]*\|MaxMetaspaceSize=[0-9A-Za-z]*'意味：起動中のjavaプロセスのコマンドラインから、指定したJVMオプションの有無を抽出する。grep -oで該当パターンにマッチした部分だけを表示する。確認したいオプション名は環境に応じて|で追加・変更する。
実行結果例：
MaxPermSize=1G
UseConcMarkSweepGC
CMSClassUnloadingEnabled→ 意図したJVMオプションが実際に適用されているかを確認できる。
1-2. GCログファイルの存在・更新状況の確認
ls -la /var/log/jboss/gc.log*意味：GCログのファイル一覧とサイズ・更新日時を確認する。JBoss再起動後は新しいログファイルに切り替わる設定になっていることが多く、その場合、再起動前のGC状況はこの時点では追えないことが分かる（＝再起動前にログを退避しておく重要性が分かる）。
実行結果例：
-rw-r--r-- 1 root root 18039 8月 18 13:55 /var/log/jboss/gc.log.0.current→ 再起動後の新しいログのみ存在し、障害発生時（再起動前）のGCログは既に上書き・消失している、といった状況が分かる。
1-3. server.logから特定時間帯のエラー・警告を抽出
障害発生時間帯を絞り込んでエラー・警告のみを抽出する。
grep -n "12:0[0-9]:\|12:1[0-9]:\|12:2[0-4]:" /var/log/jboss/server.log | grep -i "error\|warn\|exception"意味：grep -nで行番号付きで時刻パターンにマッチする行を抽出し、さらにerror/warn/exceptionを含む行だけに絞り込む。時刻の範囲は正規表現の文字クラス（[0-9]等）で指定する。調査したい時間帯に応じてパターンを変更する（例：13時台なら13:0[0-9]:等）。
実行結果例（着目すべきログの種類の例）：
... WARN [org.jboss.as.ee] (ContainerBackgroundProcessor...) JBAS011005: コンポーネントインスタンス...の破棄に失敗しました。: java.lang.NullPointerException
... ERROR [org.jboss.as.ejb3.invocation] (...) ある業務サービス...: 何らかの必須項目がnullである旨の例外
... WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker N) ARJUNA012113: ...missed interrupt when cancelling TX ... exiting as zombie→ コンポーネント破棄失敗（NPE）、業務ロジック上のnullチェック例外、TransactionReaperのトランザクション強制キャンセル失敗（ゾンビ化）など、動作遅延・リソース滞留の手がかりとなるログパターンを発見できる。特に「TransactionReaperのゾンビ化」は、長時間実行されたトランザクション（多くはDB側の重いクエリ）が存在したことを示す強いシグナルになる。
2. DBサーバー（MySQL）調査
2-1. スロークエリログ・エラーログの設定確認
mysql -u root -p -e "SHOW VARIABLES LIKE 'slow_query_log'; SHOW VARIABLES LIKE 'long_query_time'; SHOW VARIABLES LIKE 'slow_query_log_file'; SHOW VARIABLES LIKE 'log_error'; SHOW GLOBAL STATUS LIKE 'Slow_queries';"意味：スロークエリログが有効か、閾値（何秒以上を「遅い」とみなすか）、ログファイルの場所、エラーログの場所、サーバー起動からの累積スロークエリ数を確認する。有効になっていれば、以降の調査で最も重要な情報源になる。
実行結果例：
slow_query_log = ON
long_query_time = 10.000000
slow_query_log_file = /var/lib/mysql/data/slow.log
log_error = /var/lib/mysql/data/mysqld.log
Slow_queries = 240174→ 一定秒数以上かかったクエリがすべてログファイルに記録されていることを確認できる。
2-2. 特定テーブル・処理を含むクエリの累積実行統計
mysql -u root -p -e "SELECT DIGEST_TEXT, COUNT_STAR AS exec_count, ROUND(AVG_TIMER_WAIT/1000000000, 1) AS avg_ms, ROUND(MAX_TIMER_WAIT/1000000000, 1) AS max_ms, ROUND(SUM_TIMER_WAIT/1000000000, 1) AS total_ms, FIRST_SEEN, LAST_SEEN FROM performance_schema.events_statements_summary_by_digest WHERE DIGEST_TEXT LIKE '%対象テーブル名%' ORDER BY AVG_TIMER_WAIT DESC LIMIT 20;" --table意味：performance_schemaに蓄積されている「クエリの型（ダイジェスト）ごとの累積実行統計」から、疑わしいテーブルを参照するクエリを平均実行時間の降順で抽出する。個々の実行タイミングは分からないが、「そもそも重いクエリがどれか」の当たりをつけるのに使える。バックアップ（mysqldump等）由来のSELECT SQL_NO_CACHE * FROM ...のような、業務とは無関係な定期処理も混在するため、FIRST_SEEN/LAST_SEENや実行頻度から見分ける必要がある。
実行結果例（着目パターンの例）：
定期バックアップ由来の全件取得クエリ exec_count=25 avg_ms=92750.4 （夜間の決まった時間帯にのみ実行、障害とは無関係と判断できる）
一覧系の集計クエリ exec_count=81267 avg_ms=1624.5 max_ms=20370.5（平均は軽いが最大値が突出）
JOINを含む集計クエリ exec_count=1433 avg_ms=1138.7 max_ms=60225.4（同上）→ 累積統計だけでは「いつ」遅かったかは分からないため、次にスロークエリログ本体の調査に進む。
2-3. スロークエリログの時刻書式の確認
head -n 20 /var/lib/mysql/data/slow.log意味：ログの先頭を見て、タイムスタンプの書式を確認する。MySQLのバージョンや設定によって書式が異なるため（例：YYYY-MM-DDTHH:MM:SSのISO形式か、YYMMDD H:MM:SSのような古い書式か）、grep等で絞り込む前に必ず確認する。
実行結果例：
# Time: 260818 0:05:14→ YYMMDD H:MM:SSという書式（ISO形式ではない）であることが確認できる。この書式を確認せずにISO形式でgrepすると、該当件数が0件になり時間を浪費するため、必ず最初に確認する。
2-4. 特定時間帯のスロークエリ件数を分布で確認
for m in 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19; do
c=$(grep -c "# Time: <日付> 12:$m:" /var/lib/mysql/data/slow.log)
echo "12:$m -> $c"
done意味：1分単位でスロークエリの発生件数をループで集計し、特定の分に集中しているか、時間帯全体でばらついているかを見る。<日付>はログの書式に合わせて置き換える。
実行結果例：
12:00 -> 1
12:06 -> 2
12:08 -> 4
...→ 特定の1分に極端に集中しているか、時間帯全体で継続的に高負荷だったかを判断する材料になる。前者なら単発の重いクエリ、後者なら同時実行される他処理との競合や、全体的なリソース不足を疑う。
2-5. 特定時間帯のスロークエリの内容を抽出
grep -A15 "# Time: <日付> 12:0[5-9]\|# Time: <日付> 12:10" /var/lib/mysql/data/slow.log意味：時刻の行にマッチした箇所から、後続N行（クエリ本体の先頭部分）を表示する。-A（after）の行数はクエリの長さに応じて調整が必要（短すぎるとクエリの本質部分が見えない）。
実行結果例（着目すべき値の例）：
# Time: <日付> 12:06:53
# Query_time: 1914.730925 Lock_time: 0.000601 Rows_sent: 135 Rows_examined: 3045121049
select
...→ Query_time（実行時間）やRows_examined（読み取り行数）が異常に大きいクエリを発見できれば、それが動作遅延の直接的な証拠になる。Rows_sent（返却行数）に対してRows_examinedが極端に大きい場合は、非効率なJOINやインデックス未使用が疑われる。
2-6. 特定クエリの全文（WHERE句含む）を正確に抽出
awk '/^# Time: <日付> 12:06:53/{flag=1} flag; /^# Time: <日付> 12:07:15/{exit}' /var/lib/mysql/data/slow.log意味：awkで「開始の時刻行が来たら出力開始（flag=1）」「次のクエリの時刻行が来たら終了（exit）」という範囲指定を行い、1件分のログエントリを丸ごと正確に抜き出す。grep -Aでは行数指定が必要で長いクエリを途中で切ってしまうため、正確に1エントリを抜き出したい場合はこの方法が確実。終了条件の時刻は、対象クエリの次に出現する# Time:の値を指定する。
実行結果例：WHERE句を含む全文が取得でき、副問い合わせ（derived table）の絞り込み条件が外側のクエリの絞り込み条件と一致していない、といったSQLの構造上の問題を特定できる場合がある。
まとめ：調査の流れ（一般化）
- アプリサーバーでJVM起動オプション（GC設定）とエラーログを確認し、過去の類似障害と同系統かどうかを判断する
- DBサーバーでスロークエリログの設定（有効か、閾値は何秒か）を確認する
performance_schemaの累積統計で「重そうなクエリ」の当たりをつける（ただしいつ発生したかは分からない）- スロークエリログの時刻書式を確認し、対象時間帯の件数分布を見て「単発の異常」か「時間帯全体の高負荷」かを判断する
- 該当時間帯のクエリ本体を
grep -Aで確認し、Query_timeやRows_examinedが極端に大きい異常なクエリを発見する awkで該当クエリの全文（WHERE句含む）を正確に抜き出し、SQLの構造上の問題点を特定する
このプロセスは、JBoss側のログだけでは「何が起きたか」までしか分からず、「なぜ起きたか」を特定するには、対になっているDB側のログ（スロークエリログ）まで踏み込む必要がある、という点がポイントになる。
No responses yet