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

by kokuyouwind

Slide 1

Slide 1 text

APM をちゃんと使おうとしたら、いつのまにか独⾃gem を作っていた話 Leaner Technologies, Inc. 黒曜 (@kokuyouwind)

Slide 2

Slide 2 text

$ whoami 黒曜 / @kokuyouwind Leaner Technologies Inc. 所属 Rails エンジニアインフラ・SRE 的なこともやっている APM など開発周辺ツールの管理

Slide 3

Slide 3 text

APM の話をします

Slide 4

Slide 4 text

APM とは Application Performance Monitoring の略リクエスト数や応答速度を監視・管理できる代表的な APM サービス etc.

Slide 5

Slide 5 text

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 1 2 3 4 5 6 7

Slide 6

Slide 6 text

APM の画⾯例 (1) https://docs.newrelic.com/jp/docs/apm/new-relic-apm/getting-started/introduction-apm/

Slide 7

Slide 7 text

APM の画⾯例 (2) https://docs.datadoghq.com/ja/tracing/other_telemetry/connect_logs_and_traces/

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

APM 導⼊後のあるある導⼊で満⾜して、その後画⾯を開かなくなった応答速度の遅いエンドポイントを⾒て、「やっぱりここは重いよね〜」と話して終わるソースコード上でどこが重いのか、結局わからない筆者は過去に全部⼼当たりがあります…( ⼩声)

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 12

Slide 12 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 13

Slide 13 text

簡単な APM の使い⽅⼤抵の APM は集計単位ごとにページに分かれているサイト全体エンドポイントごとリクエストごと最初は「サイト全体」の指標で⼤まかな傾向を⾒ると良い細かく掘り下げていくときに「エンドポイントごと」「リクエストごと」の順に⾒ていく

Slide 14

Slide 14 text

ここから先は Datadog APM を例にスクリーンショットを出します ( 他APM でも同様の画⾯があるはず)

Slide 15

Slide 15 text

APM の⾒⽅ - 全体の統計

Slide 16

Slide 16 text

APM の⾒⽅ - 全体の統計

Slide 17

Slide 17 text

APM の⾒⽅ - 全体の統計リクエスト数も応答速度も、極端な変化がないか確認曜⽇や時間帯で傾向が違うため、前週同曜⽇と⽐較するサービスによっては⽉末・年末なども考慮する異常値があった場合はトリアージする⼀時的要因であれば様⼦⾒、問題がありそうなら調査・対応

Slide 18

Slide 18 text

APM の⾒⽅ - 個別エンドポイント

Slide 19

Slide 19 text

APM の⾒⽅ - 個別エンドポイント

Slide 20

Slide 20 text

APM の⾒⽅ - 個別エンドポイント

Slide 21

Slide 21 text

APM の⾒⽅ - 確認タイミング週1 で「APM を⾒る会」を実施している悪化傾向を⾒つけられるよう定期的に⾒る機会を作るトリアージもこのタイミングで実施開発・運⽤に関わるメンバー全員で⼀緒に⾒ると良い悪化しているエンドポイントに機能追加などの⼼当たりがあるか確認しやすい

Slide 22

Slide 22 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

リクエストごとのトレース何に時間がかかっているか( スパン) を表示できる DB アクセスやWeb API 呼び出しのスパンを⾃動で収集

Slide 25

Slide 25 text

N+1 クエリへの対処 SQL クエリを確認し、適切に includes などを設定する特定条件やデータセットがないと発⽣しないN+1 クエリは bullet gem などで⾒つけづらいケースがある

Slide 26

Slide 26 text

重いクエリへの対処まずは EXPLAIN で実⾏計画を確認するインデックス追加だけで改善することも多い

Slide 27

Slide 27 text

時間が⾜りないので詳しいチューニング⼿法は割愛

Slide 28

Slide 28 text

https://slides.com/kokuyouwind/rails-performance-tuning 詳細は以前の Kaigi on Rails 2020 で話した「Rails パフォーマンス・チューニング⼊⾨」をご覧ください！

Slide 29

Slide 29 text

パフォーマンス・チューニングについては他の⽅も発表されていたのでおすすめです！ Rails アプリの 5,000 件の N+1 問題と戦っている話初めてのパフォーマンス改善〜君たちはどう計測す( はか) るか〜

Slide 30

Slide 30 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

困るとき 1. SQL の発⾏場所がわからない ActionController スパン直下に SQL クエリのスパンがある単なるメソッドの呼び出しは標準だとスパンにならないクエリ構築がどのコードで⾏われているかわからないと修正しようがない ( 重いクエリの例を再掲)

Slide 33

Slide 33 text

困るとき2 . Ruby での処理が重いケース Ruby 処理は⾃動でスパンに区切られない原因が全くわからないので対処もできなくなってしまう

Slide 34

Slide 34 text

