DynamicObject extremely slow when debugger is attached

Feb 9, 2011 at 1:41 PM
Edited Feb 9, 2011 at 6:41 PM

Hello.

I'm using DynamicObject as a very simple "factory" of uniquely named objects: small objects are created and returned when I get a unknown member for the first time and successive "get" return the same objects. A dictionary is used internally. This results in code that is normally enough fast that I can ignore its presence (and so does the profiler).

When I run the same application with the debugger attached the same code runs 1000x slower: the application freezes for 10seconds.

If I build the application in debug mode but I make it run without the debugger attached, DynamicObject is fast as usual.

Intellitrace is disabled. I also played with several debugger settings without significant changes.

Can anybody help me to fix this problem?

Thanks.

Feb 9, 2011 at 5:45 PM

By running the app with the debugger attached, do you mean you just hit F5 in VS? Is VS loading any symbol files that you don't have locally cached (you can disable symbol loading in Tools/Options/Debugging/Symbols)? Do you have any conditional breakpoints set?

Can you share a code snippet that demonstrates the problem?

Feb 9, 2011 at 7:26 PM
Edited Feb 9, 2011 at 7:32 PM

 

Run with debug attached: press F5 or click on the green "play" button.
That is the apparent source of slow down.
I can run the debug build without debugger attached (Control-F5) without problems. I can run the same code with the profiler and I have no problems

No, symbol server are disabled.
No conditional breakpoints. One of the first things that I did was clearing all breakpoints, actually.

This code that is really close to whay my application does. It shows a noticeable slowdown (when I run it with the debugger attached) but nothing close to my real application.

 

 

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Dynamic;

namespace VariableFactoryTest {
    public static class Test {
        public static void Main() {
            var stopwatch = new Stopwatch();

            stopwatch.Start();
            Do();
            stopwatch.Stop();

            var time = stopwatch.ElapsedMilliseconds;
            // this takes less than 1 sec on my computer

            var definitionCount = VariableFactory.DefinitionCount;
            var lookupCount = VariableFactory.LookupCount;
        }

        public static void Do() {

            for (int i = 0; i < 10000; i++) {
                dynamic v = new VariableFactory();

                var x = v.Define().A1.A2.A3.A4.A5.A6.A7.A8.A9.A10;

                for (int j = 0; j < 10; j++) {
                    var a1 = v.A1;
                    var a2 = v.A2;
                    var a3 = v.A3;
                    var a4 = v.A4;
                    var a5 = v.A5;
                    var a6 = v.A6;
                    var a7 = v.A7;
                    var a8 = v.A8;
                    var a9 = v.A9;
                    var a10 = v.A10;
                }
            }
        }
    }

    public interface IVariable {       
    }
    public class Variable : IVariable {
        [DebuggerBrowsable(DebuggerBrowsableState.Never)]
        readonly string m_Name;
        public string Name { get { return m_Name; } }
        public Variable(string name) { m_Name = name; }
    }
    public class Variable<T> : Variable {
        public Variable(string name) : base(name) { }
    }
    public class AnyVariable : Variable {
        public AnyVariable() : base(null) { }
    }
    public class AnyVariable<T> : Variable<T> {
        public AnyVariable() : base(null) { }
    }

    public class VariableFactory : DynamicObject {
        readonly Dictionary<string, IVariable> m_Cache = new Dictionary<string, IVariable>();
        public Dictionary<string, IVariable> Cache { get { return m_Cache; } }

        public static int LookupCount { get; set; }
        public static int DefinitionCount { get; set; }

        public override bool TryGetMember(GetMemberBinder binder, out object result) {
            var name = binder.Name;

            LookupCount += 1;

            IVariable variable;
            if (Cache.TryGetValue(name, out variable)) {
                result = variable;
                return true;
            }
            result = null;
            return false;
        }

        public VariableDeclarator<T> Define<T>() {
            return new VariableDeclarator<T>(this);
        }
        public VariableDeclarator Define() {
            return new VariableDeclarator(this);
        }

        public AnyVariable<T> Any<T>() { return new AnyVariable<T>(); }
        public AnyVariable Any() { return new AnyVariable(); }
    }
    public abstract class VariableDeclaratorBase : DynamicObject {
        readonly VariableFactory m_Parent;
        VariableFactory Parent { get { return m_Parent; } }

        public Dictionary<string, IVariable> Cache { get { return Parent.Cache; } }

        protected VariableDeclaratorBase(VariableFactory parent) {
            m_Parent = parent;
        }

        public override bool TryGetMember(GetMemberBinder binder, out object result) {
            var name = binder.Name;

            IVariable variable;
            if (Parent.Cache.TryGetValue(name, out variable)) {
                throw new NotImplementedException();
            }
            variable = MakeVariable(name);

            VariableFactory.DefinitionCount += 1;

            Cache[name] = variable;

            result = this;
            return true;
        }
        protected abstract IVariable MakeVariable(string name);

        public VariableDeclarator<T> And<T>() {
            return new VariableDeclarator<T>(Parent);
        }
        public VariableDeclarator And() {
            return new VariableDeclarator(Parent);
        }
    }
    public class VariableDeclarator<T> : VariableDeclaratorBase {
        public VariableDeclarator(VariableFactory parent)
            : base(parent) {
        }

        protected override IVariable MakeVariable(string name) {
            return new Variable<T>(name);
        }

    }
    public class VariableDeclarator : VariableDeclaratorBase {
        public VariableDeclarator(VariableFactory parent)
            : base(parent) {
        }
        protected override IVariable MakeVariable(string name) {
            return new Variable(name);
        }
    }
}

 

The DynamicObject is the same. The "variable" objects that are created are basically the same. The ctor is the same (just a field assignment).

I don't know the "normal" performance of DLR but I would find acceptable to work in debug mode with this speed.

Unfortunately my real application is ridiculously slow. This method, called with an instance of the factory as argument v, takes more than four seconds to execute.

 

        protected override IEnumerable<IClause> ProvideDefinitions(dynamic v) {
            return v.Define().L.C.H.T.R.AndClauses(
                Self(List.Empty, v.L, v.L),
                R(
                    Self(List.Pattern(v.T, v.H), v.L, List.Pattern(v.R, v.H)),
                        Self(v.T, v.L, v.R)
                )
            );
        }

 

All you see here are calls to v and calls to ctors that do nothing more than initializing some fields.

I have several of these methods that are called once and then cached (they represent "declarations", actually). They are called mostly at startup and currently they take about 1 minute.

 

Feb 20, 2011 at 3:26 AM

I've tried the sample source code you provided, and I'm not seeing the same slowdown under the debuggger.   I set a breakpoint at the end of the program, and the time variable is 819 mS.

Could you perhaps a conditional breakpoints set?   Try Debug/Disable all breakpoints.

Feb 20, 2011 at 11:54 PM
Edited Feb 21, 2011 at 12:00 AM

BurtHarris, thanks for checking it on your computer and reporting the timing.

The test you ran created 100.000 dynamic object members and accessed them 1 million times. My actual code created few hundred of members and accessed each them 2-3 times in average but its execution required several minutes to complete. 

Unfortunately I could not understand the cause of the slowdown and since I didn't want to wait few minutes for the application to start up I eliminated all usages of DynamicObject.

I'm sure I had no conditional breakpoints enabled because I use them very rarely and because I cleared all breakpoints as first countermeasure against the slowdown.

I hope I'll be more lucky with DLR next time I'll try to use it! :)