UnityのDebug.Logの負荷とコールスタックの深さ

unity unity-debug

こんにちは。技術部平山です。

Debug.Logにかかる時間が コールスタックの深さに影響される、というお話で、結論はそれで全てです。

深い所でDebug.Logすると重くなります。

大した話ではないので、ヒマでない方は読む必要はありません。

何この重さ?尋常じゃないよ?

先日負荷が重い状況があって調べていたところ、 重いのはDebug.Logだ、ということがわかりました。

「そんなの重いに決まってるじゃないか」

誰だってそう思うと思うのですが、その負荷が尋常でなく、プロファイラで見ると 5ms以上、GCAllocのサイズは100KBに近い状況でした。 エディタでその時間かかっているとなると、スマホ実機では20msくらい行くこともあるはずです。

「こんなに重かったっけ?」と思って見てみたところ、そのプログラムにはある特徴があったのです。

「コールスタックが深い」。

deepProfilingで見てみると、40段くらいはあります。 関数から関数を呼んで、その関数が別の関数を呼んで、ということが40回重なった状態で Debug.Logを呼んでいるということです。 Profilingで見てみると、StackTraceUtility.ExtractStackTrace()という関数が結構な時間食っていまして、 「ログに出てるコールスタックの文字列を作る所が重いのでは?」という推測に至ります。

あとは実験です。本当か確かめてみました。

実験

public class Main : MonoBehaviour
{
    int callDepth;
    TimeSpan time;
    int count;

    void OnGUI()
    {
        var us = (double)time.Ticks / (double)(TimeSpan.TicksPerMillisecond * count);
        GUI.Label(new Rect(0f, 0f, 400f, 50f), us.ToString("F3"));
        var newCallDepth = (int)GUI.HorizontalSlider(new Rect(0f, 50f, 400f, 50f), (float)callDepth, 0, 100);
        if (newCallDepth != callDepth)
        {
            callDepth = newCallDepth;
            count = 0;
            time = TimeSpan.FromTicks(0);
        }
    }

    private void Update()
    {
        var t0 = DateTime.Now;
        LogAtDepth(callDepth, 0);
        var t1 = DateTime.Now;
        time += (t1 - t0);
        count++;
    }

    void LogAtDepth(int targetDepth, int currentDepth)
    {
        if (currentDepth >= targetDepth)
        {
            Debug.Log("Log() called " + targetDepth);
        }
        else
        {
            LogAtDepth(targetDepth, currentDepth + 1);
        }
    }
}

テキトーに再帰関数を作り、指定した深さでDebug.Log()します。 深さはスライダーで設定できるようにし、所要時間をミリ秒に直して画面に表示するようにしました。

さて結果です。

f:id:hirasho0:20191115150921p:plain f:id:hirasho0:20191115150924p:plain

上が深さ0、下が深さ100です。GCAllocのサイズと処理時間が見事に増えていますね。

「ビルドしないでProfilingするとか素人だ」とお叱りを受けても嫌なのですが、 今回はビルドでは測っていません。 実はやってみたのですが、IL2CPPでビルドすると上の再帰関数が 再帰でない形に最適化されてしまうので、コールスタックが浅くなってしまうのです。 末尾再帰 の最適化ですね。実際のコードでは大抵そこの最適化はできませんので、 おそらくIL2CPPのビルドであっても同じ状況になるのではないか、と思います。

...で?

「デバグ機能が重いのは当たり前で問題ではない」という考えの方は結構いらっしゃると思います。 製品に入らないものが重いことに何の問題があるのか?というのは自然な考えです。

ですが、デバグビルドとリリースビルドの速度差が小さいことは、諸々利益をもたらします。 より強力なデバグ機能を有効にしたままで、フレームレートを損わずにテストプレイができるからです。

あまりにデバグビルドの性能が悪いと、誰もデバグビルドで遊ばなくなり、 本来なら発見されているはずのバグが製品に残ってしまう、ということだってありえます。

