こんにちは。Kaneyasuです。
本記事は第34回 中国地方DB勉強会 in 広島でLTさせていただいた内容のブログ版です。
はじめに
最近、ベテラン（私ですね）と若手の数名というチームをよく組ませていただきます。
中間層は残念ながらいません。
組織の問題というより時代の問題のような感じがして危機感を覚えますね。
そこはまあ仕方がないとして、このチーム構成だと今までしてこなかった議論の必要性を感じます。
その一つが本記事のお題に掲げてるログ設計です。
ログ設計もかなりいろいろなことを考える必要がありますが、本記事では主にデータベースで何かあった時の調査を意識して述べてみます。
本記事がイメージしているシステム
本記事は小〜中規模のWebアプリケーションを小さめのチームで開発・運用している方をイメージしています。
上の図の中で、いわゆるAPIを構成するバックエンドのログ設計を考えていきます。
AWSならALB+EC2＋RDSがバックエンドを組んでいる場合はEC2で稼働している部分。
API Gateway＋Lambda＋RDSという構成ならLambdaで稼働している部分を指していると思ってください。
EC2なのかサーバーレスで組んでるのかは抽象化して書いていきます。
この議論の必要性を感じたのは、特にサーバーレスでAPIを組んだ時です。
サーバーレスだとしっかりとしたWebフレームワークなしで手軽にAPIを組めますが、その分ログ設計を意識しないと管理が緩くなりやすいと私は思っています。
データベースの調査の始まり
データベースの調査のきっかけは監視からの通知かテスト担当者またはお客様からの連絡が多いと思います。
発生している事象が負荷上昇なら、CPU使用率やメモリ使用率に対して監視を仕込んでいたらそれを受けて通知が飛ぶのでそれを見て調査を始めるでしょう。
この場合、データベースで各種グラフを見る、可能なら分析機能も使います。
これらを駆使して事象が発生している時間帯やSQLのあたりをつけます。
この後は、バックエンドのログを見てどういう操作の流れでどの機能が発行したSQLかを特定していきます。
なお、分析機能はAWSならPerformance Insightsがあります。
このサービスに関して本記事では詳しく触れていませんが、かなり有益な情報を提供してくれるので触ってみてください。
発生している事象が、データ不整合などの場合はいきなりバックエンドのログを見ることになると思います。
Apacheやロードバランサーを見ることもありますが、先にバックエンドのログを見た方が早そうです。
データベースサーバーの情報をもっと活用しないのか？
負荷上昇の時の例で、前項であたりをつけたらバックエンドのログを見ると書きました。
ここで思うのがデータベースサーバーの情報をもっと活用しないのか？という点です。
もうちょっとできることがありそうですよね。
その通りです。
その通りなのですが、本記事で論じているシステムは小中規模であり、チームも小さいです。
この状況だと以下の理由によりデータベースサーバが提供する情報を活用しきれない可能性が高いと思います。
- 全員がDBA相当の知識を持っているわけではない
- 小中規模だと、データベースのグラフやログを整備し切れてない可能性がある
- セキュリティの都合上データベースサーバーの情報を見ることができない、持ち帰れないことがある
- リーダークラスが長時間調査にあたってると回らなくなるので、詳細な調査は他のメンバーに依頼せざるを得ない
以上の理由から皆に馴染みが深く制約も比較的緩いバックエンドのログを充実させて活用す方が効率が良いと考えます。
データベースサーバーの各種情報は、データベースの管理者を任されたり、トラブルに見舞われたりでもしなければ見る機会は少ないです。
トラブル時に慣れないものを見るのは負担が大きいので、普段から見慣れている場所に情報がたくさんある方が迅速に対応できると思います。
バックエンドのログで意識すること
以上を踏まえて、やっとログ設計の話に入ります。
バックエンドのログを意識する際には以下のことを意識すると良いと思います。
中には異なる意見と思いますので、私の提案だと思ってください。
- ログレベルを使い分ける
- 更新・削除件数やトランザクションはINFOで出力する
- SQLはDEBUGで出力する（またはファイルを分ける）
- SQLは完成系で出力する、プレースホルダがあるまま出力しない
- SQLの実行時間を出力する
- ログフォーマットにログインIDを含める
- ログフォーマットにセッションIDやリクエストIDを含める
ログレベルを使い分ける
一般的にログレベルはDEBUG、INFO、WARN、ERROR、FATALなどがあります。
本番運用時はログが出過ぎてレスポンスやストレージコストに影響が出ないようにログレベルはINFOあたりで稼働させることが多いです。
とはいえ、INFOで出る情報が少なすぎて何も得るものがないログになっては意味がありません。
いい感じに出さないといけません。
私は、更新・削除件数はINFOで出力するようにしています。
データ不整合系の問題が起きた場合、データの更新・削除件数を見て成功・失敗を判断できる可能性があるからです。
SQLはDEBUGで出力するようにしています。
トラブル発生時、パッと見で原因がわからなければ一旦ログモードをDEBUGにして再現待ちにすることがあります。
正直なところ、時間稼ぎに利用している面もあります。
トランザクションの開始・終了を示すログは、迷うところですがDEBUGかなと思います。
トランザクションの開始・終了が正しくないのは単なるバグなので、そこをINFOで確認しなければならない状況はおかしいと思うからです。
SQLは完成系で出力する、プレースホルダがあるまま出力しない
原因となるSQLをログから特定したとします。
この時、コピペで動かないSQLは困ってしまいます。
処理速度の調査にしても、データ不整合の調査にしても、特定したSQLを実行をして見る際に、手を入れる必要があるならば、手を入れた時点で同じものなのか？と思ってしまいます。
また、「一手間かかる」のもマイナスだと思います。
本記事においては詳細調査をリーダー以外のメンバーに依頼することをイメージしています。
この時に面倒な作業が含まれていると、レクチャーの手間が増えてしまいます。
また、データベースまわりは面倒なものと捉えられると長期的なチームビルディングの点でも地味なマイナスに思えます。
一方で、ログにSQLを完成系を載せるのはセキュリティ的にどうなの？という意見もあると思います。
この辺は、各チームでしっかり議論するしかないでしょう。
ログフォーマットになんらかのIDを含める
これは、Grep用のキーワードをログに仕込んでおくというテクニックです。
ログインIDで絞り込むことで、同じ人の操作を追いかけることができます。
セッションID／リクエストIDで絞り込むと、一連の作業＝画面上の1アクション分のログを追いかけることができます。
メトリクスでヒントを得た後、その時間帯のバックエンドログから該当するSQLを探します。
そこからログインIDやセッションID／リクエストIDで一連の作業を抽出します。
抽出した結果とロードバランサーやApacheのログと付き合わせたりすることで、原因を特定できる可能性はとても高くなります。
まとめ
- 小中規模のシステムだと、データベース絡みの調査に備えたログ設計が重要
- ログに調査しやすい仕込みを入れておくのがオススメ
- 逆に一手間かかるような要素が残っていると、調査が遅れる可能性あり
- 手間がかかるものと思われると、チームビルディングの面でもマイナスかも
- 普通のことを書いてる気が大変しますが、もしこれらのことを意識したことがなければ試してみてください
余談
本記事を書く中で、Performance InsightsのTipsを思い出しました。
調査してSQLを特定したけど、真の原因を調べ切れない場合サポートに問い合わせることが考えられます。
この時、サポートの方からPerformance Insightsの内容を見せて欲しいと言われることがあります。
サポートの方からするとユーザーの独自形式の情報よりも、自分たちのフォーマットの情報を見る方が効率よいからですね。
しかし、Performance Insights、無料だと7日分しか情報を保持できません。
7日だとサポートの方とやり取りする中で情報が消失してしまう可能性があるので、調査の際には有料に切り替えることを検討してみてください。
Performance Insights では、継続する 7 日間のパフォーマンスデータ履歴を無料で提供します。