こんにちは！
スペースマーケットでフロントエンドエンジニアをしているmizukiです。
少し前に新規でコンポーネントを実装したのですが、パフォーマンスについてはあまり意識せずに実装したところ、画面の読み込みや処理にかなり遅延が発生してしまいました。
そこから処理速度を上げて遅延をなくすためにパフォーマンスチューニングをしたので、その話について書いていきたいと思います。
数値上の結論を先にお伝えすると、この改善をしたことで、当初は50秒ほどかかっていたユニットテストが7~8秒ほどまで短縮することができました。
（改めて文字に起こすと改善前は時間かかりすぎですね・・・）
問題発覚
コンポーネント実装時には、PCのchromeでローカル環境を立ち上げて挙動を確認していました。
コンポーネントではAPIからデータ取得後に少し複雑な加工処理を行なっていましたが、PCのchromeで見る分には特に遅延は気にならない状況でした。
しかし、ユニットテストを書いて実行してみたところ、30ケースほどの実行に50秒ほどかかっており、平均すると1ケースあたり2秒弱かかっていることが判明しました。。。
試しにchromeのPerfomanceタブからCPUを4分の1にスローダウンさせたところ、たしかに体感でも分かるくらいの遅延が発生していました。
原因調査
原因を調べるために、主に以下3点の方法で調査をしていきました。
①ReactDeveloperToolのProfilerから時間を計測
chromeの拡張機能であるReactDeveloperToolを入れている場合は、この拡張機能のProfilerから画面操作した際の処理に時間がかかっているかを計測することができます。
Profilerタブを開き、左上にある青色の丸をクリックすると記録が開始されて丸の色が赤色に変わるので、画面の読み込みや操作を行い、再度この丸をクリックします。
すると、その操作によってどのコンポーネントでどのくらい処理に時間がかかっているかを確認することができます。
上部にあるメニューから、「Flamegraph chart」を選択するとコンポーネントが読み込まれた順に、「Ranked chart」を選択すると読み込みに時間がかかってる順に、それぞれ読み込みにかかった時間を確認することができます。
②console.timeを使用して、処理を細かい単位に分けて時間を計測
どのコンポーネントに時間がかかっているかをある程度特定ができたら、次はコード内にconsole.timeを仕込んでもっと細かく計測していきます。
例えば、3つのpropsを受け取ってそれぞれを加工した後、画面に表示しているコンポーネントがあったとします。
const Component = ({hoge, fugaList, piyo}) => {
const data1 = useHoge(hoge)
const data2 = fugaList.map((fuga) => {
// ループ処理
})
const data3 = formatData(piyo)
return (
<div>
<div>{data1}</div>
<ul>
{data2.map((data) =>
<li>{data}</li>
))}
</ul>
<p>{data3}</p>
</div>
)
}
それぞれの処理にかかった時間を調べるために、以下のようにconsoleを仕込んでいきます。
console.timeとconsole.timeEndで計測したい全体を囲い、途中でもログを出力したい時にはconsole.timeLogを使用します。
それぞれの第一引数には同じテキストを、timeLogの第二引数には目印となるテキストを入れておきます。
const Component = ({hoge, fugaList, piyo}) => {
+ console.time('時間計測')
const data1 = useHoge(hoge)
+ console.timeLog('時間計測', 'ループ処理前')
const data2 = fugaList.map((fuga) => {
// ループ処理
})
+ console.timeLog('時間計測', 'ループ処理後')
const data3 = formatData(piyo)
+ console.timeEnd('時間計測')
return (
<div>
<div>{data1}</div>
<ul>
{data2.map((data) =>
<li>{data}</li>
))}
</ul>
<p>{data3}</p>
</div>
)
}
こうすることで、検証機能のconsoleから確認すると
時間計測: 1.234ms ループ処理前 // 計測開始からループ処理前のconsole.timeLogまでにかかった時間
時間計測: 5.678ms ループ処理後 // 計測開始からループ処理後のconsole.timeLogまでにかかった時間
時間計測: 5.912ms // 計測開始からconsole.timeEndまでにかかった時間
のようにそれぞれにかかった時間を調べることができます。
仮に上記の結果になっていたとすると、「ループ処理後」のログで急に時間がかかっているので、fugaListをmapしているところで時間がかかっているのではないかという仮説を立てることができます。
③useEffectを使用して、余分なレンダリングが起こっていないかを調査
最後に時間の計測だけではなく余分にレンダリングが行われてしまっていないかを確認していきます。
useEffectを使用してその依存配列に確かめたいデータを入れておくと、そのデータが余分に読み込まれていないかを計測することができます。
const Component = ({hoge, fugaList, piyo}) => {
+ useEffect(() => {
+ console.log('hogeのレンダリング')
+ }, [hoge])
const data1 = useHoge(hoge)
const data2 = fugaList.map((fuga) => {
// ループ処理
})
const data3 = formatData(piyo)
return (
<div>
<div>{data1}</div>
<ul>
{data2.map((data) =>
<li>{data}</li>
))}
</ul>
<p>{data3}</p>
</div>
)
}
例えばここで
hogeのレンダリング
hogeのレンダリング
hogeのレンダリング
のようにログに出力されていたら、3回も呼ばれているということは親要素でmemo化できていなくて余分な処理が走っているかもしれない、といった仮説を立てることができます。
試したこと
ここまでに書いた方法で処理が重くなってしまっている原因の仮説を立てたら、あとはそれを検証していきます。
僕が今回やったことは以下です。
・ループ処理をダイエット
console.timeで調べたところループ処理に時間がかかっていることが判明したため、いろいろな書き方をしてなるべく処理に時間がかからない方法を模索しました。
・ライブラリが定義している関数を自前で用意
同じく時間がかかっている箇所に、日付を扱うライブラリであるdayjsからimportした関数を使用している箇所が挙げられました。
そのため、一部置き換えられる箇所はdayjsが用意した関数を使用せず自前で処理を書いたりすることで処理にかかる時間を軽減しました。
（※dayjsの関数を使用するとtimezoneなどをよしなに処理してくれるというメリットがありますが、弊社では元々timezoneを自前で管理していたため、特に影響はなくそれができたという背景もあります。）
・useMemo、useCallbackで余分な更新を防ぐ
useEffectで余分なレンダリングが起きていないかを調べたところ、useMemoやuseCallbackで余分なレンダリングを防ぐ余地のある箇所がいくつか見つかりました。
useMemo、useCallbackで余分なレンダリングが行われないようにすることも徹底しました。
結果
結果として、冒頭でも書いた通り、UTが50秒くらいから4~5秒ほどになりました。
さすがにここまで処理が重いと気づくこともあるかもしれませんが、そうでなくてもちょっと重い処理していそうだな〜と思ったときには処理時間などのパフォーマンスまで意識しないといけないなと改めて思いました。
おわりに
最後に宣伝です！
スペースマーケットでは一緒に働く仲間を募集しています！
ちょっと興味あるかも、話聞くだけなら聞いてみたいかも、といった方でも大歓迎ですので、以下のサイトからご応募ください🙌
▼SRE/インフラエンジニア
▼バックエンドエンジニア
▼Androidエンジニア（iOSも大歓迎です！）
▼弊社エンジニア採用ページ（迷ったらこちらからどうぞ！）
スペースを簡単に貸し借りできるサービス「スペースマーケット」のエンジニアによる公式ブログです。 弊社採用技術スタックはこちら -> whatweuse.dev/company/spacemarket
Discussion