「デバグビルドはどれくらい速いのが良いか?」という程度の話になると結論は様々でしょうが、 速いに越したことはない、ということは言えるでしょう。 であれば、「不必要にデバグビルドが遅くなるような実装は避けたい」とも言えるかと思います。

ではどうするか?

まず「そのログは意味のあるログか?」というのが一つですね。 意味がないログが出ていれば無駄に重くなるだけです。

次に、今回の結果を受けて対策するならば、 「そのログはコールスタックが必要か?」ということを考えるのが良いのでしょう。

  • コールスタックを見ない軽量なログ関数を別途用意してファイルに吐く
  • PlayerSettingsで設定を変えてコールスタックを吐かなくする、

といった選択肢があります。後者ですが、 PlayerSettingsのotherの下にLoggingという項目があり、

f:id:hirasho0:20191115150916p:plain

こんな感じのチェックボックスが並んでいるのですが、例えば 「LogだけはNone」とすれば、Debug.Logではコールスタックが出なくなります。 ScriptとかFullとかの意味については公式マニュアル をご覧ください。

そして最後に、「なんでそんなにコールスタック深いの?」ということです。 今回の場合、StartCoroutineが入れ子になっていたのが一番効いていました。

void A(){ StartCoroutine(CoA()); }
IEnumerator CoA(){ ... }

みたいなのを想像してください。ある非同期処理CoAをしたいと思った時に、 結果を待つ必要がなければ、StartCoroutineにブン投げて終わりにしたいですよね。 もしそれが頻繁にあれば、いちいちStartCoroutineを書くのは面倒なので、 上のA()みたいな関数を用意して、楽に開始できるようにするでしょう。

問題は、こういう関数が複数ある時です。

void A(){ StartCoroutine(CoA()); }
IEnumerator CoA(){ ... }

void B(){ StartCoroutine(CoB()); }
IEnumerator CoB()
{
    A();
    ...
}

AとBがあり、両方とも実体は非同期処理であるCoAとCoBであるとします。 ここで、CoBの中でAの処理が必要な場合に、CoA()でなくA()を呼んだ場合が問題になります。 どうもStartCoroutineが入れ子になると、コールスタックが深くなってしまうようなのです。

IEnumerator CoB()
{
    yield return CoA();
    ...
}

と書けばこの問題は起きませんが、先程とは処理の流れが異なります。 先程はCoBの残りの処理とAが並列で動きましたが、 こちらはCoAが終わるまでCoBの残りの処理が走らないからです。 しかし、完了を待ってかまわないのであれば、この書き方の方が無難かと思います。

さて、先日見たコードではStartCoroutineが3重になっていました。 その一番底でDebug.Logを呼んでいたわけです。

終わりに

現実問題、スパッとした解決策はないかと思います。ある程度以上作ってしまった場合はなおさらです。

  • デバグビルドが遅いのはある程度あきらめる。遊ぶのはリリースビルドで
    • 個人的には賛同できない...
  • スパイクして気になる所ではログをあきらめる。
    • バグ検出が弱くなるので避けたい...
  • StartCoroutineが入れ子になっている所で、直しやすい所だけ直す。

といった抜本的ではない対策しか取れない気がします。 ある程度以上開発が進んだ後で「今からDebug.Logはコールスタックが出なくなる」 なんてことをするのはちょっと難しいでしょうし。

平山としては、可能であれば、

  • そもそもスパイクが気になる場所(60fpsで動いてる時とか)ではDebug.Logでなく、コールスタックなしでファイルに吐く軽量ログを使う
    • 「Warningはコールスタック出るけどLogは出ない」とプロジェクト開始時に決められればそれもアリ。
  • StartCoroutineを入れ子にしないように気をつける

をおすすめしたいところです。Debug.Logはその行を実行した直後にログに出るとは限りませんが、 自力なら「その行を超えたら絶対ファイルに書かれている」という実装も可能になり、 デバグ時に便利だったりもします。「ある行まで行けたかどうか」を知りたい時は結構ありますよね。

あとは、StartCoroutineの入れ子ですが、 処理が追いにくくなり、GCAllocも増えます。 個人的には、このログの件がなくても避けたい思いです。