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