freeeの開発情報ポータルサイト

アプリチーム x SRE チームによるアプリケーションモニタリング運用改善

freee人事労務の品質改善を専任で活動している keik です。

freeeではアプリケーションパフォーマンスモニタリング(APM)に Datadog を利用しています。 SRE チームが導入し、アプリケーション開発チームに利用提供する形で運用されています。 導入のきっかけについては以下の記事でも触れられています。 developers.freee.co.jp

Datadog APM の画面は多機能かつ柔軟で、例えばウェブサーバーが受けたリクエスト処理の内訳を視覚的にドリルダウンできたり、リクエストや SQL クエリごとのレイテンシやエラー率を計測してダッシュボード化してくれたり、また全画面で共通的に「タグ」や日時を用いたフィルタリングができたりします。直感的なだけなく、見た目もオシャレで、適当に眺めているだけでもワクワクします。

しかし、私達は「ここに映っているもの」が何なのか、正直分かっていなかった。

ある時、急激なパフォーマンス劣化が発生しました。慌ててアプリケーション開発チームのメンバが集まってクラッシュレポートシステムや、それこそ Datadog APM を眺めてみたものの、原因に紐づきそうなエラーが見つからないのです。しばらくして一人のメンバが Datadog APM のあるビュー上で「エラー率95%のクエリ」が存在することに気づきました。そこからは、クエリの失敗が引き起こすロールバック処理により、CPUリソースが食われていることがパフォーマンス劣化の原因と分かったのです。

「エラー率95%のクエリ」になぜ今まで気が付けなかったのか。

単にツールの使い方が難しい。収集されているメトリクスに対する解像度が低い。そうした知識不足が原因の表層部分にはあるように思われました。 ですが、この知識不足がもたらされる根本原因には、APM というツールが SRE 領域とアプリケーション領域の中間地点にあることで、使いこなすための知見が結合されにくいことにあるのではないか、と気づきました。

こうした課題認識のもと、SRE チームメンバとアプリケーション開発チームメンバが協働して APM 運用を改善していった話をします。 また具体的なノウハウのパートとしては、Ruby on Rails と Datadog APM の組み合わせによって起きるトラップめいた挙動とそれを回避するアイデアについても説明します。

「APM サービス一覧」に悪い気配を感じ取る

実は Datadog APM の入り口である APM サービス一覧のリスト表示時点で、すでに曖昧さがもたらされていました。freee人事労務に対してセットアップされた APM サービス一覧を絞り込んでみると……

admin,admin-cache,admin-mysql2,api,api-internal,api-internal-mysql2,api-mysql2,mysql2,web,web-cache,web-mysql2

めっちゃある、怖、となりつつもまだ雰囲気で使えそうではある。

ですがここで問題です。

admin-mysql2api-mysql2web-mysql2 の違いを説明(推測)せよ

「どうやら、役割ごとに分割されたデプロイメント adminapiweb ごとに suffix -mysql2 がついた APM サービスがあるんやな。つまり MySQL に関するメトリクスが各環境ごとに分割されて収集されているということやろ」

なるほど、では次の問題です。

単の mysql2web-mysql2 の違いを説明(推測)せよ

単の mysql2 には全環境からのメトリクスが合算されているんか? いや、内容を見ると web-mysql2 のリクエスト数だけですでに 単の mysql2 のリクエスト数を上回っているからそれはない……どうなってるんや? 🤔 」

このあたりまでくると、APM の初期設定を行った SRE チームとしても想定外の状況になってきていました。ここで私はある疑問に気づきました。APM は SRE 領域とアプリケーション領域の中間に位置するツールであり、これの運用設計を SRE チーム任せにすることは果たして正しい責務分離の姿なのか。収集される各種メトリクスはアプリケーションの実装技術に依存してそれぞれで異なる解像度を持っているものなので、これを正しく解釈するためにはアプリケーションレイヤの知見が必要不可欠で、そこを補うのはアプリケーション開発チームの役割なのではないか。

その後すぐ、検証用の Datadog API キーを SRE チームに借りて、ローカル環境に datadog-agent をインストールしメトリクスを送信することで、その結果を検証していくことにしました。

メトリクスの解像度を上げる

ここでは検証をして分かったことだけを書きます。

  • APM サービス freee人事労務-mysql2 は、mysql2 gem 向けのメトリクス収集を有効化するための mysql2 設定に由来する、mysql2 gem インタフェースを経由したイベントを収集したメトリクス です。
  • APM サービス freee人事労務-admin-mysql2freee人事労務-api-mysql2freee人事労務-web-mysql2 は、Ruby on Rails 向けのメトリクス収集を統合的に有効化するための rails 設定によって自動設定される一つ active_record 設定に由来する、ActiveRecord インタフェースを経由したイベントを収集したメトリクス です。

