Akatsuki Hackers Lab | 株式会社アカツキ(Akatsuki Inc.)

Akatsuki Hackers Labは株式会社アカツキが運営しています。

UniTaskを使った話

この記事は Akatsuki Advent Calendar 2019 - Adventar 5日目の記事です。

 

はじめに

クライアントエンジニアのkawawa1989です。

現在はUnityを使っての開発を行っています、今回は初めて導入したUniTaskについてご紹介をしたいと思います。

 

UniTaskとは🤔🤔🤔

Cysharpさんが開発された、Unityでメインスレッドを使ってasync/awaitを使えるようにするプラグインです。
ちなみにUniRxは事前に入れる必要があるとか、そういうことはありませんでした。
UniRxなしでも単体で扱うことができます。
tech.cygames.co.jp




今まではIEnumeratorを使って書いていた箇所をasync/awaitで置き換えることができるようになります。

 

やりたいこと🤔

通信などの非同期処理などが多い場合、「通信が成功した(or失敗した)」のコールバック関数だらけになってしまいます。
例えばログインのフローでこんなコードがあったとします。

    // ログインフロー
    // 例えばログインボタンがタップされてログインするとする場合
    void OnLoginButtonClick()
    {
        // 利用規約が読まれていないなら利用規約UIを出したい
        if (!HasReadTermOfUse)
        {
            OpenTermOfUseDialog(onAgreed: OnAgreedEvent);
            return;
        }
        // ログインAPIを叩く
        NetworkManager.Login(onLoginSuccess: OnLoginSuccessEvent);
    }

    // 利用規約が同意された
    void OnAgreedEvent()
    {
        // ログインAPIを叩く
        NetworkManager.Login(onLoginSuccess: OnLoginSuccessEvent);
    }


    // ログイン完了
    void OnLoginSuccessEvent()
    {
        LoadNextScene();
    }

 ぶっちゃけこのレベルなら個人的には許容できるのですが、私が実際に経験したコードだとログイン一つでこれを遥かに超える複雑な作りになっていました。
なのですが、あまり具体的なことは社外秘のためとりあえずこの範囲で...
上記のような処理を、できるなら一つの関数の中で何をやっているのかすべて理解できるようにしたいですね。
 

まず最初に考えたやり方🤔

最初はコルーチンでやってしまおうと思いました。

    IEnumerator LoginFlow()
    {
        if (!HasReadTermOfUse)
        {
            var dialog = OpenTermOfUseDialog();
            // ダイアログを表示している間ずっと待機し続ける
            yield return dialog;

            // 終了したら承認されたかどうかの判定を行う
            // 利用規約に同意してもらえなかったらそこで終了
            if (!dialog.Agreed)
            {
                yield break;
            }
        }

        // ログインAPIを叩く
        var login = NetworkManager.Login();
        yield return login;

        // ログインに成功したのかどうか
        // 失敗したなら終了
        if (!login.Success)
        {
            yield break;
        }

        LoadNextScene();
    }

これで一つの関数内に収めることができます
が、いちいちAsyncOperation的なやつを取らないといけないのが面倒くさいです。
UniRxを使えばFromCoroutineでどうにかなるものの、StartCoroutineを呼び出す元になるスクリプトがないと動かせないのも欠点です。

みたいなことを会社の同僚と話していて「そういう事やりたいならUniTaskってのがあるから、それ使ってみては?」
という案が出ました。

というわけで早速導入してみました。
参考になった記事
UniRx.Async(UniTask)機能紹介 - Qiita

当初、Incremental Compilerなるものが必要で、
しかもそれはPreview版とのことだったので若干UniTaskは避けていたのですが、どうやらそれは昔の話で最近は違うらしいと知りました。

 

Incremental Compilerが不要に!😇

neue cc - UniTask(UniRx.Async)から見るasync/awaitの未来
ということでこれで安心して導入できます!!

    async UniTask LoginFlow()
    {
        // ダイアログを表示して結果が返ってくるまで待機する。
        if (!HasReadTermOfUse)
        {
            var agreed = await OpenTermOfUseDialog();
            if (!agreed)
            {
                return;
            }
        }

        // ログインAPIを叩く
        var success = await NetworkManager.Login();
        // エラーだったら終了
        if (!success)
        {
            return;
        }
        LoadNextScene();
    }

よりスッキリしました!
戻り値をawaitで待機しながら受け取れるのは便利ですね!

とはいえ全部をいきなりUniTaskに置き換えるのは難しくない?

私がUniTaskを導入したのはプロジェクトのかなり終盤でした。
そのため、全てをUniTaskに置き換えることはできないのですが、それでもやりようはあります。
例えばダイアログ関係はこのように書き換えることができます。

    // 元のコード
    public void ShowDialog(string title, string message, Action onClose)
    {
        var prefab = Resources.Load("HogeHogeDialog");
        var dialog = Instantiate(prefab);
        dialog.Initialize(title, message, onClose);
    }

    // これを元に改造
    public UniTask ShowDialogAsync(string title, string message)
    {
        var source = new UniTaskCompletionSource();
        var prefab = Resources.Load("HogeHogeDialog");
        var dialog = Instantiate(prefab);
        dialog.Initialize(title, message, () =>
        {
            source.TrySetResult();
        });
        return source.Task;
    }

UniTaskCompletionSource

UniTaskCompletionSourceというやつで終了時にTrySetResultすれば元の実装をいじくる必要なくUniTaskで待てるように改造できます!
これも最初は自分はまったく知らなかった機能で、知る前までは毎回

        var isDone = false;
        dialog.Initialize(title, message, () =>
        {
            isDone = true;
        });
        await UniTask.WaitUntil(() => isDone);

こんな風に書いてました。

UniTaskの中身を解析してみよう🤔

どう動いているのか非常に気になったので、中身を解析してみました。

PlayerLoopHelper

コルーチンの場合、StartCoroutineを走らせるためのMonoBehaviourがどうしても必要でした。
でしたが、PlayerLoopを上書きできるようになったので、この仕組みで直接UniTaskを走らせる用のUpdate関数を登録しているようでした。
PlayerLoopに関しての参考リンク
tsubakit1.hateblo.jp

PlayerLoopHelper.csの中身

    public static class PlayerLoopHelper
    {
        public static SynchronizationContext UnitySynchronizationContext => unitySynchronizationContetext;
        public static int MainThreadId => mainThreadId;

        static int mainThreadId;
        static SynchronizationContext unitySynchronizationContetext;
        static ContinuationQueue[] yielders;
        static PlayerLoopRunner[] runners;


yieldersrunnersがどうにも気になります。
PlayerLoopHelperのInitというメソッドがRuntimeInitializeOnLoadMethodによって起動時に呼び出されているようです。

        [RuntimeInitializeOnLoadMethod(RuntimeInitializeLoadType.BeforeSceneLoad)]
        static void Init()
        {
            // capture default(unity) sync-context.
            unitySynchronizationContetext = SynchronizationContext.Current;


Initialize内では以下のような感じになっていました。
InsertRunnerでループ処理を追加しています。

        public static void Initialize(ref PlayerLoopSystem playerLoop)
        {
            yielders = new ContinuationQueue[7];
            runners = new PlayerLoopRunner[7];

            var copyList = playerLoop.subSystemList.ToArray();

            copyList[0].subSystemList = InsertRunner(copyList[0], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldInitialization), yielders[0] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerInitialization), runners[0] = new PlayerLoopRunner());
            copyList[1].subSystemList = InsertRunner(copyList[1], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldEarlyUpdate), yielders[1] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerEarlyUpdate), runners[1] = new PlayerLoopRunner());
            copyList[2].subSystemList = InsertRunner(copyList[2], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldFixedUpdate), yielders[2] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerFixedUpdate), runners[2] = new PlayerLoopRunner());
            copyList[3].subSystemList = InsertRunner(copyList[3], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldPreUpdate), yielders[3] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerPreUpdate), runners[3] = new PlayerLoopRunner());
            copyList[4].subSystemList = InsertRunner(copyList[4], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldUpdate), yielders[4] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerUpdate), runners[4] = new PlayerLoopRunner());
            copyList[5].subSystemList = InsertRunner(copyList[5], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldPreLateUpdate), yielders[5] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerPreLateUpdate), runners[5] = new PlayerLoopRunner());
            copyList[6].subSystemList = InsertRunner(copyList[6], typeof(UniTaskLoopRunners.UniTaskLoopRunnerYieldPostLateUpdate), yielders[6] = new ContinuationQueue(), typeof(UniTaskLoopRunners.UniTaskLoopRunnerPostLateUpdate), runners[6] = new PlayerLoopRunner());

 
InsertRunnerの中身を見たところ、yieldLoopというのとrunnerLoopというループがあるのですが、
これをUnityの各PlayerLoopに2つずつ挿入しています。
 
f:id:kawawa1989:20191205112536j:plain


このループの中で実際にやっている処理はContinuationQueuePlayerLoopRunnerというやつをそれぞれ走らせています。
yieldLoop内でContinuationQueueのRunを走らせて
runnerLoop内でPlayerLoopRunnerのRunを走らせています。
では次にContinuationQueuePlayerLoopRunnerを見てみます。

