MessagePackSerializer.Get is slow

[neuecc]

I'm measuring own serializer(ZeroFormatter) and compare to other serializers. I found MsgPack's MessagePackSerializer.Get is too slow.

Here is my benchmark. https://gist.github.com/neuecc/52a5e0e07e25b52eead26f93ad2b52f9

If get serializer in outer iteration loop, works fine. But "Get is slow" is critical issue. Serializer is normaly called from Stream with type and called Get every time. https://github.com/neuecc/LightNode/blob/master/Source/LightNode.Formatter.MsgPack/MsgPackContentFormatter.cs#L43 It means MsgPack-CLI is x10 slower than JSON.NET...

[yfakariya]

I cannot repro the issue. Coud you tell me testing environment?

My environment is Windows 10 Pro X64 AU, Core i7-3770, 16GB RAM, .NET 4.6.1 build with CLR 4.6.2, release build.

And my micro-repro code is following:

/* My output:
  Warm-up         :526,887.9us
  With-Creation   :56,118.0us
  Without-Creation:90.3us
  Via-MPS.Get()   :93.7us
*/
class Program
{
    static void Main( string[] args )
    {
        try
        {
            const int iteration = 1000;
            var sw = Stopwatch.StartNew();
            new SerializationContext().GetSerializer<Person>();
            sw.Stop();
            Console.WriteLine( $"Warm-up         :{sw.Elapsed.Ticks / 10.0:#,0.0}us" );
            sw.Reset();
            for ( var i = 0; i < iteration; i++ )
            {
                var context = new SerializationContext();
                sw.Start();
                context.GetSerializer<Person>();
                sw.Stop();
            }
            Console.WriteLine( $"With-Creation   :{sw.Elapsed.Ticks / 10.0 / iteration:#,0.0}us" );

            {
                sw.Reset();
                var context = new SerializationContext();
                for ( var i = 0; i < iteration; i++ )
                {
                    sw.Start();
                    context.GetSerializer<Person>();
                    sw.Stop();
                }
                Console.WriteLine( $"Without-Creation:{sw.Elapsed.Ticks / 10.0 / iteration:#,0.0}us" );
            }

            sw.Reset();
            for ( var i = 0; i < iteration; i++ )
            {
                sw.Start();
                MessagePackSerializer.Get<Person>();
                sw.Stop();
            }
            Console.WriteLine( $"Via-MPS.Get()   :{sw.Elapsed.Ticks / 10.0 / iteration:#,0.0}us" );
        }
        catch ( Exception ex )
        {
            Console.Error.WriteLine( ex );
        }
    }
}

[neuecc]

Environment: Windows 10 Pro x64 Intel Core i7-6700 3.40GHz 32GB RAM .NET 4.5 release build. <package id="MsgPack.Cli" version="0.9.0-beta1" targetFramework="net45" />

Your code compare get-speed from context or static direct. I mentioned about serializer lookup speed.

var context = new SerializationContext();

// fast
var serializer = context.GetSerializer<Person>();
for ( var i = 0; i < iteration; i++ )
{
    serializer.Pack...
}

// slow
for ( var i = 0; i < iteration; i++ )
{
    context.GetSerializer<Person>Pack...
}

Get serializer everytime is slower is okay. But serializer lookup speed is (too) slower than other serializers is not good.

[yfakariya]

I got it. Do you mean MessagePackSerializer.Get() should be over 10x than now?

[neuecc]

Thank you, the answer is yes.

[fanoI]

For this object embeds another I get 1750 ms (1.750 seconds) to obtain the Serializer:

    public class DeviceMessage<T>
    {
        [MessagePackMember(0)]
        public int dev_group;
        [MessagePackMember(1)]
        public int dev_level;
        [MessagePackMember(2)]
        public int dev_type;
        [MessagePackMember(3)]
        public int dev_msg_type;
        [MessagePackMember(4)]
        public T   dev_msg_body;

        public DeviceMessage(int dev_group, int dev_level, int dev_type, int dev_msg_type, T dev_msg_body)
        {
            this.dev_group = dev_group;
            this.dev_level = dev_level;
            this.dev_type = dev_type;
            this.dev_msg_type = dev_msg_type;
            this.dev_msg_body = dev_msg_body;
        }
    }
    
    public class D8RMessage<T>
    {
        [MessagePackMember(0)]
        public String sender;
        [MessagePackMember(1)]
        public String receiver;
        [MessagePackMember(2)]
        public int msgtype;
        [MessagePackMember(3)]
        public T body;

        public D8RMessage(String receiver, String sender, int msgtype, T body)
        {
            this.receiver = receiver;
            this.sender = sender;
            this.msgtype = msgtype;
            this.body = body;
        }
    }

This the Tester method:

static void TestMessagePackMemoryStream<T>(T aType)
        {
           Stopwatch timer;

            timer = Stopwatch.StartNew();
            var serializer = MessagePackSerializer.Get<T>(context);
            timer.Stop();

            Console.WriteLine($"Got serializer in {timer.ElapsedMilliseconds}");

            using (MemoryStream stream = new System.IO.MemoryStream())
            {

                timer = Stopwatch.StartNew();
                serializer.Pack(stream, aType);
                timer.Stop();

                Console.WriteLine($"Packed in {timer.ElapsedMilliseconds} ms");

                stream.Position = 0;
                timer = Stopwatch.StartNew();
                var value = serializer.Unpack(stream);
                timer.Stop();

                Console.WriteLine($"Unpacked in {timer.ElapsedMilliseconds} ms");

                timer = Stopwatch.StartNew();
                MessagePackObject valueString = serializer.ToMessagePackObject(value);
                timer.Stop();

                Console.WriteLine($"aType (as json is) {valueString}");
                Console.WriteLine($"To print the json lasted {timer.ElapsedMilliseconds} ms");
            }
        }

And if I use this to serialize an object I got 1'750 ms!

            var D8RMessage3 = new D8RMessage<DeviceMessage<String>>("gmGateClosed", "dmInterfaceManager", 42, new DeviceMessage<string>(42, 69, 1, 16, "Cammina Cazzo!"));
 
            TestMessagePackMemoryStream(D8RMessage3);

Thank you for your help.

[fanoI]

I add another information serializing another Object of the same type but with different values hits a sort of cache as the time from 1750 ms becomes 0 (that is not measurable in ms) so it is a little better but in any case having to wait 1750 ms the first time is not acceptable for my type of applications.

There is maybe an work around?

[marcbarry]

Raised again as its own issue https://github.com/msgpack/msgpack-cli/issues/318