この説明だとわかりにくいので、問題点を強調するとこうなります。

  • 前者は 実クエリを計測する が、後者は 実クエリ数を計測しない
  • 前者は SQL エラーをエラーとしてカウントする が、後者は SQL エラーをエラーとしてカウントしない

具体的な Datadog APM 画面上での比較もしてみましょう。

まずは mysql2 設定に由来する APMサービスのクエリ統計ビューです。

このビュー上の統計情報と MySQL サーバのログを突合確認すると、このビューのリクエスト数は実際の SQL 発行数と一致することがわかりました。またエラー数も一致していました。

次に rails 設定に由来する APMサービスのクエリ統計ビューです。

f:id:keik_117:20220211074653p:plain

このビュー上の統計情報と同時間内における MySQL サーバおよび Ruby on Rails サーバログを突合確認すると、リクエスト数は実際の SQL 発行数ではなく ActiveRecord を経由したデータアクセス数すなわち ActiveRecord のキャッシュ機構が使われた回数も含まれていることがわかりました。また実際には発生している SQL エラーが、ビュー上には観測されていません。

おおよそ問題分析に有効な情報を示してくれるのは mysql2 設定に由来する APM サービスのほうでしょう。 一方で rails 設定を使うことで自動的に作られる *-mysql2 APM サービスは、探し求めている問題、例えば N+1 クエリや実行時間の長いクエリ、アプリケーションで握りつぶされている SQL エラーなどを見つけるためには、残念ながら役に立たないばかりか、誤読の可能性を与えます。

冒頭で紹介した急激なパフォーマンス劣化の際、多くのメンバが見ていたのは rails 設定で作られた *-mysql2 APM サービスのほうでした。そこに一つたりともエラーイベントが存在していなかったのは、こういう理由だったわけです。

全体最適を目指して運用を改善する

検証で分かった内容を SRE チームに持ち込み、どのように APM サービスのリストを整理するとよいかを議論しました。

アプリ開発チームと SRE チームのそれぞれの視点から、重視したいポイントを出していきました。具体的には以下のようなポイントです。

  • APM サービスが多いだけでウッとなるので極力統合したい
  • APM サービス名と実際の収集対象メトリクスがまぎらわしくないようにしたい
  • 特定のデプロイメントだけ遅いといったことが分かるよう最低限の分割はしたい
  • APM サービス名のリストから命名の法則性を読み取ることを可能にしたい

この結果、次のような APM サービス名のリストにすることにしました。

admin,admin-active_record,admin-cache,api,api-active_record,api-internal,api-internal-active_record,mysql2,web,web-active_record,web-cache

結果として変わった点は少なく、rails 設定で作れる実際には ActiveRecord レイヤで収集されるメトリクスを映した APM サービス名を *-mysql2 から *-active_record に変更した、という点だけです(これには rails 設定のリファレンス どおり database_service オプションに任意の APM サービス名を指定することで設定可能です)。APM サービスの統合なども検討しましたが、分割されているメリットなども踏まえて判断をした結果、一部の APM サービス名を変更するだけの結果に落ち着きました。それでも、APM サービス名の法則性は読み取れるようになった上に、MySQL と ActiveRecord が明確に区別できるようになって誤読の可能性が相当分減らせたのではないかと思っています。

また Datadog APM は社内の全プロダクトが利用しています。つまり、Ruby on Rails を使って開発している全アプリケーションにも同様の課題があり、それらを今回の整理でまとめて解決できる道筋が立ちました。今はこの運用改善を全プロダクトに展開中です。

さらなる発展に向けて

Datadog APM はあらゆるレイヤでのメトリクス収集をサポートしていますが、これまでは、上で説明した rails 設定と mysql2 設定だけが有効化されていました。 一方で、freee人事労務の実装技術スタックに対して利用可能性のある APM サービスとしては、faradayhttpgrpcredisresque などがあります。

これらの利用可能な APM サービスの全てを何でもかんでも有効化してしまうとまた同じ問題が招かれるでしょう。大は小を兼ねず、目的に焦点を絞った運用をすることが大事です。現在は、こういった利用可能性のある APM サービス一つ一つに対し、取得できるメトリクスの内容を SRE とアプリケーションの両視点で確認しながら、有用なものを有効化していっています。