Invoking Action<T> is 10x slower in Unity3d than a Visual Studio Console app

I’ve written the following sample application in Visual Studio 2017 (I no longer have 13 or 15 installed :/) targeting both .Net 2.0 and .Net 4.6. The results of this show that a compile time defined Action can be executed at runtime in around 3 Ticks, while an Action compiled at runtime from an Expression can be executed in 2.6 Ticks, on average.

When I run this same code in Unity3d, I’m seeing it take nearly 10x longer, 22 Ticks and 20 Ticks respectively. Is there a technical reason why, such as the runtime not being as quick as perhaps Roslyn is? I can’t remember, but would my .Net 2.0 test still be using Roslyn, since it was done in VS 17?

    using System;
    using System.Collections.Generic;
    using System.Diagnostics;
    using System.IO;
    using System.Linq;
    using System.Linq.Expressions;

    namespace CompiledActionDelegate
    {
        class Program
        {
            static Action<BinaryWriter> compiledAction = null;
            static void Main(string[] args)
            {
                var watch = new Stopwatch();
                int iterations = 1000000;
                var times = new List<long>();

                for(int count = 0; count < iterations; count++)
                {
                    watch.Start();
                    RunAction(writer => writer.Write("Foo Bar"));
                    watch.Stop();
                    times.Add(watch.Elapsed.Ticks);
                    watch.Reset();
                }

                Console.WriteLine($"Average Action time: {times.Average()} ticks over {times.Sum()} ticks.");
                CreateCompiledAction(writer => writer.Write("Foo Bar"));
                times.Clear();
                for (int count = 0; count < iterations; count++)
                {
                    watch.Start();
                    RunCompiledAction(compiledAction);
                    watch.Stop();
                    times.Add(watch.Elapsed.Ticks);
                    watch.Reset();
                }
                Console.WriteLine($"Average Action time: {times.Average()} ticks over {times.Sum()} ticks.");
                Console.ReadKey();
            }

            static void RunAction(Action<BinaryWriter> callback)
            {
                using (var writer = new BinaryWriter(new MemoryStream()))
                {
                    callback(writer);
                }
            }

            static void RunCompiledAction(Action<BinaryWriter> callback)
            {
                using (var writer = new BinaryWriter(new MemoryStream()))
                {
                    callback(writer);
                }
            }

            static void CreateCompiledAction(Expression<Action<BinaryWriter>> exp)
            {
                compiledAction = exp.Compile();
            }
        }
    }

This was the Unity3d version of the code that I wrote. I attached “Client” to the Main Camera in a new scene, from a brand new project.

using UnityEngine;
using System.Collections;
using System.Net.Sockets;
using System.Net;
using System.Text;
using System.Linq;
using System;
using System.IO;
using Assets.scripts;
using System.Linq.Expressions;
using System.Diagnostics;
using System.Collections.Generic;


public class Test
{
    static Action<BinaryWriter> compiledAction = null;
    public static void Run()
    {
        var watch = new Stopwatch();
        int iterations = 1000000;
        var times = new List<long>();

        for(int count = 0; count < iterations; count++)
        {
            watch.Start();
            RunAction(writer => writer.Write("Foo Bar"));
            watch.Stop();
            times.Add(watch.Elapsed.Ticks);
            watch.Reset();
        }

        UnityEngine.Debug.Log(string.Format("Average Action time: {0} ticks over {1} ticks.", times.Average(), times.Sum()));
        CreateCompiledAction(writer => writer.Write("Foo Bar"));
        times.Clear();
        for (int count = 0; count < iterations; count++)
        {
            watch.Start();
            RunCompiledAction(compiledAction);
            watch.Stop();
            times.Add(watch.Elapsed.Ticks);
            watch.Reset();
        }
        UnityEngine.Debug.Log(string.Format("Average Compiled Action time: {0} ticks over {1} ticks.", times.Average(), times.Sum()));
    }

    static void RunAction(Action<BinaryWriter> callback)
    {
        using (var writer = new BinaryWriter(new MemoryStream()))
        {
            callback(writer);
        }
    }

    static void RunCompiledAction(Action<BinaryWriter> callback)
    {
        using (var writer = new BinaryWriter(new MemoryStream()))
        {
            callback(writer);
        }
    }

    static void CreateCompiledAction(Expression<Action<BinaryWriter>> exp)
    {
        compiledAction = exp.Compile();
    }
}

public class Client : MonoBehaviour
{
    // Use this for initialization
    void Start()
    {
        Test.Run ();
    }
}

Was this from within the editor? For some operations, I’ve noticed substantially slower times from within the editor compared to building a standalone app and executing that. Surely has to do with building in debug mode while in the editor, but in release mode with a host of optimizations turned on when making a build.

1 Like

It was in the editor. I’ll try and put something together that will let me see the results at runtime on a production build.

It also wouldn’t surprise me if Unity genuinely is slower. Unity has a bunch of issues due to the old version of Mono. This is further compounded by the need to support every platform in existence.

There are lots of changes in the wind that should speed things up. But it all takes time.

You can download the beta with .NET 4.6 support and check out what the times are there. Latest one is this one.

2 Likes

And please post your findings… I use Action constantly.

Also keep in mind that there is a whole game engine running on your machine when you use Unity, not so much on a console application.

