Running unit tests with a large arrangement step with Moles is slow

Question

I have been using moles for a bit now, and found it very useful for smaller projects.

However when dealing with unit tests that require more extensive arrangement tasks, unit tests take FOREVER.

If I run the unit test code without assigning the HostType("Moles") attribute, the arrangement operation takes < 10 seconds (when running the intended context its a <2 second op). Adding the Moles host attribute extends this time to about 4-5 minutes.

What is going on, and what can I do about it?

----Update in regard to BryanBCook's answer.

The following is the code (a bit redacted) that seems to be the problem. If the problem is moles IL rewriting, it seems to be happening in a place I wouldn't expect that it should. Do you know if it rewrites everything? I guess I'm also curious to know if its just a problem with scaling in the moles host process.

[ClassInitialize()]
public static void ClassInit(TestContext ctx)
{

    Common.Logging.Moles.MExceptionEvent.LogExceptionStringStringStringString = delegate(Exception ex, string a, string b, string c, string d)
    {
        Debug.WriteLine(String.Format("Exception occurred in test context '{0}' : {1} ", ctx.TestName, ex.ToString()));
    };

    Common.Logging.Moles.MCriticalEvent.LogStringStringTraceEventTypeStringString = delegate(string a, string b, TraceEventType tet, string c, string d)
    {
        Debug.WriteLine(String.Format("Critical Event occurred in test context '{0}' : {1} ", ctx.TestName, a));
    };

    Common.Logging.Moles.MDebugEvent.LogStringStringTraceEventTypeStringString = delegate(string a, string b, TraceEventType tet, string c, string d)
    {
        //Debug.WriteLine(String.Format("Debug Event occurred in test context '{0}' : {1} ", ctx.TestName, a));
    };

/*there are about 1MM lines of code that generate this dataset.*/
    DataSet _ds = dg.STDDataHelper.GenerateDataSet(); 

/*This is where the delay occurs*/
    m_std = new STD(_ds);

/*Now another object (implements web caching) gets moled to use the newly constructed object*/
    BizObjects.Moles.MSCO.STDs = delegate()
    {
        return m_std;

    };


    m_co1 = new Company(dg.Company.CTSDataHelper.COMPANY_ONE_CODE);
    m_co1.HydrateCoTaxDefinitions(dg.Company.CTSDataHelper.GenerateCompanyOneDataset());
    m_co2 = new Company(dg.Company.CTSDataHelper.COMPANY_ONE_CODE);
    m_co2.HydrateCoTaxDefinitions(dg.Company.CTSDataHelper.GenerateCompanyTwoDataset());

}

---Another update

So rearranging the class init so that the logging moles happen after the STD gets initialized and removing the 3 debug logging statements (they were truly useless) in that entire STD object construction tree has reduced the arrangement operations to about a minute and a half.

While this is not optimal (exceptions in the STD object tree construction will fail the test instead of the actual thing being tested), its still better than paying this penalty. Especially since the construction input is tightly controlled.

That being said, I also noticed that the moles host process only uses about 138MB of ram and 13% of processor. Without moles (and adding all the dependencies to the unit test), the standard host will use much more than that (this comp has an i7 Quad and 8GB ram - there is plenty of room to spare). It seems like the moles host process is hitting some kind of limit.

Answer 1

The reason Moles runs slow is because it's using the ProfilerAPI to intercept the IL and rewrite it. You'd see similar slow down if you run tests with code coverage enabled or when using the TestImpact feature of Visual Studio 2010. on average tests take 4-5x longer.

4-10 minutes seems extreme, though. My guess is the difference between running tests with code coverage and Moles is that for code coverage, instrumentation and set up for the tests happens once, and this is where the bulk of the delay occurs. For Moles, it's possible that the setup cost to initialize the ProfilerAPI is fixed and happens for each test.