Chrome DevTools パフォーマンスタブを使ったデバッグの実践
こんにちは。GMOリザーブプラスの馬場です。
Chrome DevTools (Developer Tools, 開発者ツール, 魔法のF12) 使っていますか？Web アプリ開発者としては必ず使うであろう、非常に便利なツールですが、一方であまりにも機能が多く、私もまだまだ全然使いこなせている気がしません。
とはいいつつ、普段クライアントサイドでのデバッグはこの魔法のF12 にかなり依存しているのですが、私の場合はコンソールタブ、要素タブ (Elements)、ソースタブ (Sources)、ネットワークタブ (Network)、アプリケーションタブ (Application) を使うことが多いです。例えば、ソースタブでdebugger を仕込んでコンソールタブを使いながらその時の変数の状態を調査したり、ネットワークタブでネットワークリクエストをキャプチャしてサーバーサイドとの応答が正しいかをチェックしたり、アプリケーションタブでCookie やLocalStorage に間違いなくデータが入っているかを確認したりと、色々な使い方をしています。
ところで、少し前に「Web アプリの読み込みが遅い」という事象が社内で報告されました。その事象を解決するために、普段私自身あまり使いこなせていなかったDevTools の「パフォーマンスタブ」が大活躍した事例がありまして、本記事では実際の社内事例に基づいて、パフォーマンスタブで事象を解決するまでの道のりをご紹介します。
どういった事象か？
「弊社製品のメディカル革命の、とある環境のとあるページがとても重く、アクセスに時間がかかってしまう」という事象がありました。社内の特定の環境でのみ発生し、今のところ検証用の環境では発生していないようです。また、時間帯はまちまちで、発生しないこともあれば発生することもあり、常に事象が発生しているわけではありませんでした。
切り分けのポイント
トラブルシューティングにおいて「原因切り分けをどこから行うか？」は数多くの経験とセンスがいるところで、私自身修行中の身ではありますが、私の場合は、最初はその事象が製品起因なのか、特定の環境起因なのかの切り分けを中心に、情報を集めながらアタリを付けていきます。
まず、本事象については社内の特定の環境でのみ報告され、この時点で環境起因、例えばネットワークやハードウェアの問題の可能性が少しだけ高くなりますが、メディカル革命の場合は環境によってカスタマイズをしているケースがかなりありますので、この時点では当然原因を確定できません。
次に集めるのはネットワークやハードウェア情報をヒアリングします。今回は回線速度やネットワーク構成にも問題はなく、ハードウェアスペック的にも問題がありませんでした。
ここまでは最初の事象報告の段階で質問していく感じですが、並行して、トラブルシューティングの中で最も重要な事象再現の準備します。今回はアクセスが重い、遅延というある意味主観が入るトラブルだったので再現が難しかったのですが、事象が発生している環境と設定を同じにした検証用の環境を用いると、確かにアクセスが重い状況がある、という点を再現できました。
さて、ここで、アクセスができない、読み込みができないなど、いわゆる0/1 の問題であれば、ログを調査したり、クライアントサイドのリクエストをネットワークタブで追ったり、それに伴うサーバーサイドのロジックを見ていく流れになると思います。今回はアクセス遅延という、ある意味0/1 ではない、0.5 的な問題で、ログでエラーが出ているわけではなく、コンソールタブやネットワークタブでも特段エラーが出ているわけではありませんでした。
ということで、このような0.5 的な問題への立ち向かい方として、まずは当然ログを見ます。今回は幸いにもアクセス遅延ログ的なものを取っていたため、そこで遅延が発生していることが数値として出てきていました。そして遅延は、特定ページの読み込み の開始から読み込みの完了までの時間で発生していて、遅延がかかっている処理の中では、サーバーサイドへのGET リクエストとそれが返ってくるまでのいわゆるサーバーサイドロジックと、取得してきたデータの描写のクライアントサイドロジックの2 つが関わっていることが分かりました。
次に、前者のサーバーサイドへのGET リクエストについては、クライアントからのネットワークアクセス遅延か、もしくはサーバーサイドでの情報取得に時間がかかっていると予想ができますが、Chrome のネットワークタブを見ると、この点にアクセス遅延は発生していないため、この時点でネットワーク遅延及びサーバーサイドでの処理遅延という2つの選択肢が消えました。
そこで、今度は後者の、取得してきたデータの描写遅延を疑います。クライアントサイドの処理なので、Javascript の処理をソースから見ることもできますが、いかんせん時間がかかります。そこで、本記事のテーマである「パフォーマンスタブ」の出番です。パフォーマンスタブでできることは色々ありますが、その中でも今回は最も強力なパフォーマンスのレコーディング機能が今回は大活躍しました。
パフォーマンスタブを使ってみよう
今回は本事象の実例に近い以下のサンプルコードを使って模擬的に調査していきます。
<!DOCTYPE html>
<html lang="ja">
<head>
<meta charset="UTF-8">
<title>パフォーマンスタブ チュートリアル</title>
</head>
<body>
<h1>パフォーマンスタブ チュートリアル</h1>
<button onclick="runTest()">テスト実行</button>
<div id="result"></div>
<script>
function runTest() {
const resultDiv = document.getElementById("result");
resultDiv.innerText = "テスト実行中...";
setTimeout(() => {
let arr = [];
arr[1000000] = 2;
arr[2000000] = 1;
arr[3000000] = 0;
const startTime = performance.now();
for (let i = 0; i < 100; i++) {
let res = arr.sort(function (a, b) {
return a - b;
});
}
const endTime = performance.now();
const duration = endTime - startTime;
resultDiv.innerText = `結果: ${duration.toFixed(3)} ミリ秒`;
}, 50);
}
</script>
</body>
</html>この時点で怪しいポイントはわかる人にはわかると思いますが、コードの内容としては、3つの値が入った疎な配列に対して、100回のソートをかけるだけです。test.html などというファイルを作って上記コードをコピペして、テスト実行ボタンをクリックすると、自動的に100回のソートが走り、その合計時間が表示されます。
実行結果は約13秒でしたね。たかだか100回の計算にしてはめちゃくちゃ遅いですが、これは単にJavascript でempty (空のスロット) を含む疎かつ巨大な配列に対してそのままソートをかけてしまうと、大幅に時間がかかってしまうという問題です。これを見ると、そもそも事象としてはわかりやすいですし、パフォーマンスタブを使うまでもないと思いますが、今回はかなり複雑なロジックの中に、これに近い書き方をしていて、かつ特定の設定の組み合わせを有効化している環境でしか発生しなかったため、なかなか見つけることができませんでした。
さて、パフォーマンスタブを使ってみましょう。今回はパフォーマンスのレコーディングだけを実行します。まずは普通にページを読み込み、F12 を押してDevTools を開きます。
次に、画面左上の赤で囲まれたボタンをクリックするとキャプチャが開始されるので、キャプチャ開始後、すぐにテスト実行ボタンをクリックします。
テストが完了して実行時間が画面に表示されたら、パフォーマンスレコーディングを終了します。
すると、上記画面のような、ややビジーな画面が出てきます。が、ここで注目すべきは中央のMain と表示されているメインスレッド、いわゆるユーザーのイベントや描画を処理するスレッドで、(基本的に) ブラウザはシングルスレッドにてページ内のJavascript を実行するわけで、必然的に処理の重い関数がページ全体の読み込みを妨げることが発生します。
MDN Web Docs 用語集 Main thread (メインスレッド)
https://developer.mozilla.org/ja/docs/Glossary/Main_thread
今回の事象も、実はあるJavascript のロジックの処理がメインスレッドを占有していたため、ページ全体の読み込み速度に影響を与えていました。
さて、パフォーマンスレコーディングの画面に戻ります。下部のCall treeを見ると、ある無名関数に99.9％ の処理時間がかかっていることが分かります。
右側のソースファイルをクリックすると、以下のように、関数に対してより詳細な処理時間が分かります。スゴイ。
ということで、arr.sort の処理に12664.5 ms かかっていることがすぐに分かり、このように原因が特定できれば、例えば疎な配列を作らないようにする、などの対応を考えられるというわけです。 非常に簡単な事例ではありましたが、パフォーマンスタブを開き、キャプチャをかけ、メインスレッドの関数呼び出しの時間を調査する、という手法は汎用的で非常に強力です。
なお、今回は紹介していませんが、レコーディング中のスクリーンショットを連続で取得したり、事象が発生している環境に合わせるためにネットワーク帯域を絞ったりと、パフォーマンスタブは他にも様々な使い方ができます。興味がある方は下記ドキュメントを読んでみてください。
パフォーマンス パネル: ウェブサイトのパフォーマンスを分析する
https://developer.chrome.com/docs/devtools/performance/overview?hl=ja
まとめ
本記事では、Chrome DevTools のパフォーマンスタブについて、実際の社内事例をもとに使い方をお伝えしました。DevTools は非常に便利なものの、機能が豊富すぎるがゆえにキャッチアップがなかなか追いつかないです。しかも最近AI と連携され、質問次第で自動的にHTML を書き換えることができるようになっていて、これまで以上に機能が増えてきています。こういった機能を知っていると知らないとでは、トラブルシューティングの時間に大きく差が出てしまうため、私自身も引き続き継続的にキャッチアップしていきたいです。
は一緒に働く仲間を募集しています