とあるエラーの調査記録 2022.08.30 SATOSHI KANEYASU

はじめに • とあるプロジェクトにおける結合テストで起きたエラーの、 原因調査記録です • エラー調査の仕⽅は習ったことはありません、全て独学です • このことはあまり⼈に話す機会がないので、 今回テーマにしてみました。

⾃⼰紹介 • ⽒名︓兼安 聡 • 所属︓株式会社サーバーワークス • 趣味︓サックス、筋トレ、CS ゲーム • 資格︓ • X(Twitter)︓@satoshi256kbyte など

• 調査対象のエラーが発⽣したシステム • フロントエンド︓ jQuery（古い実装です） • バックエンド︓Amazon Linux、Apache、PHP（フレームワーク使⽤）、MySQL • 結合テスト中に⾒つかったエラーで、チケットで連絡が来たとします • 画⾯上でとある操作をすると、予期せぬエラーが出たとします • エラーの最終的な原因は、意図せず⼤量データを取得した故の、 メモリ不⾜エラーとします • 複数の事象を混ぜた話なので、多少⽭盾があるかもしれません。 調査対象の条件

エラー調査とは、少しずつ範囲を狭めること こっちではエラー起きない まだわからない エラー起きない 調査済 まだわからない この辺り？ 調査済 何も出てない エラー起きない

①エラーを再現する • 画⾯を操作して、現象が再現できることを確認 • ブラウザの開発ツールを確認 • Consoleタブで、JavaScriptエラーがないことを確認 • Networkタブで、エラーになっている通信があることを確認 • この時点で、フロント側の問題ではないと推測 • エラーの通信を調べ、URL・リクエスト内容・レスポンス内容を確認 • レスポンス内容から、詳細不明だがやはりエラーを返してることを確認 • URLからPHP側のファイル・クラス・メソッドを⼤体特定 • リクエスト内容は控えておく

②WEBサーバーを調べる • フロント側の問題ではないとの判断から、サーバーの⽅を調査 • PHPのフレームワークのログに、 これといったログがないことを確認 • Apacheのログにて何かエラーが起きてることだけは確認 • OS・ PHP-FPMのログには特に何も⾒つからず • PHPのフレームワークのログをもう⼀度確認すると、 ログが途中で⽌まってるように⾒えることを確認 • この時点でチケットにここまでの調査内容を記⼊して周知 • ここまでで約1時間

[補⾜]RedHat系のログ出⼒先 • Apacheのログ︓/var/log/httpd配下 • PHP-FPMのログ︓/var/log/php-fpm配下 • OSのログ（システムログ）︓/var/log/message配下

③DBサーバーを調べる • ログが途中で⽌まってるように⾒えることから、 DBサーバー側の調査を開始（理由は次ページ） • 画⾯で現象を再現させ、その間のDBサーバーの挙動を確認 • SHOW PROCESSLIST コマンドで実⾏中SQLを確認 • DBサーバーのCPU・メモリなどを監視 • 監視結果から、⾮常に重たいSQLが⾛って完了してないことを確認 • おそらくSQLが終わらないことにより、処理がそこから進んでない、 それによりタイムアウトエラーが発⽣していると推測 • この時点で、ここまでの調査結果をチケットに記⼊して周知 • ここまでで約1時間半

[補⾜] DBサーバー側の調査を開始した理由 • SQLのログは、SQLが実⾏完了してから出⼒されることが多い。 • 従って、ログにSQLが出ていない＝まだ実⾏中のSQLがある可能性が ⾼い • SQLは通るが、PHPが処理しきれてないのならば、PHP-FPMあたり に何かエラーが出るはずである • なお、実⾏完了して初めてログが出るのはApacheのアクセスログも 同様で結構重要なこと

④重いSQLを発⾏している箇所の特定 • SHOW PROCESSLISTを使って控えたSQL、途中で⽌まったログか ら、ソースコード上のあたりをつける • 複雑でソースがさっと追いきれないので、あたりをつけた直前の⾏に ⼀時的にthrow new Exception();を⼊れる • エラーが発⽣する操作を⾏うと、スタックトレースが出⼒されるので、 あたりは正解だと確信 • 最初に控えたURL・リクエスト内容から、⼊り⼝からソースを追い、 上記スタックトレースと付き合わせ特定した箇所が間違いないことを 確認

⑤修正案の作成 • 取り急ぎSQLのチューニングは決まり • SQLのチューニングしても、今度はPHPでエラーになる可能性がある ので、PHPの修正も視野に⼊れる 具体的には、⼀気にデータを受け取るのでなく、カーソルを使⽤する など • 上記修正に伴い、リグレッションテストが発⽣すると想定 • 以上をまとめてチケットに記⼊し、⼀旦調査完了とする 修正内容の具体的な設計は後⽇⾏う • ここまでで約2時間

⑥重いSQLの調査 • 後⽇調査再開 • 重いSQLが実際に返す件数、実⾏計画、メモリなどの動きを観察 • その結果、実⾏計画がよくない＋件数が多すぎる＋1レコードのデー タサイズが⼤きい、の合わせ技でメモリを⼤量消費していることが判 明 • この部分のロジックを⾒直すことを提案。 • リスクもそれなりにあるので、どのように対応するか協議中。 以上。

[補⾜] エラーを共有する場合 • エラーメッセージ、エラーログ、スタックトレースの共有は、 ハードコピーも嬉しいが、テキストの⽅がより嬉しい • 理由は、エラーを検索したり、それを元にGREPしたりするから • ハードコピーだとそれらが⼿⼊⼒になる、エラー対応で余裕がない時 は、些細な⼿間で苦しくなってしまう

以上です。ありがとうございました。