APMをちゃんと使おうとしたら、
いつのまにか独自gemを作っていた話

Leaner Technologies, Inc.
黒曜

(@kokuyouwind)

$ whoami

  • 黒曜 / @kokuyouwind

  • Leaner Technologies Inc. 所属

  • Railsエンジニア

  • インフラ・SRE的なこともやっている

    • APMなど開発周辺ツールの管理

APM の話をします

APM とは

Application Performance Monitoring の略
リクエスト数や応答速度を監視・管理できる

代表的な APM サービス

etc.

APM の導入自体は結構簡単

https://docs.datadoghq.com/ja/tracing/trace_collection/dd_libraries/ruby/

大抵の APM は エージェントソフトウェアと
gem を設定するだけ

# Gemfile
gem 'ddtrace', require: 'ddtrace/auto_instrument'

# config/initializers/datadog.rb
Datadog.configure do |c|
  c.service = 'my-service'
end

APM の画面例 (1)

https://docs.newrelic.com/jp/docs/apm/new-relic-apm/getting-started/introduction-apm/

APM の画面例 (2)

https://docs.datadoghq.com/ja/tracing/other_telemetry/connect_logs_and_traces/

🤔

すごいけど、何を見ればいいの…？

APM 導入後のあるある

  • 導入で満足して、その後画面を開かなくなった

  • 応答速度の遅いエンドポイントを見て、
    「やっぱりここは重いよね〜」と話して終わる

  • ソースコード上でどこが重いのか、結局わからない

筆者は過去に全部心当たりがあります…(小声)

ひとつの参考事例として、
弊社での APM の使い方を紹介します

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

簡単な APM の使い方

  • 大抵の APM は集計単位ごとにページに分かれている

    • サイト全体

    • エンドポイントごと

    • リクエストごと

  • 最初は「サイト全体」の指標で大まかな傾向を見ると良い

    • 細かく掘り下げていくときに「エンドポイントごと」「リクエストごと」の順に見ていく

ここから先は Datadog APM を例に
スクリーンショットを出します

(他APMでも同様の画面があるはず)

APM の見方 - 全体の統計

APM の見方 - 全体の統計

APM の見方 - 全体の統計

  • リクエスト数も応答速度も、極端な変化がないか確認

    • 曜日や時間帯で傾向が違うため、前週同曜日と比較する

    • サービスによっては月末・年末なども考慮する

  • 異常値があった場合はトリアージする

    • 一時的要因であれば様子見、問題がありそうなら調査・対応

APM の見方 - 個別エンドポイント

APM の見方 - 個別エンドポイント

APM の見方 - 個別エンドポイント

APMの見方 - 確認タイミング

  • 週1で「APM を見る会」を実施している

    • 悪化傾向を見つけられるよう定期的に見る機会を作る

    • トリアージもこのタイミングで実施

  • 開発・運用に関わるメンバー全員で一緒に見ると良い

    • 悪化しているエンドポイントに機能追加などの
      心当たりがあるか確認しやすい

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

重いエンドポイントを改善する際、
リクエストごとのトレースが足がかりになる

リクエストごとのトレース

  • 何に時間がかかっているか(スパン)を表示できる

    • DBアクセスやWeb API呼び出しのスパンを自動で収集

N+1 クエリへの対処

  • SQLクエリを確認し、適切に includes などを設定する

    • 特定条件やデータセットがないと発生しないN+1クエリは
      bullet gem などで見つけづらいケースがある

重いクエリへの対処

  • まずは EXPLAIN で実行計画を確認する

    • インデックス追加だけで改善することも多い

時間が足りないので

詳しいチューニング手法は割愛

https://slides.com/kokuyouwind/rails-performance-tuning

詳細は以前の Kaigi on Rails 2020 で話した
「Railsパフォーマンス・チューニング入門」をご覧ください！

パフォーマンス・チューニングについては

他の方も発表されていたのでおすすめです！

Rails アプリの 5,000 件の N+1 問題と戦っている話

初めてのパフォーマンス改善〜君たちはどう計測す(はか)るか〜

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

自動トレースは便利だが、
標準のトレースだけだと困るときがある

困るとき 1. SQLの発行場所がわからない

  • ActionController スパン直下に SQL クエリのスパンがある

    • 単なるメソッドの呼び出しは標準だとスパンにならない

    • クエリ構築がどのコードで行われているかわからないと
      修正しようがない

(重いクエリの例を再掲)

困るとき2 . Ruby での処理が重いケース

  • Ruby 処理は自動でスパンに区切られない

    • 原因が全くわからないので対処もできなくなってしまう

手動インストゥルメンテーション

https://docs.datadoghq.com/ja/tracing/trace_collection/dd_libraries/ruby/

Datadog::Tracing.trace(name, **options) do |span, trace|
  # 計測したい処理をここに記入
end

  • Datadog では Datadog::Tracing.trace を使って
    手動でスパンを追加できる

    • 渡したブロック内がスパンとして区切られる

Datadog::Tracingの微妙な使いづらさ

