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

フレームグラフこわくない
Singedで始めるパフォーマンス改善
Naohisa Yokoyama
2023-11-09 @After Kaigi on Rails LT Night
1

View Slide

自己紹介
Naohisa Yokoyama / @_shrrk
株式会社マイベストバックエンドエンジニア
iOSアプリのバックエンド開発を担当。
大阪在住でフルリモート勤務です。
ココイチカレーうどんを布教しています。
好きなRubyのメソッドは Array#zip
です。
2

View Slide

今日持ち帰ってほしいこと
「フレームグラフこわくないじゃん」という気持ち
3

View Slide

目次
1. フレームグラフとの出会い
2. フレームグラフ3大こわい要素
3. フレームグラフとは
4. フレームグラフの出力方法
5. Singedの紹介
6. フレームグラフの読み方
7. まとめ
4

View Slide

1. フレームグラフとの出会い
5

View Slide

2023年春 mybestのiOSアプリをリリース
しかしリリース後まもなくパフォーマンスが課題になった(表示までに数秒かかるケース
も)
ボトルネックの調査へ…
6

View Slide

まずはDatadogのAPMを使って調査してみるが…
GraphQLのどのクエリ、どのフィールドの処理が遅いのかは特定できる
しかしその先のRubyのメソッド呼び出しはAPMのフレームグラフ上には現れない
それ以上の深掘りはTracerの設定を工夫するか別途プロファイリングが必要
7

View Slide

参考
こちらのDatadogのAPMの仕様についてはDay2の黒曜さんによる「APMをちゃんと使
おうとしたら、いつのまにか独自gemを作っていた話」でも触れられているのでそちら
も参考にしてみてください。
https://slides.com/kokuyouwind/kaigi_on_rails_2023
8

View Slide

フレームグラフとの出会い
そんなときにあるTweetが流れてくる
9

View Slide

フレームグラフを読める側の人間になりたくなる
Singedを使ってローカルでフレームグラフを出力すれば内部的に呼び出されているRuby
のメソッドまで可視化できるのでは？と考えた
10

View Slide

しかしフレームグラフの3大こわい要素が立ちはだかる
11

View Slide

2. フレームグラフ3大こわい要素
12

View Slide

フレームグラフ3大こわい要素
その1. 何を表しているのかわからなくてこわい
その2. どうやって出せばいいのかわからなくてこわい
その3. 読み方がわからなくてこわい
13

View Slide

フレームって枠？
たくさんデコボコしていてこわい
14

View Slide

フレームグラフを出力するためのツールを調べると色々出てくる
rbspy
stackprof
test-prof
rack-mini-profiler
どれを使えばいいのかわからなくてこわい
15

View Slide

フレームグラフを出せるようになったけどどこから読んだらいいのかわからない
PumaとかActionDispatchとかRackとかばっかり表示されていてこわい
16

View Slide

3. フレームグラフとは
17

View Slide

ざっくり言うと
コールスタック&CPU処理時間をビジュアライズした
もの
Flame(炎)のように見えるのでFlame graphと呼びま
す
not Frame(枠) graph
18

View Slide

上下反転版
こちらは滝のように見えるのでWater fall chartと呼ぶそうですが、どちらもフレームグラフ
と呼ばれます
19

View Slide

生成のイメージ
関数の呼び出しの依存関係とCPU処理時間を元に生成されます
20

View Slide

読み方
mainの処理時間 -> 9秒
foo1の処理時間 -> 4秒
barの処理時間 -> 2.5秒
foo1自体の処理時間 -> 1.5秒
21

View Slide

22

View Slide

4. フレームグラフの出力方法
23

View Slide

