処理時間測定その2--profilerやってみた

x

作ったscriptが重いかどうか知りたいだけだった
・・・なのに深みにはまってしまいました
誰かが正しい解説記事を書いてくれると期待して体験記を書きます
読者対象は中級者向けのCluster記事を書けそうな人です
  2024.0328 更新
目次----------------
記事の目的 
信頼できるミリ秒を探し求めた経緯
時間についてのエッセイ
Unity profiler お勧め手順案A
その他の手順と疑問点
参考文献
環境その他


記事の目的 ---------------
作ったscriptの処理時間を知るためにUnity profiler を再勉強してみました
Unity profiler の一般の記事は ありますが 難しく奥が深く発展途上のようです
さらに Cluster CCK で成立するのかという 条件付きで学習せざるを得ません
どこかに不具合やちょっとしたバグがあれば なおさらつまづきます
そこで 条件として
  CCK + かおもさんのエミュレーター + Unity profiler 
の環境で解説記事がほしいです
問題提起をかねて体験記を書いてみます

 

信頼できるミリ秒を探し求めた経緯-------------------------------------------
処理負荷をどれで判断するか深入りした経過です
簡単なものから難しいものの順で述べます

1. Cluster本番の 統計  ------------------v
Clusterのワールドに入った時の右上に表示される統計です
他人のワールドも測定できます  ms=ミリ秒があります
   FPS:(CPU  ms Render  ms)
リアルタイムで数値が変化するので最初のうちは頼りにしていました
アバターの見る風景を動かす・・つまりカメラを動かすと
即刻にrenderのミリ秒が変化して わかりやすかったです
重たいバーカウンタや鏡や多数のアバターに視線を向けると
グラフィックの処理負荷が重くなるのがわかります
しかし、script負荷や厳密な分析や比較には不便を感じます        
数値が刻々と変化するのでどの値を記録すればいいのでしょう
VRの場合はsteamの ミリ秒表示を使う手もあります
Clusterの値とは同じではないようです

2. Cluster本番の Consoleのエラーと警告------------^
ワールド制作者にしか見えないアレです
処理時間に関する警告が出ることがあります
WARN: script execution (383ms) exceeded the soft limit (50ms). 
Scriptに関するエラーもあります
Script has allocated too much memory
これが不便であるということは別記事に書きました

3. UnityのPlay Gameの statistics (統計表示)    ------------
このなかで SetPass calls の値は グラフィック負荷の判断に使えました
しかし、処理時間を表すミリ秒は不安定でコロコロ変わりすぎます
しかも3種類あります 
  FPS(  ms) CPU:main msの値 render Thread msと 
これらは何を意味しているのでしょうか
簡易的に瞬間的な変動を知るぐらいにしか役立たないように思います
目視で平均値を推定して記録しようとしても 
script負荷や厳密な分析や比較には不便を感じます

4. Unity Profilerで フレームのミリ秒を確認できます ------------
ProfilerのTimeLineの並びに  CPU GPU のミリ秒が表示されています
グラフのどのあたりを抽出するかはユーザーがClickでえらべます
スパイクもえらべます。
平均的な値をしりたければ 
後述の  Unity Profile Analyzer で 中央値の時刻(フレーム)を選べます
Medianのms値の横の数字がフレームで
それをclickすると Profiler側が変化します
Profiler側で その時刻(フレーム)をclickしたのと同じことになるようです
選択したフレームの秒数は Analyzerの値と一致します
グラフをじっくり観察して原因を洞察するには向いています
しかし症状を記録したり報告書にするにはちょっと不便です
 

5. Unity Profile Analyzer    ------------
原因を洞察するには向いていませんが症状を記録したり報告書にするのに便利です
平均値や中央値を算出してくれています。 
詳細は手順の章を参照ください
いまのところ この中央値が 信頼できて再現性の高い 記録向きの値と思っています
1フレームの処理時間です    
scriptを使ったワールドの比較に使えそうです

追記    その他の測定方法    ------------
profilerの使い方の資料を見聞きすると
実機での測定や ビルドしてからの測定が書かれています
editorのよけいな影響を受けずに理想的と書かれています
Cluster CCKの場合  そういう条件での測定がなさそうです
なお、standalone(profiler)での測定は未調査です
 
