TBT(Total Blocking Time)の劣化を調査した話

こんにちは、エンジニアの中島です。

この記事はフロントエンドのパフォーマンス調査の記録を記事にしたものです。

弊社は自社プロダクトのパフォーマンス劣化を検知するためにWebPageTestを導入し、数時間に一度自動計測をするようにしています。

そこでとある日からTBT (Total Blocking Time)が劣化しているようなので原因を調査してほしいという依頼が来ました。

現象確認

まずは本当に問題が起きているかの確認です。

WebPageTestのタイムラインを見てみます。

devtoolsのスクショ大きなスタイルの再計算が走っている

たしかにいくつかのタイミングで大きめのスタイルの再計算が走っていることがわかりました。

しかしながら、これらが"ある日を境に"、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 = Peformance::Timeline::Record.from_timeline("path/to/timeline.json")
p ([date, records
  .select(&:update_layout?)
  .select{|record| record.duration > 10}
  .map(&:duration)]

(タイムラインデータのモデル) Peformance::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で計測したPeformanceのログは中身が基本的に同じなので実際に手元のブラウザでそれらのツールをネットワークブロックした時とそうでない時のログを見比べて判断していきます。

とはいえ、色々なものの影響をうけるため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 = Peformance::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-9999hrmos.co

LIFULL Creators Blog

LIFULL Creators Blogとは、株式会社LIFULLの社員が記事を共有するブログです。自分の役立つ経験や知識を広めることで世界をもっとFULLにしていきます。

TBT(Total Blocking Time)の劣化を調査した話

現象確認

原因調査

最後に