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 にて自分で実装していく部分のこと

方法

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

コード

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;
}

処理計測結果

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

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 での計測結果。

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

IL2CPP だと Rendering時間が伸びるのは謎。（他スレッドの影響？）

備考3（2022年8月）

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

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

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

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