⼿動インストゥルメンテーション https://docs.datadoghq.com/ja/tracing/trace_collection/dd_libraries/ruby/ Datadog::Tracing.trace(name, **options) do |span, trace| # 計測したい処理をここに記⼊ end 1 2 3 Datadog では Datadog::Tracing.trace を使って⼿動でスパンを追加できる渡したブロック内がスパンとして区切られる

Slide 35

Slide 35 text

Datadog::Tracing の微妙な使いづらさ # ↓ 標準だとこう書く必要がある class User def awesome_method Datadog::Tracing.trace( 'awesome_method', service: 'my-service', resource: 'User') do # ... 処理 end end end 1 2 3 4 5 6 7 8 9 10 11 処理対象をブロックで囲むとインデントが変わる差分が⼤きくなって気軽につけ外ししづらい引数が多く、記述がやや冗⻑

Slide 36

Slide 36 text

APM Traceable gem # ↓ こう書けるようにした class User include ApmTraceable::Tracer trace_methods :awesome_method def awesome_method # ... 処理 end end 1 2 3 4 5 6 7 8 9 trace_methods にメソッド名を指定するとスパンとして表示 UseCase やPresenter など、独⾃レイヤークラスの呼び出し重いメソッドを切り分けたプライベートメソッド

Slide 37

Slide 37 text

APM Traceable gem 各Presenter#call をtrace_methods した結果

Slide 38

Slide 38 text

APM Traceable gem 元々は1 モジュールでlib 以下に置いていた以前に書いた話複数プロダクトに必要だったのでgem に切り出した APM Traceable gem 本体 Datadog への送信⽤アダプタアダプタを作れば他の APM にも切り替えられるようにしたブログ記事 apm_traceable apm_traceable-datadog

Slide 39

Slide 39 text

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 1 2 3 4 5 6 7 8 9 10 11 12 13 trace_methods で各メソッドを持つモジュールを作り、 prepend して呼び出しをラップするだけ

Slide 40

Slide 40 text

APM Traceable gem - 仕組み Class User awesome_method prepended Module awesome_method メソッド呼び出し Datadog Adapter trace_span トレース送信

Slide 41

Slide 41 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 42

Slide 42 text

事例 1. SQL クエリの速度悪化 MySQL 8.0 に更新した際、特定エンドポイントだけ遅くなった

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

事例 1. SQL クエリの速度悪化テンポラリテーブルでの SELECT COUNT(*) の問題っぽい… https://zenn.dev/hmatsu47/articles/mysql80-count-slowdown

Slide 45

Slide 45 text

事例 1. SQL クエリの速度悪化元のクエリが GROUP BY してから最初の⾏を取っており、実質 DISTINCT 相当の処理がテンポラリテーブルで⾏われていた DISTINCT を使えばテンポラリテーブルを使わなくなるので直した

Slide 46

Slide 46 text

事例 1. SQL クエリの速度悪化元々 1.0sec -> 悪化して 4.0sec -> 改善後 100ms 結果的に元の10 倍に⾼速化🚀

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

事例 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 1 2 3 4 5 6 7 8 9

Slide 49

Slide 49 text

事例 2. 外部API 呼び出しのトレースこの変更で、きれいにトレースが⾒られるようになった 🎉

Slide 50

Slide 50 text

事例 2. 外部API 呼び出しのトレーストレースを精査したところ、外部API 呼び出しよりも XML レスポンスのパース処理に時間がかかっていた

Slide 51

Slide 51 text

事例 2. 外部API 呼び出しのトレースローカルで再現させ、 Stackprof でプロファイルを取ったところ DidYouMean::Jaro.distance が⼤半を占めている… ？

Slide 52

Slide 52 text

事例 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 1 2 3 4 5 6

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

事例 2. 外部API 呼び出しのトレースエンドポイントのレスポンスタイムも、修正を境に⾶び上がった値が出ることがなくなった

Slide 55

Slide 55 text

アジェンダ簡単な APM の使い⽅トレースを使ったパフォーマンス・チューニング APM Traceable gem を作った話具体的なチューニング事例紹介まとめ

Slide 56

Slide 56 text

まとめ APM は本番で起こっている問題を⾒つけるのに便利統計値を定期的に⾒て、変化に気づけるようにすると良いトレースを⾒ると重い原因を⾒つける⾜がかりになる重要なメソッドにスパンを仕込んでおくと原因を掘り下げやすいこれをやりやすいように独⾃gem を作ったトレースで⽬星をつけて、掘り下げた調査を別で⾏うこともある APM 全然使いこなせてないので、いい使い⽅教えてください！休憩時間や懇親会でお話しましょう

Slide 57

Slide 57 text

補⾜資料

Slide 58

Slide 58 text

各 APM での⼿動トレース機能 New Relic add_method_tracer が trace_method とほぼ同等機能 Scout APM だけで⼗分かもしれない Open Telemetry Ruby カスタムインストゥルメンテーション Custom Instrumentation Auto Instruments Manual Instrumentation