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

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

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も増えます。 個人的には、このログの件がなくても避けたい思いです。

終わりがないサービス開発を支える理想の分析基盤とは?クラシコムxカヤック合同勉強会11月号

毎度お世話になっております、カヤックの谷脇です。

10月にクラシコムさんと合同勉強会を行った様子を以前紹介させていただきましたが、今月も合同の「Hygge」を開催しました。

前回は、クラシコムさんのオフィスで開催させていただきましたが、今回は鎌倉のカヤックのオフィスにクラシコムの皆さんをお招きして行いました。

f:id:mackee_w:20191108162402j:plain

鎌倉での開催ということもあり、前回とは違った多種多様なカヤックのメンバーが参加しての発表となりました。また、クラシコムの皆さんからも「北欧、暮らしの道具店」のサービス運営に関する悩みや解決への道筋について、とても興味深い発表がありました。

というわけで今回もHyggeの様子を紹介していきます。

「データ分析基盤について」

カヤックの池田から、データ分析基盤をなぜつくるのか、どうやってつくるのか、どのように活用するかについての発表です。

アプリケーションサーバ上に存在するアクセスログをその場でコマンドで集計するだけでもデータ分析基盤であるといえます。しかし、良いデータ分析基盤であるとは言えないとのこと。

良いデータ分析基盤とは、必要なときにビジネスの判断材料が取り出せる基盤のことであるそうです。

f:id:mackee_w:20191111171114p:plain

また、データ分析基盤の例としてカヤックの事例の紹介がありました。fluentdを経由して、Amazon Redshiftに溜め込み、Re:dashからデータを抜き出して加工し、ビジュアライズする例も見せてくれました。

「終わりのない物語」

クラシコムの遠藤さんによる、サービス運営の指標を決めるときの悩みについての発表です。

f:id:mackee_w:20191105192540j:plain

遠藤さんが例としてあげた、他社で経験された時のサービスのユーザーゴールでは、ユーザーゴールの設定とはサービス利用者が「できない」を「できる」にすることを言っていたそうです。

しかし、クラシコムさんのビジョン「フィットする暮らし、つくろう」は、明示的なゴールがなく他のサービスのようなユーザーゴールをうまく設定できない悩みがありました。

そこで、運営する「北欧、暮らしの道具店」を、そこにいるだけで心地が良い場所と定義して、ユーザーにとってまちの公園と同じようなものであるかもしれないとすると、ユーザーに良い体験を提供できるかもしれないという話をされていました。

発表直後の質問コーナーで、直前にデータ分析基盤について話した池田から、NPS(ネット・プロモーター・スコア)を計測する際の提案も出て盛り上がりました。

「Twitter自動返信アプリを作った話」

カヤックのクライアントワーク事業部の姫野から、[Twitter DM Cを制作したときの苦労についての話がありました。

現在のTwitter APIをふまえて、Twitter上でのキャンペーンを行うための仕組みの説明があったあとに、Twitter APIを使うための申請の困難さや、インターネットに事例があまりないAPIはドキュメントを精読して自分で解決しなければならないなど、Twitterキャンペーン特有の難しさが語られました。

「正しい『北欧、暮らしの道具店』を正しく作りたい」

クラシコムの村田さんは、「正しいものを正しくつくる」という本を紹介しつつ、「北欧、暮らしの道具店」を正しく作るにはどうすればいいかという発表をされました。

f:id:mackee_w:20191105201938j:plain

今年の2月にクラシコムに入社された村田さんは、入ってすぐに新しいプロジェクトを進めることになったのですが、そのときに「なぜ作るのかわからない」「本当に作れるのかわからない」「MVP(Minimum Viable Product)が作れない」という3つの不確実性に直面したそうです。

そこで、クラシコムの内外の方々の力も借りながら、一つずつ不確実性を潰していって、プロジェクトを進めようとする過程を話されました。

「ゲーム事業部分析基盤のこれまでとこれから」

カヤックの川添は、ソーシャルゲーム事業部で使用している分析基盤・KPI可視化ツールの歴史と今行っているリニューアルについての発表をしました。

2014年のぼくらの甲子園!ポケットがリリースされる直前に作られた分析基盤の歴史を紐解きつつ、昨今のフロントエンドのライブラリの移り変わりの速さにも触れました。

2014年に作ったときにはAngularJSがWebフロントエンドのライブラリとして使われており、そこから4年ほどの間何度も、AngularJSから他のライブラリに移行を試みられたそうです。2017年にはReact、2018年にはVue.jsで書き直そうとされましたが、特にUIフレームワークを使おうとしなかったことから工数がかかりすぎて断念。

しかし2019年はVue.jsとCoreUIを使うことで、順調にリニューアルが進んでいるそうです。勝因としてはアプリケーションに適したUIフレームワークを導入してから、可視化する部分まで、力尽きる前にたどり着けたことだそうです。

まとめ

いかがでしたでしょうか。様々な事業を行っているカヤックからは多種多様な目線の話が飛び出しました。一方で「北欧、暮らしの道具店」という一つのプロダクトを集中して作っているクラシコムさんからは、サービスの本質を洞察するような話がなされて、好対照な会になりました。心地が良い異文化交流イベントにもなったかと思います。来月も、そのまた来月も続けていこうと思います。

f:id:mackee_w:20191105200808j:plain

カヤックでは、ゆるっとふわっとした感じで、心地が良い合同勉強会をやってくれる会社さんをどしどし募集しております。興味がありましたら、私のTwitterアカウントにメンションやDMを飛ばしていただくか、お知り合いのカヤック社員にご連絡ください。