フレームグラフこわくない - Singedで始めるパフォーマンス改善

After Kaigi on Rails LT Night 〜SmartBank x メドピア x マイベスト〜での登壇資料です。
https://smartbank.connpass.com/event/299631/

Transcript

1. フレームグラフこわくない Singedで始めるパフォーマンス改善 Naohisa Yokoyama 2023-11-09 @After Kaigi on Rails LT Night 1
2. 自己紹介 Naohisa Yokoyama / @_shrrk 株式会社マイベスト バックエンドエンジニア iOSアプリのバックエンド開発を担当。 大阪在住でフルリモート勤務です。 ココイチカレーうどんを布教しています。 好きなRubyのメソッドは Array#zip です。 2
3. 今日持ち帰ってほしいこと 「フレームグラフこわくないじゃん」という気持ち 3
4. 目次 1. フレームグラフとの出会い 2. フレームグラフ3大こわい要素 3. フレームグラフとは 4. フレームグラフの出力方法 5. Singedの紹介 6. フレームグラフの読み方 7. まとめ 4
5. 1. フレームグラフとの出会い 5
6. 2023年春 mybestのiOSアプリをリリース しかしリリース後まもなくパフォーマンスが課題になった(表示までに数秒かかるケース も) ボトルネックの調査へ… 6
7. まずはDatadogのAPMを使って調査してみるが… GraphQLのどのクエリ、どのフィールドの処理が遅いのかは特定できる しかしその先のRubyのメソッド呼び出しはAPMのフレームグラフ上には現れない それ以上の深掘りはTracerの設定を工夫するか別途プロファイリングが必要 7
8. 参考 こちらのDatadogのAPMの仕様についてはDay2の黒曜さんによる「APMをちゃんと使 おうとしたら、いつのまにか独自gemを作っていた話」でも触れられているのでそちら も参考にしてみてください。 https://slides.com/kokuyouwind/kaigi_on_rails_2023 8
9. フレームグラフとの出会い そんなときにあるTweetが流れてくる 9
10. フレームグラフを読める側の人間になりたくなる Singedを使ってローカルでフレームグラフを出力すれば内部的に呼び出されているRuby のメソッドまで可視化できるのでは？と考えた 10
11. しかしフレームグラフの3大こわい要素が立ちはだかる 11
12. 2. フレームグラフ3大こわい要素 12
13. フレームグラフ3大こわい要素 その1. 何を表しているのかわからなくてこわい その2. どうやって出せばいいのかわからなくてこわい その3. 読み方がわからなくてこわい 13
14. その1. 何を表しているのかわからなくてこわい フレームって枠？ たくさんデコボコしていてこわい 14
15. その2. どうやって出せばいいのかわからなくてこわい フレームグラフを出力するためのツールを調べると色々出てくる rbspy stackprof test-prof rack-mini-profiler どれを使えばいいのかわからなくてこわい 15
16. その3. 読み方がわからなくてこわい フレームグラフを出せるようになったけどどこから読んだらいいのかわからない PumaとかActionDispatchとかRackとかばっかり表示されていてこわい 16
17. 3. フレームグラフとは 17
18. ざっくり言うと コールスタック&CPU処理時間をビジュアライズした もの Flame(炎)のように見えるのでFlame graphと呼びま す not Frame(枠) graph 18
19. 上下反転版 こちらは滝のように見えるのでWater fall chartと呼ぶそうですが、どちらもフレームグラフ と呼ばれます 19
20. 生成のイメージ 関数の呼び出しの依存関係とCPU処理時間を元に生成されます 20
21. 読み方 mainの処理時間 -> 9秒 foo1の処理時間 -> 4秒 barの処理時間 -> 2.5秒 foo1自体の処理時間 -> 1.5秒 21
22. フレームグラフ3大こわい要素 その1. 何を表しているのかわからなくてこわい その2. どうやって出せばいいのかわからなくてこわい その3. 読み方がわからなくてこわい 22
23. 4. フレームグラフの出力方法 23
24. Rubyにおける代表的なフレームグラフ出力のためのツール rbspy(https://github.com/rbspy/rbspy) stackprof(https://github.com/tmm1/stackprof) 24
25. rbspy 起動中のRubyのプロセスにアタッチできるため、プロファイリング用のコード挿入が不 要 $ rbspy record --pid $PID 特定のエンドポイントのみに絞ってのプロファイリングは難しい 25
26. stackprof コード挿入が必要ですが、プロファイリング箇所や対象のコントロールが容易 StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do # code you want to profile here end フレームグラフ取得のためには追加でコマンドが必要 $ stackprof --d3-flamegraph tmp/stackprof-cpu-myapp.dump > flamegraph.html 26
27. 課題 どのスコープでプロファイルしたいかによってGemの使い分けが必要 プロファイルのセットアップ、出力、ビジュアライズにいくつかのステップが必要でハ ードルが高い 27
28. 5. Singedの紹介 28
29. Singedとは https://github.com/rubyatscale/singed rbspyとstackprofをラップしたGem プロファイリング方法によってrbspyと stackprofのどちらを使うかを自動的に切り替 えてくれる プロファイリング後に自動的にspeedscope でフレームグラフを表示してくれる 29
30. 多様なプロファイリング方法 ブロックで囲う flamegraph { # your code here } コントローラーで特定のアクションを指定 class EmployeesController < ApplicationController flamegraph :show def show # your code here end end 30
31. 多様なプロファイリング方法 RSpecで特定のテストを指定 require 'singed/rspec' RSpec.describe YourClass do it "is slow :(", flamegraph: true do # your code here end end リクエストヘッダーで指定 $ curl -H 'X-Singed: true' https://localhost:3000 CLIでの実行時に指定 $ bundle exec singed -- bin/rails runner 'Model.all.to_a' 31
32. speedscopeの自動起動 計測したいアクションをコントローラー内で指定 class ArticlesController < ApplicationController flamegraph :index def index; end end 該当のURL(例: /articles )にアクセスすると別タブでspeedscopeが自動的に起動 32
33. フレームグラフ3大こわい要素 その1. 何を表しているのかわからなくてこわい その2. どうやって出せばいいのかわからなくてこわい その3. 読み方がわからなくてこわい 33
34. 6. フレームグラフの読み方 34
35. speedscopeとは ブラウザベースのフレームグラフビューワーのOSS https://github.com/jlfwong/speedscope ローカルで動かすこともできるし、 https://www.speedscope.app にアクセスして使う ことができる ブラウザ上でスタンドアロンで動き、インポートしたファイルはどこにも送信されない ので安心 35
36. speedscopeの3種類のView Time Order Left Heavy Sandwich 36
37. Time Order 横軸が時系列、縦軸がコールスタックになっているビュー どういう時系列でどんな処理が呼び出されているのか把握するために使う 37
38. Left Heavy 同一のコールスタックをグループ化、より重い処理が左側に配置されたビュー どの処理が多くの時間を占めているのか把握するために使う 38
39. Sandwich 全ての関数とその処理時間を一覧にしたビュー 処理時間でのソートやキーワード検索を組み合わせることができる 39
40. フレームグラフを読む上での勘所 Left Heavyで処理時間がどこに偏っているか俯瞰してみる アプリケーションコードよりも親のスタックは一旦無視する まずはコントロールが効きやすいアプリケーションコードの中でのボトルネックを 探す Sandwichで処理時間順に降順ソートして特に遅い箇所を特定してから深掘りする マイベストではGraphQLのオブジェクトタイプに ObjectTypes:: という名前空間 を切ってあるので、どのフィールドが遅いのか簡単に特定することができる 40
41. 実際に読んでみよう Railsチュートリアルの実装を例にフレームグラフを出力してみます 41
42. flamegraph出力のための設定 ※ /users/:id というエンドポイントへのリクエストをプロファイルします。 ※ わざと遅い処理を挟んでフレームグラフ上でわかりやすくしています。 class UsersController < ApplicationController + flamegraph :show def show + User.all.find_each { |user| user.some_slow_method } @user = User.find(params[:id]) @microposts = @user.microposts.paginate(page: params[:page]) end class User < ApplicationRecord + def some_slow_method + sleep 0.0005 + end 42
43. リクエストを送ってflamegraph表示 43
44. Left Heavyで表示 44
45. スクロールしてアプリケーションコードを探す UsersController#show を発見 45
46. 何を呼び出しているのか見てみる ActiveRecord::Batches#find_each ActiveRecord::Core::ClassMethods#find User::GeneratedAssociationMethods#microposts WillPaginate::ActiveRecord::Pagination#paginate ※ 再掲 def show User.all.find_each { |user| user.some_slow_method } @user = User.find(params[:id]) @microposts = @user.microposts.paginate(page: params[:page]) end 46
47. ActiveRecord::Batches#find _each を深掘り ActiveRecord::Batches#find_each → ActiveRecord::Batches#find_in_batches → ActiveRecord::Batches#in_batches → Kernel#loop → (略) → User#some_slow_method → Kernel#sleep 47
48. フレームグラフ3大こわい要素 その1. 何を表しているのかわからなくてこわい その2. どうやって出せばいいのかわからなくてこわい その3. 読み方がわからなくてこわい 48
49. 7. まとめ 49
50. フレームグラフを読むようになってよかったこと Gemのコールスタックも可視化されるため、OSSのソースコードリーディングがしやす くなる 内部実装について知っておくことで不要なActive Recordオブジェクトのインスタンス生 成にも気付けるようになる 50
51. 大幅なレイテンシ改善に成功 p90: 2,000ms → 200ms p50: 900ms → 30ms 51
52. まとめ Singedを使うと簡単にフレームグラフの出力ができる フレームグラフを見るとパフォーマンス上のボトルネックを俯瞰しつつ特定できる フレームグラフはこわくない 52
53. 参考にさせていただいたサイト https://cloud.google.com/profiler/docs/concepts-flame?hl=ja https://zenn.dev/nateberkopec/articles/af7ab6ee7fb88a https://mametter.hatenablog.com/entry/2020/09/11/230139 https://www.brendangregg.com/flamegraphs.html 53
54. ご清聴ありがとうございました 54