時間についてのエッセイ-----------------------------------
時間についての エッセイ または我流の解釈です
1フレームってどうなっているの?-----------------------------------
◯ わかっていたつもりが どこかで混同していたかもしれません
用語が同じでも 畑が違うと前提や使い方が違うということがあります
そもそも映像業界の時間の観念とゲームの時間の観念が違うようです
1フレームという用語が AfterEffectとUnityで同じとは限らないようなものです
身についた時間の観念と思い込みが邪魔をします。この際に整理してみました
◯ 映像編集で 1フレームの時間の刻みは一定であること
を疑ったことはありませんでした
1フレームの時間の長さが毎回不揃いで 
一定間隔ではないなんて 映像編集では考えたことがありません
数百フレーム集計したときに だいたい11msに辻つまがあってればいいなんて
なんと泥臭いテクノロジーでしょうか
◯  交通機関に例えてイメージしてみました・・・
例えば 「CPU と GPUのどちらの処理時間に注目するべきか」
・・・という疑問を考えたときのことです
CPUとGPUは 同じ一つの線路上にあるのではなく
交通機関に例えると電車とバスという 異なる路線にあると考えました
想像してみてください、環状線は一定のサイクルで
列車(スレッドやタスク)を処理していきます
環状線から吐き出された乗客は バスに乗り継ぎます
もし、バスが過剰積載で市内循環の到着に遅れが生じたら
環状線は発車時刻を少しずらして対応するかもしれないし
ダイヤグラムを変えずに1周遅れの列車で運行するかもしれないし
プラットフォームにあぶれた乗客をまとめて運ぶ
特別列車を繰り出すかも知れない
 
こうして1サイクルの時間が変動すると考えます 
時間が映像編集のような絶対的なものでなく
動的に曖昧で不揃いでケースバイケースで目標値に合わせよう
といろんな工夫があるらしい
 
構造や階層が複雑です CPUとGPUの処理時間を分けて表示すれば
どちらに原因があるか絞りやすいのでしょう
災害時に交通網が乱れた時に環状線とバス路線でどちらに原因があったか
追求するようなものです
正常なときにどのように働いているか見ておかないと
いざというときに使えない profilerはそういう泥臭いツールのようです
では、もう少し具体的な体験を語ってみましょう
◯ Visual Studio Code だけでは処理時間の手がかりがほとんどありません
「 onUpdate  は0.02秒に1回程度呼ばれる。0.02秒=20ms」
・・・という理解を  どこで読んだのでしょうか 20msは不適切な数字です
1÷60=0.016666…秒(≒0.02秒)これを四捨五入するなら 17msではないでしょうか
◯ 以下の文章では かおもさんのエミュレーターに合わせて
1フレームが約11msを目標値とするという文章で進めます
英語動画では Budget=予算 という言葉が使われていました
VR環境90FPSを想定して  1÷90=0.011111…秒(≒0.011秒) 四捨五入して11msですね
◯◯ どのミリ秒の数値を判断基準にすればよいのでしょうか-------------------------
◯ scriptの処理負荷を検討するときは主にCPUの数値だけでいいのだと思います
最初は (CPUミリ秒 - GPUミリ秒) = script処理時間  だろうかと考えました
1フレームの総計に グラフィックやscriptやその他の
処理時間が含まれていると思われたからです
厳密にはそうではないようです
◯ CPUとGPUの時間きざみはレンガ積みのようにズレているようです
いくつか測定しているとたまに GPUの方が大きい値になることがあります
これは変だぞと気づいて理解を変えてみました 
交通機関に例えるのは別に書きました。ダイヤグラムではないですが
レンガ積みのようにズレている というイメージです。
これは動画資料の 解説図にも登場しています
  -------------------------0秒------------------------------約11ms
 
         一つ前のCPU処理-----||--------CPUの1フレーム----------||--------次のCPU処理---
             |---一つ前のGPU処理------|             |--------GPU---------|

CPU処理が 計算準備して GPUに処理を投げる・・・と表現されていました
図はGPU処理がCPUの次の処理に食い込むケースを想定しています
計算負荷がふえると どちらも待ち時間を調整してタイミングをあわせているようです
GPUバウンド  CPUバウンドをほのめかしましたが 間違っているかもしれません)
timlineを見ると idleとかwaitというブロックが目につきます 
そういう待ち時間や調整が見受けられます
いくつか測定していて  大幅にGPUの処理時間がCPUを上回り続けることがありませんでした
これは多分、GPUの方が大きい値になった場合は次のCPUの待ち時間に食い込んで 
次のCPUの処理時間を長くすることに吸収されるからだろうと思います
 

 

手順案 準備部分    -------------------v
Window > Analysis > Profilerを開いています
Window > Analysis > Profile Analyzer     を開いています
これは標準ではメニューにありません PackageManagerからインストールしています
なお今回の測定データは CCKTemplateの    MinimalSample.unity を使っています

 