Rubyにおける代表的なフレームグラフ出力のためのツール
rbspy(https://github.com/rbspy/rbspy)
stackprof(https://github.com/tmm1/stackprof)
24

View Slide

rbspy
起動中のRubyのプロセスにアタッチできるため、プロファイリング用のコード挿入が不
要
$ rbspy record --pid $PID
特定のエンドポイントのみに絞ってのプロファイリングは難しい
25

View Slide

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

View Slide

課題
どのスコープでプロファイルしたいかによってGemの使い分けが必要
プロファイルのセットアップ、出力、ビジュアライズにいくつかのステップが必要でハ
ードルが高い
27

View Slide

5. Singedの紹介
28

View Slide

Singedとは
https://github.com/rubyatscale/singed
rbspyとstackprofをラップしたGem
プロファイリング方法によってrbspyと
stackprofのどちらを使うかを自動的に切り替
えてくれる
プロファイリング後に自動的にspeedscope
でフレームグラフを表示してくれる
29

View Slide

多様なプロファイリング方法
ブロックで囲う
flamegraph {
# your code here
}
コントローラーで特定のアクションを指定
class EmployeesController < ApplicationController
flamegraph :show
def show
# your code here
end
end
30

View Slide

多様なプロファイリング方法
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

View Slide

speedscopeの自動起動
計測したいアクションをコントローラー内で指定
class ArticlesController < ApplicationController
flamegraph :index
def index; end
end
該当のURL(例: /articles
)にアクセスすると別タブでspeedscopeが自動的に起動
32

View Slide

33

View Slide

6. フレームグラフの読み方
34

View Slide

speedscopeとは
ブラウザベースのフレームグラフビューワーのOSS
https://github.com/jlfwong/speedscope
ローカルで動かすこともできるし、 https://www.speedscope.app にアクセスして使う
ことができる
ブラウザ上でスタンドアロンで動き、インポートしたファイルはどこにも送信されない
ので安心
35

View Slide

speedscopeの3種類のView
Time Order
Left Heavy
Sandwich
36

View Slide

Time Order
横軸が時系列、縦軸がコールスタックになっているビュー
どういう時系列でどんな処理が呼び出されているのか把握するために使う
37

View Slide

Left Heavy
同一のコールスタックをグループ化、より重い処理が左側に配置されたビュー
どの処理が多くの時間を占めているのか把握するために使う
38

View Slide

Sandwich
全ての関数とその処理時間を一覧にしたビュー
処理時間でのソートやキーワード検索を組み合わせることができる
39

View Slide

フレームグラフを読む上での勘所
Left Heavyで処理時間がどこに偏っているか俯瞰してみる
アプリケーションコードよりも親のスタックは一旦無視する
まずはコントロールが効きやすいアプリケーションコードの中でのボトルネックを
探す
Sandwichで処理時間順に降順ソートして特に遅い箇所を特定してから深掘りする
マイベストではGraphQLのオブジェクトタイプに ObjectTypes::
という名前空間
を切ってあるので、どのフィールドが遅いのか簡単に特定することができる
40

View Slide

実際に読んでみよう
Railsチュートリアルの実装を例にフレームグラフを出力してみます
41

View Slide

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

View Slide

リクエストを送ってflamegraph表示
43

View Slide

Left Heavyで表示
44

View Slide

スクロールしてアプリケーションコードを探す
UsersController#show
を発見
45

View Slide

何を呼び出しているのか見てみる
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

View Slide

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

View Slide

48

View Slide

7. まとめ
49

View Slide

フレームグラフを読むようになってよかったこと
Gemのコールスタックも可視化されるため、OSSのソースコードリーディングがしやす
くなる
内部実装について知っておくことで不要なActive Recordオブジェクトのインスタンス生
成にも気付けるようになる
50

View Slide

大幅なレイテンシ改善に成功
p90: 2,000ms → 200ms
p50: 900ms → 30ms
51

View Slide

まとめ
Singedを使うと簡単にフレームグラフの出力ができる
フレームグラフを見るとパフォーマンス上のボトルネックを俯瞰しつつ特定できる
フレームグラフはこわくない
52

View Slide

参考にさせていただいたサイト
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

View Slide

ご清聴ありがとうございました
54

View Slide

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

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

naohisa

Featured

Transcript