こんにちは、かたいなかです。
みなさんが関わっているシステムでなぜか遅くて悩まされている処理はないでしょうか？
最近、遅いAPIをDatadog Continuous Profilerを使用して調べました。どのように問題解決までつなげたかを記事にまとめます。
TL;DR
遅い処理を改善しようと思ったらまずは計測してみること。 計測することで実は単純な問題であったことに気付けるケースがたくさんあります。また、的はずれな推測を元にでたらめな変更を繰り返してしまう事態を防げます。
通常のDatadog APMで原因がわからない場合には、Continuous Profilerで可視化をしてみることで時間がかかっているメソッドが特定でき、原因調査の手がかりが得られる場合があります。
特定のAPIが遅い問題が発覚
ある日、Datadog上のダッシュボードでメトリクスを眺めていたとき、Railsで作られたとあるAPIで処理に時折10秒以上かかっており、BFFからの呼び出しがタイムアウトしていることに気づきました。
転職会議ではパフォーマンスの可視化を行うためにDatadog APMを導入しています。さっそく遅い処理について、Datadog APMで調べてみました。
すると、以下のことがわかりました。
- Active Model Serializerの処理で時間がかかっている
- 問題になっている処理が毎回遅いわけではなく、時折遅い
- 当該APIのCPUやメモリの使用率が高まっているわけではない
- 時間がかかっている処理の間にDBのアクセスはなさそう
しかし、APMの画面ではそれ以上に掘り下げる材料がなく、全く原因がわかりませんでした。
Continous Profiler導入
通常のAPMよりも更に深堀りして調べるため、DatadogのContinuous Profilerを導入することにしました。
Continuous Profilerを使用すると、APMのトレースと紐付けてプロファイリングを取ることができます。これにより、たまに実行が非常に遅くなる今回のようなケースでも、実行が遅かった場合にどのメソッドにどの程度時間がかかっていたかなどを詳しく見ることができます。
Continuous Profilerの導入にあたっては、以下の変更が必要でした。
ddtraceのバージョンアップ
環境変数や起動コマンドの修正
費用面も考慮し、計測を行うときのみ環境変数などでContinuous Profilerを有効化し、必要のないときには無効化しておくことにしました。
Continuous Profilerで計測してみると・・・
計測してみると予想外のことがわかりました。なんと、Sentryへの送信処理で時間を消費していたのです。
もっと詳しく見てみると、ビジネスロジック上通ることを想定していないコードパスでSentryに警告メッセージを送るところで時間がかかっていました。
SentryのRubyのライブラリ内部では、FaradayというHTTPクライアントを使用しています。そのため、Datadog APMでFaradayの計測を有効化していれば気づけたのかもしれません。しかし、このAPIでは外部APIにSentry以外でHTTPで通信しにいく処理はないため、APMでFaradayの計測を有効化していませんでした。
Continuous Profilerにより可視化した後では「なーんだそんなことか」と感じてしまいますが、可視化しないとなかなか原因を特定するのが難しいケースでした。
問題修正
そもそもの原因は、特定のビジネスロジックで分岐の実装が漏れており、通るはずのないパスを通るようになっていたことのようでした。そのため、Sentryに大量に警告メッセージが送られるようになっていました。しかし、SentryからSlackへの通知のルールもまずかったため、問題が起きていることにも気づきにくくなってしまっていました。調査にあたって、Slackに通知が飛ばないなら通常動作だろうと思いこんでしまったのも気づくのが遅れた原因でした。
実装を修正したものをデプロイすると、問題が起きていた処理が遅くなることはなくなりました。
実際のところ
ここまでの記事の中では、まず計測し、原因の仮説を立て、修正することで問題が直るか検証する、という理想的な流れで取り組めたように書いてきました。しかし、実際のところはスムーズに問題解決に取り組めたわけではありませんでした。
Continuous Profilerで詳しく計測する前に、Active Model SerializerやPuma、ガベージコレクションなどの問題を疑い、ああでもないこうでもないと考え時間を浪費してしまいました。現在計測できていないことをどうやって計測するかに焦点を当てて考えていれば、無駄な労力がかかってしまうことも防げたはずです。
まず計測するのがセオリーだと頭ではわかっていても、関係していそうな解決策に飛びついてしまう、今見えているものだけから問題を考えようとしてしまう、そんな自分の弱さを痛感しました。
まとめ
今回はContinuous Profilerを使ったパフォーマンス改善の取り組みについて記事にしました。
Continuous Profilerは、APMで得られるよりもっと詳細な情報を得るのにとても便利でした。この便利な機能を同じ組織で働く人なら誰でも使えるようにするため、調査が必要になってから準備をするのではなく、いつでも有効化できる状態を整えておくと良いように思いました。
個人的には、まず計測してみる、そして今計測できていないものを計測するにはどうしたらよいかを考える、スムーズにそんな動きができるよう鍛錬を積んでいきたいと痛感させられました。