手順案A    [ playMode  +  PlayGame]    の場合    -------------------v
◯ 文献や動画を参考に現時点のまとめです  間違っていたらごめんなさい
まずProfiler Modulesは defaultで Play Mode のはずです
Profiler の赤丸ボタンをオンの状態で playgameオンにして 測定します
適度に測定グラフが安定したところで止めます 
ちなみに defaultでは300フレームしか記録できません
CPU usage windowで クリックすると止まります
これは playgame pause || をクリックしたのと同じことのようです
ProfilerのCPU usage windowで 適当な時刻(フレーム)を選べます
肉眼でグラフのスパイクの時刻を選んだりできます
今回は平均的な処理時間を知りたいので 
肉眼でグラフの平均的な時刻を選んでいましたが、それよりは
Profile Analyzerの Frame  Summary の Median の値を使いたいと思います
平均値ではなく中央値を使います 数値の再現性と信頼性が上がりました
今回の測定では11.08ミリ秒です
ちなみに測定データは     CCKTemplateの    MinimalSample.unity    です
床と空しかない軽いデータですが かおもさんのエミュレーターの FPS制限90FPS設定によって
11msに調整されているはずです 予定どおりでした

この手順に間違いない・・・と思いたいわけです。 
なので他の手順も調べます

 
手順案B      [ game画面が見えない状態]     -------------------v
◯ 考察・・・これはたぶん測定失敗だと思います
profilerを最大化したり game画面が見えない状態で 測定すると
TimeLineのrender Threadに    緑ブロックがびっしり出現します
測定データが    MinimalSample.unity でない場合も同様でした
拡大するとピアノ鍵盤のようです
CCKのみ場合 ピアノ鍵盤症状は現れないので
かおもさんのエミュレーターFPS制限の副作用と考えられます
文献にそのような注意事項が見当たらないので どなたか解説してほしいです
とにかく 測定時には 念のためそうならないように注意することにします
ちなみに game画面は freeAspectよりも    FullHD1920x1080固定にしています

 
手順案C      [ EditMode ]  だけの場合    -------------------v
1フレームが4msという小さい値がでます
シーンの内容にかかわらずほぼ同じ値になるので
これは    UnityEditorだけでの処理負荷のようです
かおもさんのエミュレーターの FPS制限90FPS設定が効いてないようです
◯ 考察・・・風袋引きのようなものでしょうか マシンによる差異を差し引きするのでしょうか

 

手順案D      [ EditMode + Play  ]   の場合    -------------------v
EditMode  で PlayGameすると 別の測定結果がでます
かおもさんのエミュレーターの FPS制限90FPS設定が効いてないようです
TimeLineの構造がシンプルなので何かに使えそうです どなたか解説してほしいです
◯ 考察・・・たまに変な値になるし、文献にもないし  よくわかりません

◯ 補足    profilerのCPU USAGEグラフの見方-------------
profilerのCPU USAGEのグラフの横軸はフレームです。縦軸がミリ秒です。
横軸が普通の時間ではなく  面積が時間ということになります
1フレームの時間が一定という暗黙の前提ならば横軸も普通の時間軸だろう
・・とうっかり勘違いしていました。 
映像編集で身についた時間の観念と思い込みが邪魔をします。
◯ 補足    profilerのtimelineの見方-------------
CPU USAGEで適当なフレームを選択しないと何も見えてきません
横軸は時間です  0秒とは何でしょう
どこからどこまでが1フレームか
表示をスケールすると 白い枠線が2本見えてきます
 
手順を 自分用にまとめましたが疑問点 未検証点 多々あります
この理解であっているのかどうかの検証するための文章です
参考にするかたは 自己責任でお願いします
 
 
参考文献------------------------------------------------
 【Unity】CPUプロファイラでパフォーマンスを改善する 前編
テラシュールブログ  2016.0509 山村 達彦 後にユニティ・テクノロジーズ・ジャパン
【Unity】Profilerの実用的な使い方!パフォーマンス改善に必要な部分だけサクッとまとめ2019-09-19
Haruki Yano   Unityエンジニア
プロファイリング入門  英語 2020/05/25
スピーカー:Ciro Continisio(EMEA 地域リードエヴァンジェリスト
パフォーマンス最適化 入門~2021年版~ - Unityステーション 42分
黒河 優介   
Unity2021.2から始めるプロファイリング入門 - CEDEC2021 2021/08/26   動画21分
講演者:黒河 優介(ユニティ・テクノロジーズ・ジャパン株式会社 
 
環境その他-------------------------
環境 Unity 2021.3  CCK2.9.0      かおもさんのエミュレータ(CSEmulator2.22)  
Profile Analyzer 1.1.1 cluster v2.116(2024/03/18)
・・以上  専門家ではないので理解に間違いがあればお許しください
#cluster #ClusterScript