ブログ

Nrealアプリの実機でのCPU処理計測(UnityアプリのスクリプトでのCPU処理計測)

背景

  • DevelopmentBuild できない ので、実機でUnityプロファイラで計測できない
    • 2022/8/10 追記:NRSDK 1.9.3 では Development Build で実機起動できるようになった
  • NRSDK/Prefabs/FPSCanvas を流用すればFPS計測はすぐにできる
  • スクリプト処理時間、レンダリング時間、NRKernel処理時間なども知りたい
  • Android Studio の CPU Profile は低レイヤーすぎる(スレッド単位の計測)

結論

  • Unityスクリプトライフサイクル に沿って Time.realtimeSinceStartup で打刻して、差分からCPU処理時間を求める
    • Nrealアプリに限らず、一般的なUnityアプリでも同様
  • 以下の「自前実装」とは、Unity にて自分で実装していく部分のこと
Update
のCPU処理時間
「最後の MonoBehaviour の yield null 時刻」から
「最初の MonoBehaviour の Update 時刻」を引いた値
Animation
のCPU処理時間
「最初の MonoBehaviour の LateUpdate 時刻」から
「最後の MonoBehaviour の yield null 時刻」を引いた値
LateUpdate
のCPU処理時間
「最後の MonoBehaviour の LateUpdate 時刻」から
「最初の MonoBehaviour の LateUpdate 時刻」を引いた値
Rendering
のCPU処理時間
「最初の MonoBehaviour の yield WaitForEndOfFrame 時刻」から
「最後の MonoBehaviour の LateUpdate 時刻」を引いた値
Update_NRKernel
のCPU処理時間
「最初の MonoBehaviour の Update 時刻」から
「自前実装の最初の MonoBehaviour の Update 時刻」を引いた値
LateUpdate_NRKernel
のCPU処理時間
「最初の MonoBehaviour の LateUpdate 時刻」から
「自前実装の最初の MonoBehaviour の LateUpdate 時刻」を引いた値

方法

  • Unity にて3つの C# Script を作成
    • アプリ全体の最初と最後に実行される MonoBehaviour  と、自前実装の最初の MonoBehaviour の3つ
    • クラス名はそれぞれ ProfilingFirstMonoBehaviour, ProfilingFirstMonoBehaviour, Framework とする
  • 3つとも Main Camera などにアタッチする
  • インスペクタから Execution Order を開き、下図のように設定する
    • Unity の MonoBehaviour は実行順序不定だが、これで「最初」→「NRKernel」→「自前実装の最初」→「最後」の順番で実行される MonoBehaviour が得られる
    • NRKernel から NRKernel.NREmulatorManager が外れているが、実機では実行されないので問題ナシ

Nreal_Execution_Order

コード

Profilingクラスはデータ集計するだけなので、MonoBehaviour を継承しない。

using System.Collections;
using System.Collections.Generic;
using UnityEngine;

public sealed class ProfilingFirstMonoBehaviour : MonoBehaviour
{
    // Start is called before the first frame update
    void Awake()
    {
        mWaitForEndOfFrame = new WaitForEndOfFrame();
        StartCoroutine(coroutine_WaitForEndOfFrame());
    }

    // Update is called once per frame
    void Update()
    {
        Profiling.Instance.OnUpdate_FirstMonoBehaviour();
    }

    void LateUpdate()
    {
        Profiling.Instance.OnLateUpdate_FirstMonoBehaviour();
    }

    private IEnumerator coroutine_WaitForEndOfFrame()
    {
        for (; ; )
        {
            yield return mWaitForEndOfFrame;
            Profiling.Instance.OnYieldWaitForEndOfFrame_FirstMonoBehaviour();
        }
    }

    private WaitForEndOfFrame mWaitForEndOfFrame;
}

 

using System.Collections;
using System.Collections.Generic;
using UnityEngine;

public sealed class ProfilingLastMonoBehaviour : MonoBehaviour
{
    // Start is called before the first frame update
    void Awake()
    {
        StartCoroutine(coroutine_null());
    }

