Halving SQL Prompt’s unit test time using TeamCity test statistics

On the SQL Prompt team we use unit tests to provide stable releases to our customers.

The problem with automated tests is that they take time to run. Ideally we could test a release instantly but in reality we run 6405 tests in 1 minute. We use NCrunch to run tests immediately during development. I began hearing that team members had turned off NCrunch because it was slowing down their development work.

We use TeamCity to build SQL Prompt whenever we push to Github. TeamCity shows you information about test duration on the build results page, under the Tests tab. We took a quick look and here is what we found:

When ordered slowest first, the majority of the slow tests on the first page were from the same test fixture HighlightMatchingObjectCalculatorTests. Browsing a few pages further we found more of the same:

The same test fixture HighlightMatchingObjectCalculatorTests spanned the first 5 pages. With 20 tests per page that meant we had about 100 test cases, each taking just over 400 ms. After doing the maths, we estimated that 40 seconds were taken up with these tests. We couldn’t resist trying to speed up all the tests in that test fixture with a single fix.

None of us had worked on that area of the codebase before so we opened up the slow test fixture to try to understand it:

class HighlightMatchingObjectsCalculatorTests
{
    [TestCase("SELECT {alias}.Col1 FROM TestTable {a^lias}")]
    ... 80+ more similar test cases ...
    public void MatchingObjectsShouldBeHighlighted(string script)
    {
        AssertObjectsAreHighlighted(script);
    }

    private void AssertObjectsAreHighlighted(string script, ISqlParser parser)
    {
        ...
        var calculator = new HighlightMatchingObjectsCalculator();

        var matchingObjects = calculator.CalculateMatchingObjectRanges(offset, parser, CancellationToken.None);

        var rangeHelper = new TextRangeTestHelper(script);
        rangeHelper.AssertRangesMatch(matchingObjects);
    }
}

There were 80+ test cases in the test fixture. All of them went through the same test method AssertObjectsAreHighlighted which tested the method CalculateMatchingObjectRanges on HighlightMatchingObjectsCalculator.

What was this method doing to take so much time?

internal List<Range> CalculateMatchingObjectRanges(...)
{
    cancellationToken.WaitHandle.WaitOne(TimeSpan.FromMilliseconds(c_DelayMilliseconds));

    ...

    return GetMatchingObjectRanges(terminalNodes, offset);
}

This code was very suspicious. We were causing the thread to sleep for c_delayMilliseconds via WaitOne on the cancellationToken.WaitHandle. How large is c_delayMilliseconds?

internal class HighlightMatchingObjectsCalculator
{
    // Small delay to improve performance and to avoid it feeling like the highlight is "stuck" to the caret
    private int c_DelayMilliseconds = 400;
    ..

It was 400 ms! And there was a comment to explain — to improve the user experience. So we were running 80+ tests that took around 405 ms each and we were sleeping for 400 ms of that. That sounded like something we could speed up.

We had to make the delay customisable so that we could keep the user experience the same. We did this by extracting the delay through the constructor:

internal class HighlightMatchingObjectsCalculator
{
    /// <summary>
    /// Small delay to improve UI experience or empty in unit tests
    /// </summary>
    private readonly TimeSpan m_DelayTimeSpan;
    ..

    public HighlightMatchingObjectsCalculator(TimeSpan delayTimeSpan)
    {
        m_DelayTimeSpan = delayTimeSpan;
        ..
    }

Then we set the delay to zero in tests:

new HighlightMatchingObjectsCalculator(TimeSpan.Zero)

We reran NCrunch and the tests felt faster — it looked positive! We pushed to Github to measure the impact.

What was the impact of the change? We halved the unit test time from 58 seconds to 26 seconds:

That halved the time for NCrunch to complete and also reduced our TeamCity build time from 4.5 minutes to under 4 minutes:

From 9.0.53526 onwards builds were 30 seconds faster

So there it is. If your unit tests take a while to run, have a quick check on TeamCity to see if it is just one test fixture with lots of test cases slowing you down.