ContinuationQueue

内部的にはactionListというActionの配列を管理しているようです。
そしてこれをRun実行時に呼び出している。
Enqueueというメソッドが用意されていて、これを呼び出すことでActionが登録できそうです。
ではこのEnqueueはどこから呼び出されているのだろう?

と思って追ってみたら、PlayerLoopHelperで管理しているようでした。
イメージとしては以下の図のような感じでしょうか。

f:id:kawawa1989:20191205113005j:plain
では、次にこのAddActionとAddContinautionがどこから呼び出されているか調べてみます。

f:id:kawawa1989:20191205114020p:plain
ReusablePromise.csが気になるので見てみます。
PlayerLoopReusablePromiseBaseというクラスのIsCompletedというメソッドで呼び出されていました。

PlayerLoopReusablePromiseBase

        public override bool IsCompleted
        {
            get
            {
                if (Status == AwaiterStatus.Canceled || Status == AwaiterStatus.Faulted) return true;

                if (!isRunning)
                {
                    isRunning = true;
                    ResetStatus(false);
                    OnRunningStart();
#if UNITY_EDITOR
                    TaskTracker.TrackActiveTask(this, capturedStackTraceForDebugging);
#endif
                    PlayerLoopHelper.AddAction(timing, this);
                }
                return false;
            }
        }