    // Update is called once per frame
    void Update()
    {
    }

    void LateUpdate()
    {
        Profiling.Instance.OnLateUpdate_LastMonoBehaviour();
    }

    private IEnumerator coroutine_null()
    {
        for (; ; )
        {
            yield return null;
            Profiling.Instance.OnYieldNull_LastMonoBehaviour();
        }
    }
}

 

using System.Collections;
using System.Collections.Generic;
using UnityEngine;

public sealed class Framework : MonoBehaviour
{
    // Start is called before the first frame update
    void Awake()
    {
    }

    // Update is called once per frame
    void Update()
    {
        Profiling.Instance.OnUpdate_GameFirstMonoBehaviour();

        // 30秒経過時にCPU処理時間をログ出力
        if (!mIsPrintProcessingTime && Time.realtimeSinceStartup > 30f)
        {
            mIsPrintProcessingTime = true;
            Debug.Log($"[Profiling]Update: {Profiling.Instance.ProcessingTimeAverage_Update:f1} ms (NRKernel: {Profiling.Instance.ProcessingTimeAverage_Update_NRKernel:f1} ms)");
            Debug.Log($"[Profiling]Animation: {Profiling.Instance.ProcessingTimeAverage_Animation:f1} ms");
            Debug.Log($"[Profiling]LateUpdate: {Profiling.Instance.ProcessingTimeAverage_LateUpdate:f1} ms (NRKernel: {Profiling.Instance.ProcessingTimeAverage_LateUpdate_NRKernel:f1} ms)");
            Debug.Log($"[Profiling]Rendering: {Profiling.Instance.ProcessingTimeAverage_Rendering:f1} ms");
            Debug.Log($"[Profiling]All: {Profiling.Instance.ProcessingTimeAverage_All:f1} ms");
        }
    }

    void LateUpdate()
    {
        Profiling.Instance.OnLateUpdate_GameFirstMonoBehaviour();
    }

    private bool mIsPrintProcessingTime = false;
}

 

using System.Collections;
using System.Collections.Generic;
using UnityEngine;

// 処理計測クラス
// 複数個所から呼ばれるのでシングルトンにしている
public sealed class Profiling
{
    public void OnUpdate_FirstMonoBehaviour()
    {
        // 計測開始:Update
        mStartTime_Update = Time.realtimeSinceStartup;

        if (++mIndex == cIndexMax)
        {
            mIndex = 0;
        }
    }