# ↓ 標準だとこう書く必要がある
class User
  def awesome_method
    Datadog::Tracing.trace(
      'awesome_method', 
      service: 'my-service', 
      resource: 'User') do
      # ... 処理
    end
  end
end

  • 処理対象をブロックで囲むとインデントが変わる

    • 差分が大きくなって気軽につけ外ししづらい

  • 引数が多く、記述がやや冗長

APM Traceable gem

# ↓ こう書けるようにした
class User
  include ApmTraceable::Tracer
  trace_methods :awesome_method

  def awesome_method
    # ... 処理
  end
end

  • trace_methods にメソッド名を指定するとスパンとして表示

    • UseCaseやPresenterなど、独自レイヤークラスの呼び出し

    • 重いメソッドを切り分けたプライベートメソッド

APM Traceable gem

各Presenter#call をtrace_methods した結果

APM Traceable gem

  • 元々は1モジュールでlib以下に置いていた

    • 以前 ブログ記事 に書いた話

    • 複数プロダクトに必要だったのでgemに切り出した

  • apm_traceable

    • APM Traceable gem 本体

  • apm_traceable-datadog

    • Datadog への送信用アダプタ

    • アダプタを作れば他の APM にも切り替えられるようにした

APM Traceable gem - 仕組み

module ApmTraceable::Tracer
  def self.trace_methods(*method_names)
    wrapper = Module.new do
      method_names.each do |method_name|
        define_method method_name do |*args, **options, &block|
          trace_span(method_name.to_s) { super(*args, **options, &block) }
        end
      end
    end

    prepend(wrapper)
  end
end

trace_methods で各メソッドを持つモジュールを作り、
prepend して呼び出しをラップするだけ

 

APM Traceable gem - 仕組み

Class User

awesome_method

prepended Module

awesome_method

メソッド呼び出し

Datadog Adapter

trace_span

トレース送信

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

事例 1. SQLクエリの速度悪化

MySQL 8.0 に更新した際、特定エンドポイントだけ遅くなった

 

事例 1. SQLクエリの速度悪化

事例 1. SQLクエリの速度悪化

テンポラリテーブルでの SELECT COUNT(*) の問題っぽい…

 

https://zenn.dev/hmatsu47/articles/mysql80-count-slowdown

事例 1. SQLクエリの速度悪化

元のクエリが GROUP BY してから最初の行を取っており、
実質 DISTINCT 相当の処理がテンポラリテーブルで行われていた

DISTINCT を使えばテンポラリテーブルを使わなくなるので直した

事例 1. SQLクエリの速度悪化

元々 1.0sec -> 悪化して 4.0sec -> 改善後 100ms
結果的に元の10倍に高速化🚀

事例 2. 外部API呼び出しのトレース

外部 API を並列で呼び出す箇所のトレースが取れていなかった
(単独だと取れるが、2箇所以上Parallelだと取れない)

 

事例 2. 外部API呼び出しのトレース

Parallel をまたぐとスパンの親子関係が途切れるようなので、
手動で親ダイジェストを引き渡すよう修正

 

  def search_parallel(clients)
+   trace_span('search_parallel') do |_span, trace|
      results = Parallel.map(clients, in_processes: clients.count) do |client|
+       trace_span(client.name, continue_from: trace.to_digest) do
          client.search
+       end
      end
+   end
  end

事例 2. 外部API呼び出しのトレース

この変更で、きれいにトレースが見られるようになった 🎉

 

事例 2. 外部API呼び出しのトレース

トレースを精査したところ、外部API呼び出しよりも

XMLレスポンスのパース処理に時間がかかっていた

事例 2. 外部API呼び出しのトレース

ローカルで再現させ、 Stackprof でプロファイルを取ったところ

DidYouMean::Jaro.distance が大半を占めている…？

事例 2. 外部API呼び出しのトレース

XML で未知の attribute が出てきた際、

const_get でNameError が起こる実装になっていた。
const_defined? で確認を挟むよう実装を修正

      klass = "CXML::#{camelize(key)}"
-     send("#{key}=", Object.const_get(klass).new(val))
+     send("#{key}=", Object.const_get(klass).new(val))
+     if Object.const_defined?(klass)
+        send("#{key}=", Object.const_get(klass).new(val))
+     else

事例 2. 外部API呼び出しのトレース

事例 2. 外部API呼び出しのトレース

エンドポイントのレスポンスタイムも、
修正を境に飛び上がった値が出ることがなくなった

アジェンダ

  • 簡単な APM の使い方

  • トレースを使ったパフォーマンス・チューニング

  • APM Traceable gem を作った話

  • 具体的なチューニング事例紹介

  • まとめ

まとめ

  • APM は本番で起こっている問題を見つけるのに便利

    • 統計値を定期的に見て、変化に気づけるようにすると良い

  • トレースを見ると重い原因を見つける足がかりになる

    • 重要なメソッドにスパンを仕込んでおくと原因を掘り下げやすい

    • これをやりやすいように独自gemを作った

    • トレースで目星をつけて、掘り下げた調査を別で行うこともある

  • APM全然使いこなせてないので、いい使い方教えてください！

    • 休憩時間や懇親会でお話しましょう

補足資料

各 APM での手動トレース機能