DynamicObject and TrySetMember performance vs ExpandoObject performance
Asked Answered
P

1

5

I'm using a custom implementation of a DynamicObject which works perfectly for my application, other than the fact that I'm running into some performance issues. Some performance overhead is to be expected with dynamics, but I'm seeing significant (read: orders of magnitude) performance penalties even over using ExpandoObject.

The reason I can't use ExpandoObject is that I want to override some of its behavior. I've boiled the problem down to a very simple example below.

My custom ExpandoObject code is the following (simplified down to just enough code to exhibit the problem) --

public class SuperExpando : DynamicObject
{
    public Dictionary<string, object> dictionary = new Dictionary<string, object>();
    public override bool TrySetMember(SetMemberBinder binder, object value)
    {
        dictionary[binder.Name] = value;
        return true;
    }
}

public dynamic m = new SuperExpando();

When I set values in the DynamicObject's dictionary directly (i.e. m.dictionary["keyname"] = 500), then I see performance similar to that of ExpandoObject, which is sub-millisecond times to set the value of the key in the dictionary. When I use the TrySetMember override (i.e. m.keyname = 500), then I see performance drop to as much as 30ms - 50ms per key value set. When writing to lots of keys, this obviously becomes a problem. Even if I write to the same key over and over again, accessing it through TrySetMember takes the same amount of time.

My real performance problem doesn't appear to be related to the fact that I'm using dynamics as it does the TrySetMember override. For kicks I even commented out the

dictionary[binder.Name] = value;

in the TrySetMember method and left nothing but a "return true;", and the performance was the same.

If I add something like the following to my SuperExpando class --

public override bool TryGetMember(GetMemberBinder binder, out object result)
{
    if (dictionary.ContainsKey(binder.Name))
    {
        result = dictionary[binder.Name];
        return true;
    }
    return false; 
}

The performance issues accessing (reading) the variables through TryGetMember is the same, whereas reading the dictionary directly offers reasonable performance.

Any ideas?

-BJ Quinn

EDIT: Here's full sample code. Just create a form and put a button on it that runs the go_Click event and set your project to be a Console Application. For me it takes ~30ms to set all 50 keys in the ExpandoObject, whereas the SuperExpando takes a minimum of ~750ms.

using System;
using System.Collections.Generic;
using System.ComponentModel;
using System.Data;
using System.Drawing;
using System.Linq;
using System.Text;
using System.Windows.Forms;
using System.Dynamic;

namespace test
{
    public partial class ExpandoTest : Form
    {
        public ExpandoTest()
        {
            InitializeComponent();
        }

        public class SuperExpando : DynamicObject
        {
            public Dictionary<string, object> dictionary = new Dictionary<string, object>();

            public override bool TrySetMember(SetMemberBinder binder, object value)
            {
                //dictionary[binder.Name] = value;
                return true;
            }
        }

        DateTime lasttime = DateTime.Now;

        public void outputtime(string label = "")
        {
            TimeSpan elapsedtime = DateTime.Now - lasttime;
            Double elapsedms = elapsedtime.TotalMilliseconds;
            Console.WriteLine(label + " : " + elapsedms.ToString());
            lasttime = DateTime.Now;
        }