I’d also suspect that Debug.Log is somewhat slower than Console.WriteLine - Debug.Log has to build a stacktrace

Debug.Log is outside the timed portion.

I will download it and give it a shot. The published version of the app wouldn’t be affected would it? I’m not familiar with whether all apps go through IL2CPP or just apps on platforms that require it.

I have kept that in mind as well. There’s nothing going on in the scene, and this happens in a single frame, which I would think would account for engine overhead somewhat. Unless there’s a massive amount of stuff happening on background threads in the engine (not familiar with the engine architecture). I’ll report back the 4.6 version findings and that will tell me pretty quickly if it’s engine overhead or the old Mono runtime.

Will do. It takes 10,000 Ticks to make 1 millisecond. So unless you’re using hundreds of Action instances per frame, you’ll likely not even notice this difference TBH. This was just something I caught when benchmarking the cost of parsing Expression trees in Unity (fairly cheap) and thought it would be interesting to ask.

The benchmarks here were slower. 38 and 39 ticks to run. Not sure if it’s because this is a preview build and not a production optimized version of what we’ll see in the end or not. It does state in the release notes that the release is for testing stability and not performance.

My first thoughts are inlining and branch prediction. However, it’s hard to see where branch prediction would be failing on unity’s IL but working on the roslyn IL. Inlining is a possibility. The only way to know for certain is to look at the IL that is generated by unity’s mono, and the IL generated by your version of ms’s compiler.

One thing I notice is that you create a list, but don’t initialize it with a length. This will negatively impact the time of the first loop, since you will pay the list resize cost in that loop, but not the second one.

Yeah, I’ve sinced updated my script so that I run a warmup loop first, then perform the test on the two different Actions. The difference is now nanoseconds between Expression based Action and compile-time Action.

This was the updated script, you can see I also pre-compiled the Action, instead of instantiating one every loop. Which wasn’t a fair comparison to the second loop. So the results between the two are virtually identical. However they’re still 8-10x slower than Unitys runtime.

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Linq.Expressions;

namespace CompiledActionDelegate
{
    class Program
    {
        static Action<BinaryWriter> compiledAction = null;
        static Action<BinaryWriter> precompiledAction = new Action<BinaryWriter>(writer => writer.Write("Foo Bar"));
        static string Name { get; set; } = "Foo Bar";

        static void Main(string[] args)
        {
            var watch = new Stopwatch();
            int iterations = 1000000;
            var times = new List<long>();

            for (int count = 0; count < iterations; count++)
            {
                watch.Start();
                RunAction(precompiledAction);
                watch.Stop();
                times.Add(watch.Elapsed.Ticks);
                watch.Reset();
            }

            Console.WriteLine($"Average Action warmup time: {times.Average()} ticks over {times.Sum()} ticks.");
            CreateCompiledAction(writer => writer.Write("Foo Bar"));
            times.Clear();

            for (int count = 0; count < iterations; count++)
            {
                watch.Start();
                RunAction(precompiledAction);
                watch.Stop();
                times.Add(watch.Elapsed.Ticks);
                watch.Reset();
            }

            Console.WriteLine($"Average Action time: {times.Average()} ticks over {times.Sum()} ticks.");
            CreateCompiledAction(writer => writer.Write("Foo Bar"));
            times.Clear();
            for (int count = 0; count < iterations; count++)
            {
                watch.Start();
                RunCompiledAction(compiledAction);
                watch.Stop();
                times.Add(watch.Elapsed.Ticks);
                watch.Reset();
            }
            Console.WriteLine($"Average Action time: {times.Average()} ticks over {times.Sum()} ticks.");
            Console.ReadKey();
        }

        static void RunAction(Action<BinaryWriter> callback)
        {
            using (var writer = new BinaryWriter(new MemoryStream()))
            {
                callback(writer);
            }
        }

        static void RunCompiledAction(Action<BinaryWriter> callback)
        {
            using (var writer = new BinaryWriter(new MemoryStream()))
            {
                callback(writer);
            }
        }

        static void CreateCompiledAction(Expression<Action<BinaryWriter>> exp)
        {
            compiledAction = exp.Compile();
        }
    }
}

Looking at the IL, it looks like the Roslyn version creates an entire Type with the method generated in it. The app invokes the method via a singleton in the compiler generated Type. While the Unity version uses a delegate to handle it.

Roslyn

        [CompilerGenerated]
        [Serializable]
        private sealed class <>c
        {
            public static readonly Program.<>c <>9 = new Program.<>c();

            internal void cctor>b__7_0(BinaryWriter writer)
            {
                writer.Write("Foo Bar");
            }
        }

        private static Action<BinaryWriter> compiledAction = null;

        private static Action<BinaryWriter> precompiledAction = new Action<BinaryWriter>(Program.<>c.<>9.<.cctor>b__7_0);

Mono

    private static Action<BinaryWriter> compiledAction = null;

    private static Action<BinaryWriter> precompiledAction = delegate(BinaryWriter writer)
    {
        writer.Write("Foo Bar");
    };

This would kind of explain why delegates are slower than Action in .net full framework when I benchmarked them a few weeks ago. Action is converted into a real method that’s invoked at runtime.

1 Like