    public void OnUpdate_GameFirstMonoBehaviour()
    {
        // 計測終了:Update_NRKernel
        mProcessingTime_Update_NRKernel = (Time.realtimeSinceStartup - mStartTime_Update) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_Update_NRKernel += mProcessingTime_Update_NRKernel;
        }
        else
        {
            mProcessingTimeAverage_Update_NRKernel = mProcessingTimeSum_Update_NRKernel / cIndexMax;
            mProcessingTimeSum_Update_NRKernel = 0f;
        }
    }

    public void OnYieldNull_LastMonoBehaviour()
    {
        // 計測終了:Update
        mProcessingTime_Update = (Time.realtimeSinceStartup - mStartTime_Update) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_Update += mProcessingTime_Update;
        }
        else
        {
            mProcessingTimeAverage_Update = mProcessingTimeSum_Update / cIndexMax;
            mProcessingTimeSum_Update = 0f;
        }

        // 計測開始:Animation
        mStartTime_Animation = Time.realtimeSinceStartup;
    }

    public void OnLateUpdate_FirstMonoBehaviour()
    {
        // 計測終了:Animation
        mProcessingTime_Animation = (Time.realtimeSinceStartup - mStartTime_Animation) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_Animation += mProcessingTime_Animation;
        }
        else
        {
            mProcessingTimeAverage_Animation = mProcessingTimeSum_Animation / cIndexMax;
            mProcessingTimeSum_Animation = 0f;
        }

        // 計測開始:LateUpdate
        mStartTime_LateUpdate = Time.realtimeSinceStartup;
    }

    public void OnLateUpdate_GameFirstMonoBehaviour()
    {
        // 計測終了:LateUpdate_NRKernel
        mProcessingTime_LateUpdate_NRKernel = (Time.realtimeSinceStartup - mStartTime_LateUpdate) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_LateUpdate_NRKernel += mProcessingTime_LateUpdate_NRKernel;
        }
        else
        {
            mProcessingTimeAverage_LateUpdate_NRKernel = mProcessingTimeSum_LateUpdate_NRKernel / cIndexMax;
            mProcessingTimeSum_LateUpdate_NRKernel = 0f;
        }
    }

    public void OnLateUpdate_LastMonoBehaviour()
    {
        // 計測終了:LateUpdate
        mProcessingTime_LateUpdate = (Time.realtimeSinceStartup - mStartTime_LateUpdate) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_LateUpdate += mProcessingTime_LateUpdate;
        }
        else
        {
            mProcessingTimeAverage_LateUpdate = mProcessingTimeSum_LateUpdate / cIndexMax;
            mProcessingTimeSum_LateUpdate = 0f;
        }

        // 計測開始:Rendering
        mStartTime_Rendering = Time.realtimeSinceStartup;
    }

    public void OnYieldWaitForEndOfFrame_FirstMonoBehaviour()
    {
        // 計測終了:Rendering
        mProcessingTime_Rendering = (Time.realtimeSinceStartup - mStartTime_Rendering) * 1000;
        if (mIndex != cIndexMax - 1)
        {
            mProcessingTimeSum_Rendering += mProcessingTime_Rendering;
        }
        else
        {
            mProcessingTimeAverage_Rendering = mProcessingTimeSum_Rendering / cIndexMax;
            mProcessingTimeSum_Rendering = 0f;
        }
    }

    public float ProcessingTime_Update { get { return mProcessingTime_Update; } }
    public float ProcessingTime_Animation { get { return mProcessingTime_Animation; } }
    public float ProcessingTime_LateUpdate { get { return mProcessingTime_LateUpdate; } }
    public float ProcessingTime_Rendering { get { return mProcessingTime_Rendering; } }
    public float ProcessingTime_Update_NRKernel { get { return mProcessingTime_Update_NRKernel; } }
    public float ProcessingTime_LateUpdate_NRKernel { get { return mProcessingTime_LateUpdate_NRKernel; } }

    public float ProcessingTimeAverage_Update { get { return mProcessingTimeAverage_Update; } }
    public float ProcessingTimeAverage_Animation { get { return mProcessingTimeAverage_Animation; } }
    public float ProcessingTimeAverage_LateUpdate { get { return mProcessingTimeAverage_LateUpdate; } }
    public float ProcessingTimeAverage_Rendering { get { return mProcessingTimeAverage_Rendering; } }
    public float ProcessingTimeAverage_All { get { return ProcessingTimeAverage_Update + ProcessingTimeAverage_Animation + ProcessingTimeAverage_LateUpdate + ProcessingTimeAverage_Rendering; } }
    public float ProcessingTimeAverage_Update_NRKernel { get { return mProcessingTimeAverage_Update_NRKernel; } }
    public float ProcessingTimeAverage_LateUpdate_NRKernel { get { return mProcessingTimeAverage_LateUpdate_NRKernel; } }

    public static Profiling Instance
    {
        get
        {
            if (sInstance == null)
            {
                sInstance = new Profiling();
            }
            return sInstance;
        }
    }

    private Profiling() { }

    private static Profiling sInstance = null;
    private float mProcessingTime_Update = 0f;
    private float mProcessingTime_Animation = 0f;
    private float mProcessingTime_LateUpdate = 0f;
    private float mProcessingTime_Rendering = 0f;
    private float mProcessingTime_Update_NRKernel = 0f;
    private float mProcessingTime_LateUpdate_NRKernel = 0f;

    private float mStartTime_Update = 0f;
    private float mStartTime_Animation = 0f;
    private float mStartTime_LateUpdate = 0f;
    private float mStartTime_Rendering = 0f;

    private static readonly int cIndexMax = 60;
    private int mIndex = 0;
    private float mProcessingTimeAverage_Update = 0f;
    private float mProcessingTimeAverage_Animation = 0f;
    private float mProcessingTimeAverage_LateUpdate = 0f;
    private float mProcessingTimeAverage_Rendering = 0f;
    private float mProcessingTimeAverage_Update_NRKernel = 0f;
    private float mProcessingTimeAverage_LateUpdate_NRKernel = 0f;
    private float mProcessingTimeSum_Update = 0f;
    private float mProcessingTimeSum_Animation = 0f;
    private float mProcessingTimeSum_LateUpdate = 0f;
    private float mProcessingTimeSum_Rendering = 0f;
    private float mProcessingTimeSum_Update_NRKernel = 0f;
    private float mProcessingTimeSum_LateUpdate_NRKernel = 0f;
}

 