        private void go_Click(object sender, EventArgs e)
        {
            outputtime("Time spent waiting on user");
            dynamic se = new SuperExpando();
            outputtime("Declared SuperExpando");
            se.test120 = 5;
            se.test121 = 5;
            se.test122 = 5;
            se.test123 = 5;
            se.test124 = 5;
            se.test125 = 5;
            se.test126 = 5;
            se.test127 = 5;
            se.test128 = 5;
            se.test129 = 5;
            se.test130 = 5;
            se.test131 = 5;
            se.test132 = 5;
            se.test133 = 5;
            se.test134 = 5;
            se.test135 = 5;
            se.test136 = 5;
            se.test137 = 5;
            se.test138 = 5;
            se.test139 = 5;
            se.test140 = 5;
            se.test141 = 5;
            se.test142 = 5;
            se.test143 = 5;
            se.test144 = 5;
            se.test145 = 5;
            se.test146 = 5;
            se.test147 = 5;
            se.test148 = 5;
            se.test149 = 5;
            se.test150 = 5;
            se.test151 = 5;
            se.test152 = 5;
            se.test153 = 5;
            se.test154 = 5;
            se.test155 = 5;
            se.test156 = 5;
            se.test157 = 5;
            se.test158 = 5;
            se.test159 = 5;
            se.test160 = 5;
            se.test161 = 5;
            se.test162 = 5;
            se.test163 = 5;
            se.test164 = 5;
            se.test165 = 5;
            se.test166 = 5;
            se.test167 = 5;
            se.test168 = 5;
            se.test169 = 5;
            outputtime("Time to Run SuperExpando, set 50 test key/value pairs -- (not even setting values, just returning true from TrySetMember!)");

            dynamic eo = new ExpandoObject();
            outputtime("Declared ExpandoObject");
            eo.test120 = 5;
            eo.test121 = 5;
            eo.test122 = 5;
            eo.test123 = 5;
            eo.test124 = 5;
            eo.test125 = 5;
            eo.test126 = 5;
            eo.test127 = 5;
            eo.test128 = 5;
            eo.test129 = 5;
            eo.test130 = 5;
            eo.test131 = 5;
            eo.test132 = 5;
            eo.test133 = 5;
            eo.test134 = 5;
            eo.test135 = 5;
            eo.test136 = 5;
            eo.test137 = 5;
            eo.test138 = 5;
            eo.test139 = 5;
            eo.test140 = 5;
            eo.test141 = 5;
            eo.test142 = 5;
            eo.test143 = 5;
            eo.test144 = 5;
            eo.test145 = 5;
            eo.test146 = 5;
            eo.test147 = 5;
            eo.test148 = 5;
            eo.test149 = 5;
            eo.test150 = 5;
            eo.test151 = 5;
            eo.test152 = 5;
            eo.test153 = 5;
            eo.test154 = 5;
            eo.test155 = 5;
            eo.test156 = 5;
            eo.test157 = 5;
            eo.test158 = 5;
            eo.test159 = 5;
            eo.test160 = 5;
            eo.test161 = 5;
            eo.test162 = 5;
            eo.test163 = 5;
            eo.test164 = 5;
            eo.test165 = 5;
            eo.test166 = 5;
            eo.test167 = 5;
            eo.test168 = 5;
            eo.test169 = 5;
            outputtime("Time to Run ExpandoObject, set 50 test key/value pairs");
        }
    }
}
Papillote answered 2/3, 2012 at 22:48 Comment(8)
Really? 30ms for this? This is extremely slow. Are you sure it doesn't have anything to do with the way you manipulate the object? How do you use your SuperExpando in code?Schistosomiasis
Yeah, it's painfully slow. Not enough to notice if you're only doing one or two but if you do dozens/hundreds/thousands then it gets pretty painful. I'm really not doing much of anything other than the code shown above. I declare the instance of the SuperExpando just as described above (public dynamic m = new SuperExpando();) and I reproduce the problem by just doing lots of "m.var1 = 500;" copy and pasted one line after the other.Papillote
Have you profiled your code in a Release Build? I've seen some painfuly slow Debug code perform adequately on Release mode. Good Luck!Loring
Tried it, but it really isn't any faster (a couple percent faster). Thanks for the suggestion though.Papillote
Added sample code. Right now the line that actually updates the value in the dictionary is commented out and I'm still experiencing the same performance issues. It appears to be the very fact that TrySetMember is getting called?Papillote
ExpandoObject doesn't inherit from DynamicObject directly so you aren't comparing apples to apples. Try having SuperExpando implement IDynamicMetaObjectProvider instead if you want a true test. Even though this is true, you're writing a UI application... what difference does a few ms make?Episcopalian
Did you try running the release EXE without attaching to Visual Studio (CTRL-F5 instead of F5)? It can have a massive effect on performance.Schistosomiasis
@M.Babcock, the difference is if there's dozens of dynamic variables set (or more) 30ms a pop really starts to add up and be noticeable.Papillote
M
9

First, you shouldn't measure time like this. DateTime.Now is not precise down to milliseconds. You should use Stopwatch for this.

Second, in .Net in general, and when dealing with dynamic especially, order matters. That's because there are several things the CLR and DLR have to compute the first time around, but can retrieve from cache the second time around.

Third, in my testing, I certainly did not see 750 ms, or anything close to that.

If I run SuperExpando first, and do both tests twice, I get times like this:

SuperExpando: 50,7736 ms
EpandoObject: 27,786 ms
SuperExpando: 0,0285 ms
EpandoObject: 0,0373 ms

So, SuperExpando is slower and the difference can be significant, but it's only the first time. When you run the same code with the same type again, it's much faster.

What happens when we reverse the order?

EpandoObject: 33,3107 ms
SuperExpando: 43,7383 ms
EpandoObject: 0,0348 ms
SuperExpando: 0,0186 ms

SuperExpando is still slower, but the difference is now smaller. And again, the second run for both is faster by several orders of magnitude.

Merely answered 4/3, 2012 at 0:33 Comment(4)
Thx, using StopWatch now. However, regardless of the order I run in, I'm still seeing 750ms+. Another interesting thing is that if I increase the number of calls to TrySetMember (by adding more lines like "se.test120 = 5"), the amount of time required goes up linearly, even if I just copy and paste the 50 calls I was already doing (therefore making two calls to TrySetMember for each key). Also, the second time I press the button to run the code again, the time goes down to almost zero. This is helpful, but if first run time is still linear and this slow, that's still a major issue.Papillote
Oh and another thing -- if I ensure that the code that runs the first time isn't exactly the same as the code that's run the second time (set a counter and copy and paste the same code multiple times and have the counter increment and run different copies of the same code each time), then I get the slow, "first run" times each time there's something different about the code that runs. This is still only a problem with my "SuperExpando" and TrySetMember. ExpandoObject behaves well in all scenarios.Papillote
After more testing, I determined that my issue is a combination of things. First of all, as suggested by sgorozco, the debug build is very slow. Doing Ctrl+F5 detaches the debugger and runs much faster. Also, as svick suggested, first time runs are slower, it gets faster after that, but first time vs second time run speed isn't as noticeable when the debugger isn't attached. This is annoying during development, but isn't as much of an issue in release mode. My REAL problem in release mode was something completely different, but this issue in debug mode distracted me from the real problem.Papillote
So what was the real problem in release mode, so others can avoid the same issue(s)?Microgroove

© 2022 - 2024 — McMap. All rights reserved.