こんにちは、エンジニアの中島です。 この記事はフロントエンドのパフォーマンス調査の記録を記事にしたものです。 弊社は自社プロダクトのパフォーマンス劣化を検知するために WebPageTest を導入し、数時間に一度自動計測をするようにしています。 そこでとある日から TBT (Total Blocking Time) が劣化しているようなので原因を調査してほしいという依頼が来ました。 現象確認 まずは本当に問題が起きているかの確認です。 WebPageTestのタイムラインを見てみます。 たしかにいくつかのタイミングで大きめのスタイルの再計算が走っていることがわかりました。 しかしながら、これらが"ある日を境に"、TBTの大幅な劣化を引き起こした犯人かどうかはまだわかりません。 数日分のタイムラインをみて確認する必要があります。 タイムライン情報を一つ一つ目でみて確認するのも大変だなと思ったのでこのタイムラインの元になっているjsonファイルをパースして導くことができないかと考えました。 生データを見るとあまり詳しくはわかりませんが以下のように配列で50万行ほどログがつまっているようでした。 { ... " traceEvents ": [ { " args ": { ... } , " name ": " XXXX ", " dur ": 2 , .... } , { " args ": { ... } , " name ": " XXXX ", " dur ": 1 , .... } , { " args ": { ... } , " name ": " XXXX ", " dur ": 3 , .... } , { " args ": { ... } , " name ": " XXXX ", " dur ": 1 , .... } , ... ] } nameにはどういうログなのかが記載されており、具体的にはFunctionCallやUpdateLayoutTree、ResourceFinishといった値がみられました。 またdurはdurationの略のようで1/1000ms単位の数値が入っていることがわかりました。 ざっくりとこのログに対応する モデル を作り、そこから10ms以上のUpdateLayoutTreeだけを抽出してその実行時間を出力してみれば少なくとも発生の根拠になるかなと考えました。 WebPageTestを簡単にスクレイピングして該当日の前後数日のtimeline情報のjsonファイルのurlを抽出し、そのコンテンツを取得してパースしていきます。 records = Performance :: Timeline :: Record .from_timeline( " path/to/timeline.json " ) p ([date, records .select(& :update_layout? ) .select{|record| record.duration > 10 } .map(& :duration )] (タイムラインデータのモデル) Performance::Timeline::Record class Performance :: Timeline :: Record def initialize (record) @record = record.deep_symbolize_keys end def name @record [ :name ] end def duration ( @record [ :dur ] || 0 ) / 1000.0 end def update_layout? name == ' UpdateLayoutTree ' end def self . from_timeline (file) result = JSON .parse( File .read(file)) records = result[ ' traceEvents ' ] records.map {|record| new(record) } end end 実行結果 [YYYY-MM-DD 19:41:43 +0900, [15.948]] [YYYY-MM-DD 19:41:43 +0900, [15.984]] [YYYY-MM-DD 19:41:48 +0900, [20.741]] [YYYY-MM-DD 19:41:09 +0900, [11.888]] [YYYY-MM-DD 19:42:24 +0900, [25.136]] [YYYY-MM-DD 19:41:59 +0900, [14.453]] [YYYY-MM-DD 19:42:15 +0900, [14.962, 13.14, 11.3871, 11.410]] [YYYY-MM-DD 19:41:49 +0900, [15.190, 15.919, 10,873, 11.733]] [YYYY-MM-DD 20:57:31 +0900, [16.211, 10.861, 15.085, 11.209]] [YYYY-MM-DD 20:59:48 +0900, [26.105, 19.971, 17.264, 11.762]] [YYYY-MM-DD 20:55:14 +0900, [18.890, 15.410, 12.570, 14.569]] [YYYY-MM-DD 19:37:16 +0900, [17.059, 11.72, 11.735, 13.011]] [YYYY-MM-DD 19:38:57 +0900, [14.816, 17.057, 13.122, 10.301]] 実行結果を見ると、確かにある日を境にスタイルの再計算が急増してることが確認できました 原因調査 ある日を境にということであれば、リリースだったり、GTMなどのツール経由のタグ挿入などが疑われます。 WebPageTestは数時間に一度回しているので、同じ手順で問題発生の時間を特定します。 まずはその特定された時間にリリースされたものを一つずつ洗っていきます。 しかしながら今回は対象となるページに影響を与えるような実装はどこにも含まれていませんでした。 そうなるとツール経由のタグ挿入の影響の線が濃くなります。 WebPageTestとchromeのdevtoolsで計測したPerformanceのログは中身が基本的に同じなので実際に手元のブラウザでそれらのツールをネットワークブロックした時とそうでない時のログを見比べて判断していきます。 とはいえ、色々なものの影響をうけるためtimelineが完全に安定することはなく、複数回分のログを取得して判断していく必要があります。 その工程が面倒なのでPuppeteerを使って自動化していきます。 require ' puppeteer-ruby ' ... Puppeteer .launch( headless : false ) do |browser| page = browser.new_page block_list = [ # タグ挿入系のサービスのパス (ex: gtm) # ... # ... ] # ネットワークリクエストのインターセプトを有効化 page.request_interception = true page.on( ' request ' ) do |request| if block_list.any? {|uri| request.url.include?(uri) } request.abort # リクエストを中止してブロック else request.continue end end # とありえず10回分計測する ( 1 .. 10 ).each do # トレースの開始 page.tracing.start( path : ' trace.json ' ) # 検証対象のページに移動 page.goto( ' https://www.homes.co.jp/path/to/target/ ' ) # トレースの停止 page.tracing.stop # トレース結果の読み込み trace_data = File .read( ' trace.json ' ) trace_json = JSON .parse(trace_data) records = Performance :: Timeline :: Record .from_timeline( ' trace.json ' ) p records.select(& :update_layout? ) .select{|record| record.duration > 10 } .map(& :duration ) end end このように検証したところ、今回はとあるタグ挿入ツールをブロックすると問題のスタイルの再計算はなくなることが判明しました。 ツールから挿入されてるタグを列挙し、二分探索でブロックしていき原因となるスクリプトを特定します。 今回はこのような手順で現象の確認と原因の特定ができました。 最後に この調査方法が王道的な調査方法かはわかりませんが、生ログを見る調査方法は汎用性の高いアプローチなので何かの参考になれば幸いです。 LIFULL ではともに成長できるような仲間を募っています。 よろしければこちらのページもご覧ください。 hrmos.co https://hrmos.co/pages/LIFULL/jobs/010-9999 hrmos.co