ログで障害の原因を絞る

目標

運用ログ(catalina.out、GCログ、アクセスログ、nginxエラーログ)から根拠を抜き出して障害の原因を絞り込み、数字の入った障害報告書を作成できるようになります。

なぜ重要なのか

障害対応で最もよくある失敗は、502でタイムアウトを延ばすことです。502は「無効なレスポンスを受け取った」で、504は「時間内に応答がなかった」です。2つを混同すると、何時間も無駄にします。また、OOMは種類(Java heap space / Metaspace / unable to create native thread)によって、対応が完全に違うので、メッセージを読まずに-Xmxだけを上げると、かえって悪化することがあります。ログから数字を取り出す手があれば、この判断が推測から根拠に変わります。

ステップ

/root/tsを作成して、/opt/lab/fixtures/tomcat/logs/の4つのファイルをそのままコピーします。(catalina-oom.log、gc.log、access.log、nginx-error.log)内容が原本と同一である必要があります。
catalina-oom.logからOutOfMemoryErrorを探して、/root/ts/oom.txtを作成します。2行で、形式は次のとおりです(プレースホルダーは、順にログに書かれたタイムスタンプと、OOMの種類の文字列です)。
```
time=<로그에 적힌 타임스탬프>
type=<OOM 종류 문자열>
```
typeは、Java heap space / Metaspace / GC overhead limit exceeded / unable to create native threadのいずれかです。
gc.logを分析して、/root/ts/gc.txtを作成します。2行です(プレースホルダーは、順にFull GCの発生回数と、最も長い停止時間です。停止時間はミリ秒で、小数点を含めてそのまま書きます)。
```
fullgc=<Full GC 발생 횟수>
maxpause=<가장 긴 정지 시간, 밀리초, 소수점 포함 그대로>
```
access.logから、処理時間が長いURLの上位5個を抜き出して、/root/ts/slow.csvを作成します。1行目はurl,count,max_msで、max_msの降順に並べます。
access.logから5xxのレスポンスをURLごとに集計して、/root/ts/5xx.csvを作成します。1行目はurl,status,countで、件数の降順に並べます。
nginx-error.logからアップストリームのエラーを原因別に集計して、/root/ts/upstream.csvを作成します。1行目はcode,cause,countです。codeは502または504、causeはconnection refusedまたはtimeoutです。
Tomcatを起動して、スレッドダンプを取って/root/ts/threads.txtに保存したあと、/root/ts/threadstat.txtを作成します。2行です(プレースホルダーは、順にダンプにある全スレッド数と、WAITING状態のスレッド数です)。
```
total=<덤프에 있는 전체 스레드 수>
waiting=<WAITING 상태 스레드 수>
```
2つの値は、threads.txtの内容と一致する必要があります。
/root/ts/rca.mdを作成します。## 현상、## 원인、## 조치、## 재발방지という4つのh2見出し(韓国語の見出しは、順に「現象」「原因」「対処」「再発防止」を意味します)が必要で、ステップ2のOOMの種類の文字列と、ステップ3のfullgcの数字が、本文にそのまま引用されている必要があります。

参考

URLごとの最大値: awk -F'|' '{ if ($3 > m[$2]) m[$2]=$3; c[$2]++ } END {...}'
スレッドダンプ: jcmd <PID> Thread.print > /root/ts/threads.txt
ダンプのスレッド数: ダブルクォートで始まる行が、スレッド1つです。
よくあるミス1: Full GCを数えるときに、Young GCまで一緒に数えるミスです。
よくあるミス2: 並べ替えるときにsort -nの代わりに辞書順の並べ替えを使い、9.5が12.3より大きく出るミスです。
よくあるミス3: 報告書に数字なしで、「メモリが足りなかった」とだけ書くミスです。

ログのコピーの確保

/root/tsを作成して、/opt/lab/fixtures/tomcat/logs/の4つのファイルをそのままコピーします。(catalina-oom.log、gc.log、access.log、nginx-error.log)内容が原本と同一である必要があります。

障害分析の最初の行動は、原本の保全です。分析中にログがローテーションされたり上書きされたりすることが、実際に起きます。

OOMの発生時刻と種類の確認

catalina-oom.logからOutOfMemoryErrorを探して、/root/ts/oom.txtを作成します。2行で、形式は次のとおりです(プレースホルダーは、順にログに書かれたタイムスタンプと、OOMの種類の文字列です)。

time=<로그에 적힌 타임스탬프>
type=<OOM 종류 문자열>

typeは、Java heap space / Metaspace / GC overhead limit exceeded / unable to create native threadのいずれかです。

OutOfMemoryErrorは、種類によって対応が完全に異なります。メッセージの後ろの部分に、種類が書かれています。

GCログの分析

gc.logを分析して、/root/ts/gc.txtを作成します。2行です(プレースホルダーは、順にFull GCの発生回数と、最も長い停止時間です。停止時間はミリ秒で、小数点を含めてそのまま書きます)。

fullgc=<Full GC 발생 횟수>
maxpause=<가장 긴 정지 시간, 밀리초, 소수점 포함 그대로>

Full GCだけを数える必要があります。停止時間は、各行の末尾のミリ秒の値です。小数点があるので、並べ替えの方式に注意してください。

遅いURLの上位の抽出

access.logから、処理時間が長いURLの上位5個を抜き出して、/root/ts/slow.csvを作成します。1行目はurl,count,max_msで、max_msの降順に並べます。

アクセスログの最後のフィールドが処理時間です。URLごとにまとめて、最大値を求める必要があります。awkの連想配列を使えば、1回のスキャンで終わります。

5xxの発生分布

access.logから5xxのレスポンスをURLごとに集計して、/root/ts/5xx.csvを作成します。1行目はurl,status,countで、件数の降順に並べます。

ステータスコードのフィールドを正確に指定する必要があります。5で始まる3桁だけを選んで、URLごとに集計してください。

502と504の原因の区別

nginx-error.logからアップストリームのエラーを原因別に集計して、/root/ts/upstream.csvを作成します。1行目はcode,cause,countです。codeは502または504、causeはconnection refusedまたはtimeoutです。

nginxのエラーログの文言が、原因を教えてくれます。接続そのものが拒否されたことと、時間が超過したことは、別の文言で残ります。

実際のスレッドダンプの分析

Tomcatを起動して、スレッドダンプを取って/root/ts/threads.txtに保存したあと、/root/ts/threadstat.txtを作成します。2行です(プレースホルダーは、順にダンプにある全スレッド数と、WAITING状態のスレッド数です)。

total=<덤프에 있는 전체 스레드 수>
waiting=<WAITING 상태 스레드 수>

2つの値は、threads.txtの内容と一致する必要があります。

実行中のTomcatからダンプを取ったあと、状態別にスレッド数を数えます。ダンプでスレッドの状態は、大文字のキーワードとして現れます。

障害報告書の作成

/root/ts/rca.mdを作成します。## 현상、## 원인、## 조치、## 재발방지という4つのh2見出し(韓国語の見出しは、順に「現象」「原因」「対処」「再発防止」を意味します)が必要で、ステップ2のOOMの種類の文字列と、ステップ3のfullgcの数字が、本文にそのまま引用されている必要があります。

報告書の価値は数字にあります。前のステップで抜き出した値を、そのまま引用してください。再発防止の項目には、「注意する」の代わりに、具体的な設定や監視項目を書きます。