PlayerLoopReusablePromiseBaseの実装を見ればわかりますが、IPlayerLoopというやつを実装していました。

    public abstract class PlayerLoopReusablePromiseBase : ReusablePromise, IPlayerLoopItem
    {

これはMoveNextというメソッドを提供するインターフェースのようで、
MoveNextメソッドはPlayerLoopReusablePromiseBaseを継承した先で実装されていました。
WaitUntilPromise
WaitWhilePromise
YieldPromise

PlayerLoopRunnerは基本的にこのIPlayerLoopItemを配列で管理して、毎ループ時に各IPlayerLoopItemのMoveNextを呼び出しているようです。
次はUniTaskを見ます。
AddActionメソッドにログを仕込んでみました。
で、下記のようなサンプルコードを書いてみました。とりあえず3秒間待つタスクです。

    bool isDone = false;
    private void Awake()
    {
        Run().Forget();
        StartCoroutine(WaitCoroutine());
    }

    private IEnumerator WaitCoroutine()
    {
        yield return new WaitForSeconds(3.0f);
        isDone = true;
    }

    private async UniTask Run()
    {
        Debug.Log("Run Start!!");
        await UniTask.WaitUntil(() => isDone);
        Debug.Log("Run End!!");
    }

f:id:kawawa1989:20191205115942p:plain
呼ばれています!
呼び出し先を見てみると、PlayerLoopReusablePromiseBaseIsCompletedというプロパティで呼び出されているのがわかります。
PlayerLoopReusablePromiseBaseIsCompletedを呼び出しているのはUniTaskIsCompletedプロパティのようです。

UniTask

IsCompleted

UniTask.IsCompleted

        [DebuggerHidden]
        public bool IsCompleted
        {
            get
            {
                return awaiter == null ? true : awaiter.IsCompleted;
            }
        }

UniTaskawaiterというフィールドを持っていることがわかります。
このawaiterにPlayerLoopReusablePromiseBaseのインスタンスを設定しているということになります
そして、これを呼び出しているのはAwaiterというやつのようですAwaiterはUniTask内に定義されています。
Awaiter

Awaiter
        public struct Awaiter : IAwaiter
        {
            readonly UniTask task;
            [DebuggerHidden]
            public Awaiter(UniTask task)
            {
                this.task = task;
            }

こいつの中にUniTaskが内包されているようです。
で、実際はAwaiterのIsCompletedからUniTaskのプロパティにアクセスしているようです。

IAwaiter

IAwaiterの定義自体はこんな感じです。

    public interface IAwaiter : ICriticalNotifyCompletion
    {
        AwaiterStatus Status { get; }
        bool IsCompleted { get; }
        void GetResult();
    }
ICriticalNotifyCompletion

ICriticalNotifyCompletionはちょっとよくわからないので調べます。
どうもTaskでも使用されているインターフェースのようです。

.NET Framework標準で提供されているTaskAwaiter/TaskAwaiter型はINotifyCompletionインターフェースを継承するICriticalNotifyCompletionインターフェースを実装しています。

参考記事
このIsCompletedはどこで呼ばれているのか?
IsCompleted内部にログを仕込んでみます。
f:id:kawawa1989:20191205121706p:plain

どうやらAsyncUniTaskMethodBuilderとかいうやつが居るようで、そいつが呼び出しているようです。
では今度はこいつのStartメソッドに同じようなログを仕込んでみましょう。
f:id:kawawa1989:20191205121755p:plain

これ以上先はもう何もありません。
このAsyncUniTaskMethodBuilderが何者なのか?といろいろ調べていたら、これはどうもコンパイラ側が使用するクラスのようです
www.atmarkit.co.jp

IAsyncStateMachineというやつが何か関連がありそうです。
コイツについて調べてみましょう。
docs.microsoft.com

非同期メソッドに生成されるステート マシンを表します。 この型はコンパイラでのみ使用されます。

他にもこのような記事がありました。
blog.xin9le.net

・async/awaitは何かの糖衣構文で、実際はコンパイラがもっと複雑な形に変換している
・exeやdllには変換後の形で格納されている

とのことなので、試しにILSpyで中身を開いてみます。

    .method /* 06000006 */ private hidebysig 
        instance valuetype [UniRx.Async]UniRx.Async.UniTask Run () cil managed 
    {
        .custom instance void [mscorlib]System.Runtime.CompilerServices.AsyncStateMachineAttribute::.ctor(class [mscorlib]System.Type) = (
            01 00 12 54 65 73 74 43 6f 64 65 2b 3c 52 75 6e
            3e 64 5f 5f 36 00 00
        )
        .custom instance void [mscorlib]System.Diagnostics.DebuggerStepThroughAttribute::.ctor() = (
            01 00 00 00
        )
        // Method begins at RVA 0x2080
        // Code size 59 (0x3b)
        .maxstack 2
        .locals /* 11000001 */ init (
            [0] class TestCode/'<Run>d__6',
            [1] valuetype [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder
        )

        IL_0000: newobj instance void TestCode/'<Run>d__6'::.ctor() /* 06000012 */
        IL_0005: stloc.0
        IL_0006: ldloc.0
        IL_0007: ldarg.0
        IL_0008: stfld class TestCode TestCode/'<Run>d__6'::'<>4__this' /* 04000008 */
        IL_000d: ldloc.0
        IL_000e: call valuetype [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder::Create() /* 0A000012 */
        IL_0013: stfld valuetype [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder TestCode/'<Run>d__6'::'<>t__builder' /* 04000007 */
        IL_0018: ldloc.0
        IL_0019: ldc.i4.m1
        IL_001a: stfld int32 TestCode/'<Run>d__6'::'<>1__state' /* 04000006 */
        IL_001f: ldloc.0
        IL_0020: ldfld valuetype [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder TestCode/'<Run>d__6'::'<>t__builder' /* 04000007 */
        IL_0025: stloc.1
        IL_0026: ldloca.s 1
        IL_0028: ldloca.s 0
        IL_002a: call instance void [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder::Start<class TestCode/'<Run>d__6'>(!!0&) /* 2B000001 */
        IL_002f: ldloc.0
        IL_0030: ldflda valuetype [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder TestCode/'<Run>d__6'::'<>t__builder' /* 04000007 */
        IL_0035: call instance valuetype [UniRx.Async]UniRx.Async.UniTask [UniRx.Async]UniRx.Async.CompilerServices.AsyncUniTaskMethodBuilder::get_Task() /* 0A000014 */
        IL_003a: ret
    } // end of method TestCode::Run

AsyncUniTaskMethodBuilder::Create()とかAsyncUniTaskMethodBuilder::Start()とか呼ばれてます!
ILコードがよくわかりませんが、callとか呼ばれてますね。
(この辺もそのうち勉強してみたい)

[参考リンク]
www5b.biglobe.ne.jp

次に気になったこと

どうやってAsyncUniTaskMethodBuilderを呼び出している?🤔

これがちょっと謎でしたが、UniTask.csの定義をよく見るとAsyncMethodBuilderというやつがあります!

    [AsyncMethodBuilder(typeof(AsyncUniTaskMethodBuilder))] // ←これ!!!!
    public partial struct UniTask : IEquatable<UniTask>

AsyncMethodBuilderに関して参考リンク
qiita.com

つまりawaitが呼ばれたとき、その戻り値の型に対応されたAsyncMethodBuilderが呼び出される
ということでしょうか?
ここ、調べてもあまり出てこないのでちょっとわからない。
おそらくこんな感じ

f:id:kawawa1989:20191205122359j:plain
試しに
UnsafeOnCompleted(Action act)
で受け取るデリゲートを最後に呼び出さないようにしてみたら
永遠にawaitから戻ってこれない状態になったので、おそらくこれは処理が終了したあとに呼び出さないといけないやつ。
GetAwaiterが何者なのか気になったけど、これは戻り値の型が独自定義型であろうとなんだろうと関係なく呼ばれるように見えます。
docs.microsoft.com
ちなみにGetAwaiterをコメントアウトするとawaitする箇所全てでコンパイルエラーになって死にます。

要約

全体のライフサイクルはこんな感じ?だと思われる🤔
f:id:kawawa1989:20191205122539j:plain


オレオレTaskを作ってみよう!

試しに自分でawaitできるタスクを作ってみます。
UniTaskはstructで定義されていましたが、structだとデフォルトコンストラクタが定義できないので今回はclassで定義しています。

using System.Runtime.CompilerServices;
using System;

namespace Bz.Brotherhood
{
    [AsyncMethodBuilder(typeof(BzTaskBuilder))]
    public class BzTask
    {
        IAwaiter awaiter;

        public BzTask()
        {
            UnityEngine.Debug.Log($"BzTask.Constructor");
        }

        public BzTask(IAwaiter awaiter)
        {
            this.awaiter = awaiter;
        }

        public IAwaiter GetAwaiter()
        {
            UnityEngine.Debug.Log($"BzTask.GetAwaiter");
            return new Awaiter(awaiter);
        }

        private struct Awaiter : IAwaiter
        {
            IAwaiter awaiter;
            public Awaiter(IAwaiter awaiter)
            {
                this.awaiter = awaiter;
            }

            public bool IsCompleted
            {
                get
                {
                    var isCompleted = true;
                    if (awaiter != null)
                    {
                        isCompleted = awaiter.IsCompleted;
                    }
                    UnityEngine.Debug.Log($"Awaiter.IsCompleted :{isCompleted}");
                    return isCompleted;
                }
            }

            public void OnCompleted(Action moveNext)
            {
                UnityEngine.Debug.Log("Awaiter OnCompleted");
                awaiter?.OnCompleted(moveNext);
            }

            public void UnsafeOnCompleted(Action moveNext)
            {
                UnityEngine.Debug.Log("Awaiter UnsafeOnCompleted");
                awaiter?.UnsafeOnCompleted(moveNext);
            }

            public void GetResult()
            {
                UnityEngine.Debug.Log("Awaiter GetResult");
                awaiter?.GetResult();
            }
        }
    }

AsyncMethodBuilderAttributeは存在しない?

コードを書いてみたのですがエラーが出ます。
f:id:kawawa1989:20191205122824p:plain
UniTaskはAsyncMethodBuilderAttributeを定義しているようでした。
blog.meilcli.net

また、現時点でほとんどのプラットフォームではAsyncMethodBuilderAttribute属性も自分で定義する必要があります。

理由はよくわからないのですが、とにかくこっちで定義しないと駄目らしい。
以下のようなオレオレタスクビルダーを作ってみました(といってもほぼUniTaskBuilderのコピペ)

namespace Bz.Brotherhood
{
    public struct BzTaskBuilder
    {
        IAwaiter awaiter;

        // 1. Static Create method.
        public static BzTaskBuilder Create()
        {
            UnityEngine.Debug.Log("BzTaskBuilder.Create");
            var builder = new BzTaskBuilder();
            return builder;
        }

        // 2. TaskLike Task property.
        public BzTask Task
        {
            get
            {
                UnityEngine.Debug.Log("BzTaskBuilder.Task");
                return new BzTask(awaiter);
            }
        }

        // 3. SetException
        public void SetException(Exception exception)
        {
            UnityEngine.Debug.Log("BzTaskBuilder.SetException");
        }

        // 4. SetResult
        public void SetResult()
        {
            UnityEngine.Debug.Log("BzTaskBuilder.SetResult");
        }

        // 5. AwaitOnCompleted
        public void AwaitOnCompleted<TAwaiter, TStateMachine>(ref TAwaiter awaiter, ref TStateMachine stateMachine)
            where TAwaiter : INotifyCompletion
            where TStateMachine : IAsyncStateMachine
        {
            UnityEngine.Debug.Log("BzTaskBuilder.AwaitOnCompleted");
            this.awaiter = awaiter as IAwaiter;
            this.awaiter.OnCompleted(stateMachine.MoveNext);
        }

        // 6. AwaitUnsafeOnCompleted
        [SecuritySafeCritical]
        public void AwaitUnsafeOnCompleted<TAwaiter, TStateMachine>(ref TAwaiter awaiter, ref TStateMachine stateMachine)
            where TAwaiter : ICriticalNotifyCompletion
            where TStateMachine : IAsyncStateMachine
        {
            UnityEngine.Debug.Log("BzTaskBuilder.AwaitUnsafeOnCompleted");
            this.awaiter = awaiter as IAwaiter;
            this.awaiter.UnsafeOnCompleted(stateMachine.MoveNext);
        }

        // 7. Start
        public void Start<TStateMachine>(ref TStateMachine stateMachine)
            where TStateMachine : IAsyncStateMachine
        {
            UnityEngine.Debug.Log("BzTaskBuilder.Start");
            stateMachine.MoveNext();
        }

        // 8. SetStateMachine
        public void SetStateMachine(IAsyncStateMachine stateMachine)
        {
            UnityEngine.Debug.Log("BzTaskBuilder.SetStateMachine");
        }
    }
}


そして最後にこんなテストコードを試しに作ってみます。

    void Start()
    {
        Debug.Log("Start");
        TestTask();
    }

    async BzTask HelloWorldTask()
    {
        Debug.Log("Hello World!!");
    }

    async BzTask TestTask()
    {
        Debug.Log("TestTask Start");
        await HelloWorldTask();
        Debug.Log("TestTask End");
    }

これでも一応エラーになりません(まったく待機とかしないけど)
そして実行してみます。
f:id:kawawa1989:20191205123138p:plain

動いた!
現在のままだとawaitとか言っておきながら全く待機していないので今度は例えば60フレーム後に処理が進行するようにしてみたいです。
このBzTaskのIAwaiterに何か実装を渡せばその実装に合わせて動くようになっています。
IAwaiterの中身はUniTaskのものとほぼ同じです。

    public interface IAwaiter : ICriticalNotifyCompletion
    {
        // BzTask.Awaiter内部で呼び出される。
        bool IsCompleted { get; }
        void GetResult();
    }


そしてこのIAwaiterを実装した60フレーム待機するクラスを作ってみます。

    private interface IOnUpdate
    {
        bool OnUpdate();
    }

    private class FrameAwater : IAwaiter, IOnUpdate
    {
        int frame = 0;
        int waitFrameCount = 0;
        Action moveNext = null;

        public FrameAwater(int waitFrameCount)
        {
            this.waitFrameCount = waitFrameCount;
        }

        public bool OnUpdate()
        {
            Debug.Log($"OnUpdate[frame:{frame}, waitFrameCount:{waitFrameCount}]");
            if (frame == waitFrameCount)
            {
                moveNext();
                return false;
            }
            frame += 1;
            return true;
        }

        // BzTask.Awaiter内部で呼び出される。
        public bool IsCompleted { get { return false; } }
        public void GetResult()
        {
        }

        public void OnCompleted(Action continuation)
        {
            moveNext = continuation;
        }

        public void UnsafeOnCompleted(Action continuation)
        {
            moveNext = continuation;
        }
    }


そしてMonoBehaviour側にIOnUpdateをUpdate時にコールする、みたいなやつを追加します。

    List<IOnUpdate> list = new List<IOnUpdate>();
    List<IOnUpdate> removeList = new List<IOnUpdate>();
    void Update()
    {
        removeList.Clear();
        foreach (var update in list)
        {
            if (!update.OnUpdate())
            {
                removeList.Add(update);
            }
        }
        foreach (var item in removeList)
        {
            list.Remove(item);
        }
    }

そして試しに60フレーム待機するように以下のように書き換えてみます。

    void Start()
    {
        Debug.Log("Start");
        TestTask();
    }

    BzTask WaitForFrame(int frame)
    {
        Debug.Log("WaitForFrame");
        var frameAwaiter = new FrameAwater(frame);
        list.Add(frameAwaiter);
        return new BzTask(frameAwaiter);
    }

    async BzTask TestTask()
    {
        Debug.Log("TestTask Start");
        await WaitForFrame(60);
        Debug.Log("TestTask End");
    }

意図した通りに動くのであれば、
60フレーム経過したらUnsafeOnCompleted()で受け取ったデリゲートを実行し、それによってタスクは終了するはずです。

f:id:kawawa1989:20191205123431p:plain
f:id:kawawa1989:20191205123516p:plain
しっかり60フレーム待機してくれています!
長くなりましたがたまにこうやって他の人の作ったプラグインのソースコードを除くのは楽しいですね。


ここまで読んでくださってありがとうございました!

Redash上からBigQueryスクリプトを利用してみた

この記事は Akatsuki Advent Calendar 2019 - Adventar 4日目の記事です。

こんにちは! suwahime です。

昨今どの業界を見渡しても、アクティブユーザー数や入会数といったデータは、当たり前のように日々追っているかと思います。 私の所属するチームでは、主にRedashを用いてKPIを可視化しています。

今日は、先月BigQueryにBetaリリースされたスクリプトとプロージャ機能を使って、RedashのQuery作成を、よりシンプルに、管理しやすい形で書いてみたことをお話しさせていただきます。

RedashはQueryごとに定義が分散してしまいがち

例として、「期間内にサービスを訪れたユーザー」の利用デバイスを調べる、以下のようなQueryをRedashに作成していたとします。

SELECT B.device_name, COUNT(DISTINCT A.user_id) FROM
  (SELECT * FROM dataset.login_user_ids
    WHERE timestamp >= TIMESTAMP("{{start_time}}")
    AND timestamp <= TIMESTAMP("{{end_time}}")
    GROUP BY user_id) AS A
  LEFT JOIN
  (SELECT user_id, device_name FROM dataset.user_devices) AS B
  ON A.user_id = B.user_id
GROUP BY B.device_name

テーブルの内容等は割愛しますが、利用者はstart_timeとend_timeをRedash上のGUIから入力することで、数字が見られるというイメージです。

Redashはこのように愚直なSQLを書いても簡単にグラフ化までできる魔法のようなツールなのですが、いかんせん簡単すぎて、考えなしに様々なQueryを作成してしまい、後々の定義変更が大変だったりすることがあります。

たとえば、以下のような要求がきた場合はどうなるでしょうか。

  • 期間ごとの不正なユーザーIDを検知することができたので、その一覧をKPIから削減したい。
  • ログインしたユーザーではなく、サービスをプレイしたユーザーから取るように変えてほしい。

中間テーブルを作成するなど、やり方はいろいろあると思いますが、ここではまた愚直に以下のように修正してみます。

SELECT B.device_name, COUNT(DISTINCT A.user_id) FROM
(SELECT * FROM dataset.play_user_ids -- 参照するテーブルを置き換え
  WHERE timestamp >= TIMESTAMP("{{start_time}}")
  AND timestamp <= TIMESTAMP("{{end_time}}")
  AND user_id NOT IN -- 不正ユーザーIDを弾く
  (SELECT user_id FROM dataset.wrong_user_ids
    WHERE timestamp >= TIMESTAMP("{{start_time}}")
    AND timestamp <= TIMESTAMP("{{end_time}}"))
  GROUP BY user_id) AS A
LEFT JOIN
(SELECT user_id, device_name FROM dataset.user_devices) AS B
ON A.user_id = B.user_id
GROUP BY B.device_name

Redashの埋め込み記法である {{}} が増えて少々見づらくなりましたが、なんとか簡単にできました。Redashはこのフットワークの軽さが良いですね。

では、更に次のような要求が来た場合はどうでしょう?

  • 「期間内にサービスを訪れたユーザー」を元に調査している他の全てのQueryについても、同様に置き換えて欲しい。

…これは少々困りました。Query数が少ないプロジェクトなどは、そんなにコストがかからず置き換え可能なのかもしれません。しかし、誰でも好き勝手にQuery作成が可能なプロジェクトにおいては、どこでこの指標を利用しているのか、検索して見ていくしかありません。

もし「期間内にサービスを訪れたユーザー」の定義が一元管理できていたら、こんな手間は無くなると思いませんか?

RedashとBigQueryスクリプトを組み合わせて使ってみる

ではここで、BigQueryスクリプトを使った解決策を試してみましょう。

まずは「期間内にサービスを訪れたユーザー」をaccess_user_idsというTEMP TABLEに吐き出すプロシージャを、以下のスクリプトをBigQuery上で実行することで登録してみます。

CREATE PROCEDURE dataset.create_access_user_ids (start_date TIMESTAMP, end_date TIMESTAMP)
BEGIN
  CREATE TEMP TABLE access_user_ids AS
  SELECT * FROM dataset.play_user_ids
    WHERE timestamp >= start_date
    AND timestamp <= end_date
    AND user_id NOT IN
    (SELECT user_id FROM dataset.wrong_user_ids
      WHERE timestamp >= start_date
      AND timestamp <= end_date)
    GROUP BY user_id;
END;

これをCALL関数で呼び出すことで、RedashのQueryは以下のように書けるようになります。

CALL dataset.create_access_user_ids(TIMESTAMP("{{start_time}}"), TIMESTAMP("{{end_time}}"));

SELECT B.device_name, COUNT(DISTINCT access_user_ids.user_id) FROM
access_user_ids
LEFT JOIN
(SELECT user_id, device_name FROM dataset.user_devices) AS B
ON access_user_ids.user_id = B.user_id
GROUP BY B.device_name;

見た目がだいぶスッキリしましたね。しかも、今後定義変更があった場合にはプロシージャ側を編集するだけで、access_user_idsを使っているすべてのQueryが同じ指標に置き換わります。

注意すべきは、1クエリではなくスクリプトになるため、区切り文字「;」が必要になることと、プロシージャ内で作られるTEMP TABLEの名前がRedashからだと隠蔽されてしまうため、命名規則などで対応する必要があることです。

RedashからBigQueryスクリプトを使うことのメリット、デメリット 

プロシージャを利用することの最大のメリットは、RedashのQueryごとに指標がバラけることなく一元管理することができることです。他にも、BigQueryからRedashにSQLをコピペしてから、時間範囲の部分だけを {{start_time}} と {{end_date}} で置き換えて…なんていう手間を省くこともできます。最終的にはプロシージャや中間テーブルだけでクエリを作成して、RedashからはCALLするだけという運用にすれば、ダッシュボードツールに縛られることのない未来もありそうです。

デメリットは、BigQueryスクリプト内で書かれたSQLに関して、処理される推定バイト数が実行前にわからないことです。想定外に検索費用がかかってしまうこともあるかもしれません。これに関しては、たとえば先にdry runを実行して処理する推定バイト数を算出し、一定以上の費用がかかりそうなら実行しない、ということができるようになればありがたいですね。(現時点では、コンソール上からdry runをすることはできないようです。)

BigQueryスクリプトで可能になることはまだまだありそうなので、今後も追ってみたいと思います。

参考

cloud.google.com

cloud.google.com

cloud.google.com

RailsでTZ環境変数を設定するハックを不要にした話

TL;DR

環境変数を設定するだけでRuby on Railsサーバが10%高速化する(かもしれない)話』  でRailsを高速化させる素晴らしいハックが紹介されましたが。いまや有効なハックではなくなりました。

 

TZハックさん、ながい間(2日間)おつかれさまでした。

 

はじめに

 アカツキさまで技術顧問をさせていただいている小崎です。

 

このエントリは『環境変数を設定するだけでRuby on Railsサーバが10%高速化する(かもしれない)話』をRubyコミッタが読んだらこうなったというアンサーソングになっています。合わせてお読みください

 

TZ環境変数でTime.newが10倍近く速くなるのは素晴らしい発見ですが、コミッタとしてはTZなしでも速くなって欲しいなと思いました。だってめんどうだし。

 

現状分析

まず問題のテストプログラムを軽く分析してみましょう

 

% strace -c ruby ../t.rb
% time  seconds     usecs/call  calls     errors    syscall
------ ----------- ----------- --------- --------- ----------------
99.86     4.248080          11    400076         1 stat
0.03      0.001304           3       458       319 openat
0.02      0.000786           2       362         7 lstat
0.02      0.000682           4       184           read
0.01      0.000407           3       141           close
0.01      0.000390          11        34           mmap
...

Time.new 10万回に対し、statが40万回、つまりTime.new1回あたり4回のstatが呼ばれていることが分かります。

 ltraceでも確認してみます

% ltrace -c ./miniruby ../t.rb 
% time   seconds    usecs/call     calls function
------ ----------- ----------- --------- --------------------
 30.97   47.608101         158    300000 tzset
 25.24   38.804739         129    300000 localtime_r
 16.28   25.027547         120    207016 malloc_usable_size
 10.51   16.163021         161    100000 mktime
 8.31    12.781192         123    103912 calloc
 8.26    12.698693         123    103204 strlen
 0.18     0.282174          77      3645 memcpy
 0.13     0.204240          76      2674 malloc
 0.08     0.129064          80      1601 memcmp
..

 

おや?tzset(), lcoaltime_r() 呼び出しが30万回しか呼ばれておらず数が合いません。

 が、よく訓練された低レイヤー開発者は glibcの__tzfile_read() が呼ばれるのはtzset(3)が呼ばれたときだけだけども、tzset(3)はmktimeが呼ばれたときにも内部的に呼ばれていることを知っています。

つまり、Time.newするたびに、tzsetを3回、mktimeを1回呼んでおり、それがstat 4回につながります。

だいたい計算があってきました。

 

余談

 

tzset()とはTZ環境変数にもとづいてlibcのタイムゾーン初期化する関数ですが、TZ環境変数が未設定の場合は処理系依存です。

glibcの場合は /etc/localtimeのファイルに従いタイムゾーン情報を使って初期化します(まあ妥当ですよね)。ところがお節介なことに、glibcは /etc/localtime があとから変更された場合に備え、tzset()が呼ばれるたびに、 /etc/localtimeをstatして変更がないかチェックし、変更があれば再初期化するという実装になっています。

ほとんど使い道のないお節介のために遅くなっているのですから、余計なことをしてくれたものです。

 

 

localtime_r 問題(すでに解決済みでした)

 

さて、Rubyのtime.c をみると

#define LOCALTIME(tm, result) (tzset(),rb_localtime_r((tm), &(result)))

のような行があり、ようするに localtime_r()を呼ぶときには毎回 tzset()を呼んでいることがわかります。

これはlibcのマニュアルの

https://linuxjm.osdn.jp/html/LDP_man-pages/man3/ctime.3.html

POSIX.1-2004 によると、 localtime() はあたかも tzset(3) が呼ばれたかのように振舞うことが要求されているが、 localtime_r() にはこの要件はない。 移植性が必要なコードでは、 localtime_r() の前に tzset(3) を呼び出しておくべきである。

 

の記述に従っているためです。

・・・・と言いたいところですが、別に毎回呼べとは書いてありませんね。最初に一回だけ呼べばいいのでは?

 

とここまで調べたところで、実はこの問題はRuby 2.6で解決済みであったことに気がつきます。一番悔しいパターンです。元blogにあわせて Ruby 2.5で調査していたための不覚でした。

修正は以下のコミットです。

 

commit 4bc16691279e98ecdb3e19ff23902be671d46307
Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
Date: Wed Jul 18 10:30:41 2018 +0000
reduce tzset

* time.c (rb_localtime_r): call tzset() only after TZ environment
variable is changed.

 

 

ところで、さきほどの localtime_r の man を注意深く読まれた読者は、あれ? localtime_r も tzset()を内部的に呼びだすっぽいこと書いてあるけど?と思うかもしれません。賢いですね。

 

関数 localtime() は、カレンダー時刻 timep を ユーザーが指定したタイムゾーンでの時刻要素別の表現へ変換する。 この関数は tzset(3) を呼び出したかのように振舞い、 大域変数 tzname に現在のタイムゾーンの情報を設定する。 また、timezone に協定世界時 (UTC) とローカル標準時との 時差の秒数を設定し、 一年の一部で夏時間が適用される場合は daylight に 0 が設定される。 返り値は静的に確保された構造体を指しており、この後で 日付や時刻に関する関数のいずれかが呼び出されると 上書きされる可能性がある。 localtime_r() も同様だが、 データはユーザーが用意した構造体に格納される。 この関数は tzname, timezone, and daylight を設定する必要はない。

 

実は glibc は localtime() は毎回 tzset() を呼び出すが、localtime_r() は最初の1回だけtzset() を呼び出すという最適化をしています。

 

具体的には glibcのソースコード中の time/tzset.c の以下のあたりで切り分けています。

tzset_internal()の引数が0になると最初の一回のみ初期化という意味、tp == &_tmbuf はlocaltime()のとき1、 use_localtime はlocaltime(),localtime_r()どちらでも1です(gmtimeなどのときに0になります)

 

/* Return the `struct tm' representation of TIMER in the local timezone.                                                                                  
   Use local time if USE_LOCALTIME is nonzero, UTC otherwise.  */
struct tm *
__tz_convert (__time64_t timer, int use_localtime, struct tm *tp)
{
  long int leap_correction;
  int leap_extra_secs;

  __libc_lock_lock (tzset_lock);

  /* Update internal database according to current TZ setting.                                                                                            
     POSIX.1 8.3.7.2 says that localtime_r is not required to set tzname.                                                                                 
     This is a good idea since this allows at least a bit more parallelism.  */
  tzset_internal (tp == &_tmbuf && use_localtime);

 

コメントに理由が書いてありますね。つまり、tzset() で毎回 /etc/localtimeをstatするのはタイムゾーン処理のためで、localtime_r()はタイムゾーンまわりの処理が不要だから、ということのようです。

 

 mktime問題

残った mktime 問題ですが、grepすると呼び出し箇所は簡単に見つかります。 

 

time.c 

static const char *
find_time_t(struct tm *tptr, int utc_p, time_t *tp)
{
(snip)

#if defined(HAVE_MKTIME)
    tm0 = *tptr;
    if (!utc_p && (guess = mktime(&tm0)) != -1) {
        tm = GUESS(&guess);
        if (tm && tmcmp(tptr, tm) == 0) {
            goto found;
        }
    }
#endif

 

これはラッキーです。mktime() があれば使うが、なければないで特に困らないという実装になっています。このような実装になっている理由については 

 

APIデザインケーススタディ ~Rubyの実例から学ぶ。問題に即したデザインと普遍の考え方』 

 

という本に解説があるので興味がある人は一読するといいと思います。このケースに限らずRubyのいろいろなAPIデザインの知見がつまったとてもいい本です。

 

要約すると mktime() があれば使うが、なかったり信用できなかったりした場合は、64bit integerの全空間を二分探索でlocaltime_r() を使って力業で探索するということです。

 

 ふつうに考えれば、前者のほうが明らかに速いのですが、今回我々は、mktimeは毎回tzset() を呼ぶが、localtime_r () は最初の一回のみ tzset() を呼ぶ。そして tzset() はとても遅い、ということを学びました。

つまり、毎回力業探索をしたほうが速いと言うことは十分ありえるとことです。やってみましょう!

 

 結果測定

t = Time.now; 100000.times { Time.new(2019) }; Time.now - t

 

のケースで
Ruby 2.6:                                          0.387sec
Ruby 2.6 + TZ環境変数:                   0.197sec
Ruby 2.7開発ツリー:                        0.162sec
Ruby 2.7開発ツリー+TZ環境変数:   0.165sec

 

と約2倍の高速化を達成し、かつTZ環境変数ありなしで速度が同等になりました。

 

 さらに検討をすすめる

 

じゃあ、削ろうかなと準備していたところに、オリジナル作者のakrさんから

 

mktime が tzset する副作用は意図して使っていたわけじゃないけど、ユーザから見ると /etc/localtime の変化に自動的に追従する挙動を提供していたと思う。
追従しない挙動に変えるのなら、代替手段が存在した方が説明しやすいと思う。
誰も気にしない可能性もあるけど。

 

というコメントをいただきました。その後しばらくコミッタ同士で議論して、

ENV['TZ'] = nil

したら、次のTime.newはtzsetを呼びなおすという挙動にすることにしました。これはRuby 2.6でのlocaltime_rの高速化をした

 

commit 4bc16691279e98ecdb3e19ff23902be671d46307
Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
Date: Wed Jul 18 10:30:41 2018 +0000
reduce tzset

* time.c (rb_localtime_r): call tzset() only after TZ environment
variable is changed.

 

において、TZ環境変数を設定したらtzset()を呼びなおすという実装がすでに入っていたため、それを素直に拡張して、ENV['TZ'] = nil のときは元々nilだったとしてtzset()をしなおす(/etc/localtimeが変更されていればtimezoneは変わる)という挙動にしました。

  

  

まとめ

今回議論した mktime削除パッチは

https://github.com/ruby/ruby/commit/4d7a6d04b2c71aabb9d6e619f4405887806a5be8

としてコミット済みのため、とくに問題なければRuby 2.7に含まれるはずです。

 

よって要約すると

  • Ruby 2.6ではTime.newが3倍ぐらい速くなった
  • Ruby 2.7ではさらに2倍ぐらい速くなる(予定)
  • そのため、2.7以降では、TZ環境変数を設定する必要はまったくない

 ということになります。

 

アカツキさまのおかげで全世界のRailsアプリが高速化されました。このような改善につながるバグ報告は大変ありがたく、とても素晴らしい貢献だと思います。

 

運用フェーズのプロダクトのCocos2d-xバージョンを3.2から3.17に一気に上げた時の知見

この記事は https://adventar.org/calendars/3952 3日目の記事です。

 

はじめに

 こんにちは。クライアントエンジニアのRiyaaaaaです。

 私が担当しているプロダクトではゲームエンジンとしてCocos2d-xを採用しています。リリース当初のバージョンは3.2で、それ以降4年間1度もアップデートされることはありませんでした。しかし、今年、関係各所の調整の結果、とうとうCocos2d-xを最新バージョンまで上げる大規模な改修バージョンのリリースに成功し、こうして記事の執筆に至った次第です。

 断っておきますが、執筆者である私はCocos2d-xバージョンアップ作業において、先行的な技術調査、最低限のゲームを動かすためのコンパイル作業や基幹システムへの修正等しか行なっておりません。Cocos2d-xバージョンアップという大きな改修は、多くのエンジニアの協力あって実現しました。この場を借りてお礼申し上げます。

 

Cocos2d-xバージョンアップを実行に移した経緯

 品質向上のためにもゲームエンジンのバージョンを上げたいという話は以前から上がっていましたが、プロダクトの視点から見ると、リスクの割にベネフィットが薄い点が否めません。そのため、問題意識はありながらも、開発項目に具体的に上がることはありませんでした。

 しかし、スマホアプリ業界に2つの大きな激震が走り、Cocos2d-xのバージョンアップはほぼ必須というところまで追い込まれてしまったのです。業界の方ならよくご存知でしょう。

 1つ目は、2018年6月ごろAppleが発表した、iOSのOpenGL ESの利用をdeprecatedとする発表です。つまり、将来的にOpenGL ESはサポートされなくなるので、Metalへ移行すべしというお達しです。

 2つ目は、2019年1月ごろGoogleが発表した、Google Playアプリは2019年8月をもって64bit対応を必須とする発表です。これはiOSの件よりも深刻でした。なぜなら、数年後といったスパンではなく、残り半年強という期限で対応を迫られていたからです。*1

 この2つの発表が決め手となり、ついにプロジェクトリーダー、版元様、ディレクター陣の合意を取り、現場のエンジニア、テスターなどのスタッフの大規模なリソースを注いでの、バージョンアップ作業が始まりました。

 

バージョンアップ作業黎明期、とりあえずゲームが動くまで

 さて、私はというと、AppleのOpenGL ESのdeprecated化の発表より、秘密裏にCocos2d-xバージョンアップ計画を進めておりました。私は将来的に必ず、ゲームエンジンのバージョンアップを迫られる日が来るという直感があったからです。*2 しかし、マイナーバージョンを2から17に上げるというアグレッシブな改修には、そもそも「可能である」ことの証明が必要です。そのため、開発の空き時間などを利用し、地道にローカルでバージョンアップ作業を進めていました。

 もちろんコンパイルすら通らないところからのスタートです。gitで専用のworkspaceを切って、毎日少しずつコンパイルエラーを減らしていきました。ようやくコンパイルが通ったところで、起動時クラッシュに直面。そこから数多くのファイルシステム、ネットワークシステム、その他クラッシュを引き起こす不具合を修正し、「とりあえず動く」状態に持って行きます。

 

Cocos2d-xバージョンアップの開発本格始動

 そして2019年初ごろ、Googleの64bit対応必須化発表の折、「Cocos2d-xアップデートなしには対応は不可能」という見解をエンジニアチームは出します。ndk-buildのabiFilterにarm64-v8aを追加する、そんな単純な話ではありません。特に問題になるのが、Third-pirty製静的ライブラリです。アプリ側のライブラリはもちろん、Cocos2d-xが依存する外部静的ライブラリもほぼ全てが64bitサポートされていませんでした*3。エンジンはアップデートすることなくライブラリだけアップデートする? そんなことが不可能なのは火を見るより明らかでした。

 しかし功を奏して、私の手元にはとりあえず一通り動作している最新Cocos2d-xリプレイス済みバイナリがありました。もちろん、遷移するだけでクラッシュする画面もあれば、どこもかしこもレイアウト崩れが起きまくっていましたが... 「バージョンアップ、イケると思います」

 こうして、Cocos2d-xバージョンアップ計画は、新規開発チーム全体を巻き込んで始まったのでした。

 ちなみに、私はCocos2d-xバージョンアップのメイン開発チームには加わっていません(!?)。弊プロダクトは定期的に大規模なイベントを開催しておりますが、その重要機能の開発に追われていたからです。残念なことです。しかし、ちょうどその時に社内から異動してきたエンジニアの方が低レイヤーなんでも御座れの超ベテランエンジニアだったので、代わりに担当していただき、結果的に素晴らしいアウトプットになりました。最後に紹介しようと思いますが、単なるCocos2dxアップデートに留まらない劇的なビルド環境改善に取り組んでくれたのです。
 

起こったバグ、修正方針まとめ

 以降は、事象、修正方針ベースで項目化して紹介していきます。あまりにも量が膨大だったため、漏れがあるかもしれませんが、参考にしてください。免責事項として以下に紹介する内容はあくまで弊プロダクトの修正方針であり、全てのプロジェクトで動作を保証するものではありません。また、私が実際に修正したわけではないものも多くありますが、誰かの役に立つことを願って、代理として紹介させていただきます。

1. ファイルシステムの大規模なコンフリクト

 弊プロダクトはCriFsというCRIWARE様のファイルシステムを採用しています。そのため、Cocos2d-xのFileUtilsをはじめとするファイルシステム関連クラスには独自拡張を大量に含んでおり、バージョンアップの際に大規模なコンフリクトを起こしました。気合で直しました。初っ端から参考にならない事例で申し訳ない... 

2. HttpClientクラスのレスポンスコードの取り扱いの変化

 元のcocos2d/cocos/network/HttpClientには、responseCodeが200以上、300未満ではない場合、タスクの失敗とする実装がありましたが、3.17のHttpClient-apple/HttpClient-androidクラスでは、それに該当するコードが無くなっていました。つまり、コールバックの取り扱いが変化していたのです。すると、アプリ側でFailureコールバックとしてハンドリングしていた部分が途端に動かなくなりました。

 そのため、挙動を元に戻すためにエンジンに手を加えました。例えば、HttpClient-apple::processTaskの末尾に3.2当時のと同等動作のコードを加えます。

static int processTask(HttpClient* client, HttpRequest* request, NSString* requestType, void* stream, long* responseCode, void* headerStream, char* errorBuffer)
{

  // 中略

  + if (!(*responseCode >= 200 && *responseCode < 300)) {
  +   return 0;
  + }

  return 1;

}

androidも同様です。

3. OpenSSL EVP_CIPHER_CTXのインスタンスの確保方法の変化

 aes_encrypt/aes_decryptに使う暗号情報のコンテキストの型EVP_CIPHER_CTXが、動的確保に変化しました。具体的には、EVP_CIPHER_CTXは前方宣言のみ提供され、今までのようにスタック変数として宣言することができなくなり、EVP_CIPHER_CTX_nex(), EVP_CIPHER_CTX_free()インターフェースで動的確保、解放することを要求されるようになりました。

4. FileUtils::fullPathForFileNameのファイルが見つからなかった時の挙動の変化

 以前の実装ではファイルが見つからなかった時の挙動が「ファイル名」を返す、という挙動でしたが、空文字列が返るように変更されています。妥当な修正ですが、以前の挙動を前提としたコードがあったので元に戻しました。

5. Spriteのレンダー用のコマンドクラスがQuadCommandからTrianglesCommandへ変化

 独自のSpriteを継承した描画クラスが、draw関数をオーバーライドして実装していましたが、その辺りが旧_quadCommandメンバにアクセスしていたため、_trianglesCommandに変更しました。インターフェース等は抽象クラスが同じなため変数差し替えだけで動作しています。

 

6. RefPtrが不完全な型を受け付けなくなった

 RefPtrにコンパイル時型検査が追加されました。

static_assert(std::is_base_of<Ref, typename std::remove_const<T>::type>::value, "T must be derived from Ref");

 std::is_base_ofは完全型を要求するので、既存のコードで前方宣言のみされた型をRefPtrとして定義しているところのコンパイルが通らなくなったのです。これはこのstatic_assertをコメントアウトするだけでも解決しますが、アプリ側の該当箇所が1箇所だったのでそちらを修正しました。

class A {

  class B {

    cocos2d::RefPtr<A> _ptr;

  };

};

 
 このように、インナークラスが外側のクラスのRefPtrを保持するような設計でしたが、これだとBの定義段階ではAは不完全型なので、インナークラスをやめて分離することで解決しました。

7. Scene::_childrenにカメラインスタンスが追加され、_childrenのインスタンスのインデックスが変化した

 これはかなり頭を悩ませました。なにせクラッシュを引き起こす上に、不正なstatic_castを起こして意味不明な場所でバグるのです。そんなコードが何十箇所も!!

 これははっきり言ってお見せするのも恥ずかしい典型的なアンチパターンのコードなのですが、画面の構築順序上「このインスタンスはchildrenのX番目にある」という危なげな根拠による、childrenメンバへのインデックスによるアクセスコードが大量にあったのです。
  

// X番目のChildはHogeクラスだからstatic_castするぜ

auto hoge = static_cast<Hoge*>(view->getChildren().at(X));


 これは最悪なコードです。まず前提としてこんなコードを書くべきではありません。ですが、開発黎明期に書かれたレガシーコードには多くのこういったコードが含まれていました。*4 しかも、たちの悪いことに、static_castを使用しているのです! 嗚呼、これがdynamic_castだったなら、即時にnullptrアクセスで落ちるのに。しかし、static_castは違うインスタンスポインタだろうが問答無用でキャストします。その結果、アクセスの仕方によって様々な挙動を見せます。これは低レイヤー言語の趣深い挙動ですね。クラッシュすればいい方です。

これはgrepで該当コードを探し出してひたすら修正しました。修正方針はそこの文脈で都度判断。ですが、原因の多くはSceneクラスを定義する時、Layerを継承して空のSceneにaddして返す、という古きCocos2d-xのお作法によるものが多かったです。つまり、あるSceneをcreateした時、返ってくるinstanceは目的のクラスではなく、空のSceneクラスだったのです。そのため、childrenから目的のクラスインスタンスを探すコードが多くありました。

auto scene = MyScene::create();

auto myClass = static_cast<MyScene*>(scene->getChildren.at(0)); // 最新バージョンでは、0番目はカメラのインスタンスのためNG

 
 実際にはSceneクラスを定義する時にそんな面倒なことをする必要はなくシンプルにSceneを継承すればいい話です。公式のサンプルコードも、すでにその黒歴史を修正しています。
don't use Layer by minggo · Pull Request #17048 · cocos2d/cocos2d-x · GitHub


上記修正と同じことを既存のSceneクラスに取り込めば、大体は解決しました。

 

8. いくつかのクラス、関数が引数にnullptrを受け付けなくなっていた

CCLuaStack::luaLoadBuffer、CCProgresTimer::initWithSpriteなどです。大抵は呼び出しもとでnullptrハンドリングして終了です。

9. setColorを使ったグレーアウトが動作しなくなっていた

setColorの内容を子供に伝播させるにはNodeのcascadeColorEnabledをtrueにしなくてはならないのですが、様々なCocos2d-x関連クラスのデフォルト値がfalseに変更されました。そのため、setColorを使ったグレーアウトなどの処理が途端に動かなくなったため、急ぎ様々なViewクラスでsetCascadeColorEnabledを呼び出して止血しました。現象次第はシンプルなのですが、如何せん影響範囲が広く、一つの原因に紐づくバグチケットの数がかなり多かったですね。。

10. Androidで一部通信のstyleがunknown_formatになる

 Cocos2dxはAndroidでHttp通信にcurlではなくjava.net.HttpConnectionを使うようになりました。この時、デフォルトヘッダの挙動が変わり Accpet: */* が追加されなくなりました。この時、サーバーサイドのAPIのroutesでレスポンスのMIMEタイプが指定されてないときの挙動の違いにより、レスポンスの解釈がiOSとAndroidで変化するようになってしまいました。というか、基本的にはjson以外受け付けてないんですけどね...

これはアプリ側のリクエストクラスでデフォルトヘッダの差を吸収するようにしています。サーバーサイドでも必ず全てのAPIのroutesで{format: json}を指定するようにしてもらいました。

11. Android4.4未満で通信がバグる

お気の毒ですがCocos2d-x 3.17では4.4未満をサポートしなくなりました

13. ImageViewのアルファチャンネルが無効になるバグ

これはシンプルにcocos2d-xのバグで、ImageViewを2回同じファイル名でloadTexuteを呼び出すとアルファチャンネルが効かなくなるバグです。
これは担当エンジニアがすでに本家にプルリクを送っており、マージされました。
github.com

14. Labelの末尾の改行が無視されなくなった

バグだったのかはわかりませんが、末尾の改行がちゃんと適用されるようになり、それによりレイアウト崩れが発生していました。

15. 9sliceを有効にしたImageViewが特定条件下でバグる

fix_bottomとfix_topが実際の画像の縦幅を超えるというデザインバグがあり、なぜか今まで動いていた状態だったが、バージョンアップによって普通に表示が崩れるようになってしまいました。

16. SceneをaddChildしているところが動かなくなった

そんなことをしてはいけません。おそらくVisittingCameraとかそういうアクティブなシーンのカメラみたいな概念が追加された影響で動かなくなったのかと。replaceSceneやpushSceneを使いましょう。

17. 勝手にボタンがグレーアウトする

ui::Button::setEnableにfalseを渡すと、Buttonクラスの内部で勝手にグレーアウトするようになりました。仕様ということにしました。

18. ScrollViewでクリッピングがバグる

Cocos2d-xのバグです。社内で独自のパッチが当てられましたが、本家では別の形で修正されているようでしたので、そちらの方のリンクを貼っておきます。
https://github.com/cocos2d/cocos2d-x/pull/20352

19. LabelLetterを使っているところでバグる

Cocos2d-x側のバグです。本家にPRを送りました。
Fix: LabelLetter::isVisible always returns false by Riyaaaaa · Pull Request #18975 · cocos2d/cocos2d-x · GitHub

20. Labelの返すgetContentSize().hegihtが半分になっている

これはかなーーり大変な挙動の変化でした。半分になった、というよりはもともとバグっていて2倍になっていたのが元に戻った、というのが正しいです。
しかし、これを前提として構築されたレイアウトがとんでもなく多く、ハードコーディングされたオフセット、italicでアフィン変換された時の位置、様々な箇所に止血対応が入りました。heightサイズバグを再現するLegacyLabelクラスの爆誕などもしました...。この挙動の変化の影響で、とんでもない数の画面の表示がおかしくなっていたのです。。。
全体の工数の10%くらいは、この不具合の対応に追われていたような気もします。笑
 

21. Cocos2d-xのLuaBindingの強化

3.17では、任意のCocos2d-x APIをLuaから呼び出せるように、大規模な改修がされています。ただし、その影響でエンジンのいたるところに、ScriptBindingが有効な時にのみ走る処理が追加されています。弊プロダクトでは、Cocos2d-x Lua-bindingを使用していません。これらの処理は無用なオーバーヘッドなので、CC_ENABLE_SCRIPT_BINDINGを無効にしました。*5


こんなところでしょうか。数が多すぎて網羅できた気がしない...。

おわりに

Cocos2d-xバージョンアップの歴史を一気に振り返りました。この記事を執筆する上で、大量のバグチケットやプルリクを漁り、懐かしい気持ちになりながら、当時の慌ただしさを感じていました。どうせエンジンをアップデートするなら、他のシステムも改善したいというエンジニアの要望もあり、同バージョンには多くのシステム改善がされました。

・Android NDKビルドシステムのndk-buildから、CMakeへの移行
・サウンド系システムの大改修
・CocoaPodsの導入
・様々なThird-pirty製ライブラリのアップデート
・その他パフォーマンス改善など

トータルで半年以上の開発期間(検証含む)を要したこのバージョンは、無事Android 64bit対応期限に間に合い、本番環境で深刻な不具合を出すことなくリリースされました。機能追加を含まないバージョンを、半年以上も開発し続けることができるリソースがチームにあったことはとても喜ばしいことです。これが実現できたのは、現場の開発者だけではなく、マネージャー、運用サイドの担当者などの多くの方のご協力があってのことです。

ちなみにOpenGL ESが本格的にiOSでサポートされなくなり、Metal対応が必須になった時、きっとCocos2d-x v4へのバージョンアップが迫られることでしょう...。メジャーバージョンアップには、今回の規模を遥かに超える改修が必要になりそうです、が、このチームなら乗り越えられる気がしています。多分。

ここまで読んでくださりありがとうございました。


 

*1:しかし、この記事を執筆する上で再度調査していると、実際には2017年には告知されており、弊プロダクトは技術に対するアンテナが細かったために急な対応を迫られてしまった説があります。反省ですね。

*2:この時は、まだAndroid 64bit対応の発表はされていませんでした。

*3:iOSライブラリだけは、64bit対応が2014年くらいに実施されていたので対応されていました

*4:もちろん私はこんなコード書きません。

*5:なぜ有効になっていたのかというと、Cocos2d-xとは関係のないオリジナルのLuaEngineのバックエンドに、CCLuaEngineを使用していたためです。本来はtolua++等のピュアなLua Bindingライブラリを使用すれば必要のない設定でした。

環境変数を設定するだけでRuby on Railsサーバが10%高速化する(かもしれない)話

この記事は Akatsuki Advent Calendar 2019 1日目の記事です。

はじめに

アカツキでは Ruby on Rails を使ったゲームサーバを開発・運用しています。ゲームの体験を向上するために、レスポンスタイムは一つの重要な要素となるため、種々のパフォーマンスチューニングを行なっています。今回はその一例として、環境変数を1つ設定するだけで、あるAPIのレスポンスタイムが10%も改善した例をご紹介します。

TL;DR

多数の時刻を含むレコードを扱う Ruby on Rails サーバでは、 TZ 環境変数を設定することで、デフォルトタイムゾーン設定ファイル /etc/localtime へのアクセスが減り、高速化が図れるかもしれません。

効果は Time オブジェクト1個あたり数μsの短縮といったオーダーですが、チリも積もれば山となり、数千個のレコードを処理するAPIではレスポンスタイムが10%近く改善する例もありました。

f:id:NeoCat:20191105185907p:plain

APIのレスポンスタイムが10%も改善!

きっかけ

ある日、モバイルゲームのAPIサーバの負荷テストを大きめのインスタンスサイズのサーバで実施したところ、小さい構成のサーバでは問題なかったAPIのレスポンスタイムが、なぜか数秒から数10秒と、とんでもなく遅くなるという事象が起きました。
その時のシステムの状態を top を確認してみると、CPU使用率の user は数%なのにも関わらず、sys が 95% といった高い値を示しており、アプリケーションではなく OS (Linux) 周りの問題であるようでした。

環境

問題が発生した環境は、AWS EC2の c5.9xlarge インスタンス (36 core) の上にDockerで ruby:2.5 コンテナ(Debian Stretchベース)を立て、その中でRailsサーバーを動かしており、そこに多数並列でHTTPリクエストを送り込んでいた、という状況です。

Railsのサーバとして、unicorn が複数プロセス動いており、各プロセスはシングルスレッドで動作する構成です。つまり、スケーラビリティの問題の原因になりやすい Ruby の GIL (グローバルインタプリタロック) のせいではありません。

詳しく分析してみる

このセクションでは、 Linux カーネルや Ruby の動作を調べた内容を説明していきます。低レイヤーに踏み込む話になるので、早く結果を知りたいという方は、次のセクションの「対策とおまけ効果」まで読み飛ばして構いません。

プロファイラをかけてみる

こういったときには、どこでCPUが使用されているかをプロファイラで調べてみると有効です。そこでまず、 Linux のプロファイラである perf を使用してみます。

問題発生中に sudo perf top -g を実行すると、CPU が使われている場所のプロファイルが C の関数単位でリアルタイムに表示されます。

以下は95%以上を占める高い __xstat64 から下位の関数を展開していったところです。なお __xstat64 はファイルの変更日時などの情報を取得するglibcの関数です。

Samples: 30K of event 'cycles', Event count (approx.): 32976632083
  Children      Self  Shared Object       Symbol
-   95.21%     0.02%  libc-2.24.so        [.] __xstat64
   - __xstat64
      - 95.04% entry_SYSCALL_64
         - do_syscall_64
            - 94.14% __do_sys_newstat
               - 94.03% vfs_statx
                  - 92.21% filename_lookup
                     - 92.14% path_lookupat
                        - 66.85% link_path_walk.part.39
                           - 63.60% walk_component
                              - 22.86% lookup_fast
                                 - 22.75% __d_lookup
                                    + _raw_spin_lock
                              - 21.11% path_parent_directory
                                 - 19.89% dget_parent
                                    - lockref_get_not_zero
                                       + _raw_spin_lock
                                 + 1.23% dput
                              - 19.53% dput
                                 + 18.02% _raw_spin_lock
                                   1.38% lockref_put_return
                           + 3.00% inode_permission
                        - 22.98% walk_component
                           - 20.49% dput
                              + 19.17% _raw_spin_lock
                                1.14% lockref_put_return
                           + 2.41% lookup_fast
                        + 1.70% trailing_symlink
                        + 0.57% terminate_walk
                  + 0.88% path_put


詳細は割愛しますが、path_lookupat 関数を始め、主に Linux カーネル内のファイルパスを辿る関数群で時間を消費しているようです。さらに辿っていくと、主要因としていろんなところで _raw_spin_lock が出てきました。これは、 Linux カーネルのスピンロック (他のCPUと排他が取れるまで無限ループしながら待つロック方式) の関数で、1つのコアしか同時に処理を行えません。何らかの同じリソースの取り合いが全コアで発生し、コア数が多い分、より激しく競合が発生した結果、アプリケーションの処理が遅々として進まないほどに性能が低下してしまったと考えられます。

では一体何を奪い合っているのでしょうか?

システムコール呼び出しを見てみる

アプリケーションがこの時何をしているのかを調べてみます。

strace -p <rubyのPID>

を実行して何のシステムコール呼び出しているかを調べてみると、どのプロセスも、

stat("/etc/localtime", ...)
stat("/etc/localtime", ...)
stat("/etc/localtime", ...)
...

と、ひたすら /etc/localtime というファイルに対して stat システムコールを呼び出していることがわかりました。同じファイルに対して全コアでロックを取りあっているため、激しく競合が発生しているようですね。

このファイルは、システムのデフォルトのタイムゾーン情報を格納するものです。

ファイルと言いましたが、正確にはrubyコンテナではシンボリックリンクになっています。

UTCをデフォルトタイムゾーンとして使用していますので、リンク先は /usr/share/zoneinfo/Etc/UTC を指しており、さらにこれもシンボリックリンクで ../UCT を指しています。

また同様に ltrace をアタッチしてみると、tz_set, localtime_r などの時刻関連の関数がひたすら呼び出されていました。この中で先ほどの stat システムコールが呼び出されています。

stat システムコールということは、このファイルの内容を読んでいるわけではありません*1。もしかしたらいつの間にかデフォルトのタイムゾーンが前回から変更されているかもしれないので、再読み込みか必要かどうかを調べるために、更新日時を調べているのです。( → glibc__tzfile_read() )

Ruby on Railsはその時何をしていたのか?

では、なんでこんなに localtime_r が呼ばれているのでしょうか?
実は、負荷テストのシナリオの中に、数千件のレコードを MySQL から取得して読み込む API がありました。これらのレコードにはそれぞれ数個の日時が含まれていました。加えて、ActiveRecordの慣例に従って、各レコードには created_at, updated_at カラムがあり、作成・更新時刻を格納しています。
そしてこれらを ActiveRecord が Time(WithZone) クラスとしてインスタンス化する際に、 localtime_r が呼び出されていたのでした。

f:id:NeoCat:20191105191132p:plain

読み込んだレコードには日時が多数含まれていた

localtime_rTime.new ごとに1回呼ばれるだけではなかった

しかも、 localtime_r は Time のインスタンス化で一回呼び出されるだけではありませんでした。

strace ruby -e 'puts; p Time.new'

などと実行してシステムコールの呼び出され方を見てみると、以下のようになりました。*2

  • Time.new → statが1回呼ばれる
  • Time.new(2019,7,1,0,0,0,"+09:00") → なぜかstatが2回呼ばれる
  • Time.new(2019,7,1,0,0,0) → なぜかstatが4回くらい呼ばれる(timezoneを取得するため?)

Ruby の time.c を見てみると、 find_time_t 関数にてシステムの localtime_r に指定時刻の2時間前後の時刻を与えて、何が返ってくるかを調べています。これはどうやら、夏時間の切り替わりの際には同一の時刻が2回ある場合があるので、そういうときに必ず決まった側を返すための処理のようでした。

それにしても、このコードには多数の #ifdef があり、Ruby を様々な環境で動かすための苦労が窺われます……。

対策とおまけ効果

man tzset を見てみると書いてあるのですが、 環境変数 TZ に値が設定してあれば、 /etc/localtime は読まれなくなり、この問題も発生しなくなります。
そこで、例えば TZ=UTC と設定すると、 stat 等のファイルアクセスはなくなります。

これは今回きっかけとなった負荷テストで見られたような大規模サーバでのスケーラビリティの解決はもちろんですが、たとえ小さなサーバであっても、システムコールの発行自体がなくなることで性能向上を期待できます。

具体的に、先ほどのruby:2.5.1コンテナ内で、シングルプロセスのみで試してみましょう。

$ irb
irb(main):001:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 1.027663412

# 環境変数を設定
irb(main):002:0> ENV['TZ'] = 'UTC'
=> "UTC"

irb(main):003:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 0.135658217

なんと7〜8倍の高速化です!

Linuxディストリビューションによっては、 /etc/localtime はシンボリックリンクでなく実ファイルであることもあります。
例えばAmazon Linux 2では /etc/localtime は実ファイルとなっていますが、このケースでも測定してみました。

irb(main):001:0> t = Time.now; 100000.times { Time.new(2019) }; Time.now - t
=> 0.57196811

TZ を設定すると先の例と同程度の時間になり、約4倍の改善となりました。シンボリックリンクのパスを辿らなくて済む分、軽微な影響となるようです。

もちろんこれは Time.new のみの倍率であって、1回1回は高々数μsといったオーダーの効果です。しかし、数千レコードを扱うようなAPI*3だと、積もり積もってAPI全体のレスポンスタイムが10%程度も改善するケースが実際にありました。

まとめ

Ruby on Railsで大量の時間を含むレコードを扱う際、 TZ 環境変数が設定されていないと、Time オブジェクトの初期化のたびに複数回 /etc/localtime に対して stat システムコールが呼び出されるため、性能が低下します。特に /etc/localtime がシンボリックリンクである場合や、コア数の多いサーバ環境ではカーネル内のスピンロックのために影響が顕在化しやすくなります。この現象は特にRuby 2.5までにおいて顕著です。

TZ 環境変数を適切な値に設定することで、これを避けて、時刻を扱う処理を高速化することができます。

 

今後のRubyへのフィードバック

さて、これで本問題は一段落なのですが、 こうした手間をかけなくともRuby自体で高速に動作してくれたら嬉しいですよね。アカツキに技術顧問として加わって頂いた小崎資広さんに、この現象についてRubyのアップストリームで根本的な改善ができるのではないかと、コミュニティで議論していただいています。

 詳しくは別の記事でご紹介したいと思いますので、乞うご期待。 
→ 記事が公開されました! ぜひ併せてお読みください。

hackerslab.aktsk.jp

*1:ファイルの内容は、起動直後に1度だけ読み込まれています。

*2:なお、この挙動はRuby 2.6で少し変更され、stat(2)の呼び出しは 1回となっているようです。

*3:ゲームの運用を続けていくにつれてデータが増えていき、数千件のレコード処理の読み込みが必要になることはままあります。