How can I precisely time a test run in visual stud

Question

I have a suite of unit tests for my project which I run using the visual studio test runner. I want to know how long the test run takes when it runs. The test run details screen shows me the start and end times of the run, but only to the nearest second. My test suite at the moment is taking less than a second to complete, so I can't tell if my suite of 50 tests is taking < 0.1 second (good!) or up to 1 second (bad!).

Is there any way to enable this level of precision?

Answer 1

You could always run the unit tests more times and then divide the total time by the times you ran them. This would essentially be an average though, so if you are looking for low or high spots then this is not the best thing to do.

Answer 2

In your root solution directory, there is a folder called Test Results following the test runs. If you look in there, each run spits out a .TRX file with timestamp of the test run as part of its name. Open this file, and you'll see that it's an XML file with a bunch of hard-to-read information about the test run. If you look for the XML nodes "UnitTestResult", each will have an attribute called "duration". This will tell you how long each individual test took to run (assuming the test was run).

I have a good bit of experience with this as I wrote an open source utility that takes these TRX files, parses them, and generates an HTML report of the results. One of the things that it shows you is test time duration, for individual tests, test classes in aggregate, and the test run as a whole.

Lest this come off as a plug for my tool, I won't post the link unless someone is curious. But, suffice it to say, you can get the test's execution time from the TRX file without debug trace or the console or editing your test code.

Edit: And the precision is ridiculously high. Example entry is 00:00:00.0015890 for a single unit test.

Answer 3

Have all test classes inherit from a base test class that does the measurement.

In the general case you need to pipe the output message to something more useful (like a logger).

[TestClass]
public abstract class TestClassBase2
{
    protected TestContext testContextInstance;

    public TestContext TestContext
    {
        get { return testContextInstance; }
        set { testContextInstance = value; }
    }

    protected System.Diagnostics.Stopwatch _stopWatch;

    [TestInitialize]
    public void TestInitializeBase()
    {
        _stopWatch = System.Diagnostics.Stopwatch.StartNew();
    }


    [TestCleanup]
    public void TestCleanupBase()
    {
        System.Diagnostics.Debug.WriteLine("Done - Total Test time: {0} ms - {1}",
                                            _stopWatch.ElapsedMilliseconds, TestContext.TestName);
    }
}

[TestClass]
public class TempTests : TestClassBase2
{
    [TestMethod]
    public void TempTest()
    {
        // outputs: 
        // Done - Total Test time: 3 ms - TempTest
    }
}