処理計測結果

Nreal_Editor_Stats

Editor の Stats で上記の Batch数、頂点数 のシーンにて、
Computing Unit実機(Snapdragon 845)での処理計測結果。
上記コードだと、30秒経過時にCPU処理時間がログ出力される。
(ログは Android Studio の Logcat からコピペ。参考:Nrealアプリの開発環境構築

Monoビルド IL2CPPビルド
Update 2.2 ms (NRKernel: 0.6 ms) 1.8 ms (NRKernel: 0.6 ms)
Animation 0.3 ms 0.2 ms
LateUpdate 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms)
Rendering 10.8 ms 11.1 ms
All 13.4 ms (80 %) 13.2 ms(79 %)

ms は ミリ秒。
% は 60fps のときの 16.6ms を基準としたときの割合(100%を超えると処理落ち)

備考1(2022年5月)

  • Computing Unit実機、NRSDK 1.8.0 での NRKernel 処理時間は 0.6ms (60fps換算で 3.6%)
    • 平面検出、Image Tracking、Hand Tracking などは不使用
    • 6DoF移動しても NRKernel 処理時間は変わらなかった
  • スクリプト処理が多くなってくると、もっと IL2CPP 優勢になりそう

備考2(2022年7月)

Android実機(OnePlus 8)(Snapdragon 845)、NRSDK 1.8.0 での計測結果。

Stats_App

Monoビルド IL2CPPビルド(ARM64) IL2CPPビルド(ARMv7)
Update 1.9 ms (NRKernel: 0.4 ms) 1.4 ms (NRKernel: 0.6 ms) 1.6 ms (NRKernel: 0.4 ms)
Animation 0.2 ms 0.2 ms 0.2 ms
LateUpdate 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms)
Rendering 10.4 ms 12.5 ms 11.8 ms
All 12.5 ms (75 %) 14.2 ms(85 %) 13.5 ms (81%)

Computing Unit と同様に、OnePlus 8 でも IL2CPP のほうが処理負荷が高いという結果になってしまった。

IL2CPP だと Rendering時間が伸びるのは謎。(他スレッドの影響?)

備考3(2022年8月)

Android実機(OnePlus 8)(Snapdragon 845)、NRSDK 1.9.3 での計測結果。

Stats_20220810

Mono Mono_Dev IL2CPP(ARM64) IL2CPP(ARMv7)
Update 2.1 ms (NRKernel: 0.4 ms) 2.7 ms (NRKernel: 0.5 ms) 1.6 ms (NRKernel: 0.6 ms) 1.8 ms (NRKernel: 0.4 ms)
Animation 0.2 ms 0.2 ms 0.2 ms 0.2 ms
LateUpdate 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms) 0.0 ms (NRKernel: 0.0 ms)
Rendering 11.3 ms 10.7 ms 11.6 ms 11.4 ms
All 13.6 ms (82 %) 13.6 ms (82 %) 13.3 ms(80 %) 13.4 ms (81%)

Mono_Dev は、Monoビルドかつ Development Build オン のこと。

今回は、IL2CPP のほうが若干ではあるが処理負荷が低いという結果で、想定通り。

IL2CPP だと Rendering時間が伸びていたのも解消されていた。

-ブログ

© 2022 墾田ええねん! Powered by AFFINGER5