#jjug_ccc #ccc_r13 JJUG CCC 2014 Fall 参加レポート / R1-3 実例Javaトラブルシューティング! 稼働中のシステムを立て直した半年間の軌跡

※この投稿は、丸太式 Advent Calendar 2014の5日目です

11月15日に、JJUG Cross Community Conference 2014 Fallが新宿で開催されました。
朝の基調講演から参加するつもりでしたが、残念ながら寝坊してしまったので途中からの参加となりました。
今日から何日かに分けて、セッションのメモをAdvent Calendarの記事として公開していきます。

概要

http://www.java-users.jp/?page_id=1292#R1-3
by 谷本 心さん@Acroquest Technology(株)
@cero_t

メモ

世の中のシステムは完璧か?
→最近リリースしたシステムは完璧か?

完璧ならざるシステムの例

処理が遅い
アクセスを裁けない
脆弱性
システムエラー
etc…

方針

  1. 検索処理の高速化
  2. 購入エラーの是正
  3. 大量アクセスを捌く
    ※Struts + Hibernate + JSP

最初にやったこと

→まずはSeleniumの自動試験を作る
直す過程で壊すことがないように
→CheckStyle / FindBugsをかけてリファクタ
可読性を向上させながら、何とかする

→ダメだった。
1. 300KLのコード、大半がデッドコード
1. 試験項目作成中にもエラーが頻発
1. その間にも本番システムでエラーが多発

方針転換

  • 問題のトリアージ(優先度の設定)
    「一番の問題は何か?」→「購入に失敗すること」(損失の本質)
  • 購入に失敗する理由→これらの改善こそ【顧客が求めること】
    • 購入時にシステムエラーが起きる
    • 検索が遅くて購入までたどり着けない
    • TV放送でアクセスが集中すると、システムがダウンしてしまう
  • どうやって問題を見つけるか(ソースコード上の問題より、現場の問題をつかむ必要がある)
    • エラーの発生頻度(HTTPステータス、アプリケーションエラー)
    • 性能の傾向(通常のレスポンス、アクセス増大時のレスポンス性能)
  • どうやって現場の問題をつかむのか
    ※稼働システムにブレークポイントはだめ

    • ログの収集(アクセスログ、アプリケーションログ、MySQLのスロークエリログ
    • 低負荷な解析ツールの適用(ENdoSnipe等)
  • ログ分析
    • ElasticSearch(ログの蓄積) ※リアルタイム検索・解析エンジン
    • Kibana(可視化) ログ検索、可視化
    • Fluentd(収集)
  • 典型的な問題の検出
    • ENdoSnipe OSSのトラブルシュートツール。メモリリークや同一SQLの発行回数など。動的なFindBugsのようなもの

Mission1 検索処理の高速化

  • 問題点
    • 検索処理は日常的に重い(10~30秒程度)
    • 2~3日間隔で非常に重くなる
  • 分析状況
    • 100件/秒のアクセスで、全てのレスポンスが5秒以上かかる
    • 夜間、ほぼアクセスがない場合でも10~20秒かかる
    • 謎のレスポンス劣化(最大3000秒!!!)
      • スロークエリログを見ると、同じ形になる→間違いなくDBに問題
      • なぜ線形に上がるのか?→SQLを見ると、全て同じストアドプロシージャ
  • 謎のレスポンス劣化原因について仮説を立てる
    ※トラブルシューティングでは、まず問題を確認し、仮説をいくつか立ててから検証・考察するべき

  • スロークエリのストアドプロシージャを精査

    • Temporary Tableに数万件のinsert
    • 明らかに無駄な処理が多数あり、削ったが改善されず
    • Temporary Tableはどうしても必要だったので、
      • Temporary Tableをon memory
      • Temporary Tableのメモリ割り当てを増やす
        →結果・・・Disk I/Oが激減、CPUのI/O waitが激減。スロークエリも改善

Mission2 購入エラーの是正

  • 問題の確認
    • 購入処理の途中でエラー
      • システム内要因(NPE等)
      • 外部システム要因(DB,決済等の応答無し、等)
    • お客様からのクレームで気づく
    • カード決済が絡むので、問題
  • アプローチ
    • 購入処理の開始時にロギング(ログをDBに記録)
    • 処理の途中、終了時にもロギング
    • ログを解析して、正常終了した処理と異常終了した処理を可視化
    • エラー原因ごとに発生件数を整理して、件数が多いエラーから順に対応
    • バグパッチを当てるたびに、エラー数が半減
    • 外部システム要因のエラー以外は対処完了

Mission3 大量アクセスを捌く

  • 問題
    • TV放送などで大量アクセスがあるとレスポンスが悪化してシステムダウン
    • ストアドプロシージャは対処したが、CPU使用量は上がるので。。。
  • アプローチ
    • 同時アクセス数制限の強化 APサーバごとに、検索処理の同自利楠と数が一定数を超えたら503
    • 検索結果のキャッシング
    • 同時検索数を制限 ※同一検索条件は待たせ、キャッシュから読み取る。違う検索条件では同時に検索できる仕組み
  • 構成の問題
    ボトルネックはDBなのに、なぜAPサーバをスケールアウトしているのか・・・
  • アプローチ
    TV放送時にもスケールアウトしない
    →システムダウンがなくなる
    →レスポンス改善
    ※closeされていないコネクションが残ってしまう場合があった

このシステムの今後

  • 全面的なデザインリニューアルと同時に処理をRESTful APIとして再実装
  • 購入処理の非同期化
    • 在庫確保とカード決済ができた時点でレスポンスを返す
    • 外部システム連携部は自動リトライ
  • ElasticSearch / Kibanaの改善
    • シングルノードで運用しているので、たまに死ぬ
    • 処理負荷が高すぎて過去ログを流し込めない

まとめ

  • 長期的トラブルシュートでは、ログの可視化は効果的
    • 現実に起きている問題がわかる
    • 改善効果がわかる
  • 下手にスケールアウトすると怖い