CODEWITHSUNDEEP
c#xunit.net
LMB
LMB

Reputation: 1135

How can I log the execution order of tests in xUnit

I have a large test set (5k+) using xUnit.net, and I'm having concurrency problems among tests running in parallel.

xUnit randomizes the execution order of tests, which makes it harder for me to detect the issue.

I'd like to know whether is there a way to log, during test execution, the moment a test starts and the moment it ends.

Note: Using constructor and disposer methods does not cut it, because you cannot know which test is being run on the constructor/disposer.

Note 2: In case it is not obvious, I'm looking for a solution that doesn't involve writing log call in each test.

Thanks,

Upvotes: 4

Views: 1438

Answers (1)

LMB
LMB

Reputation: 1135

Well, I managed to do it using the BeforeAfterTestAttribute from xUnit. Then I wrote the utility logger below to output the results to a .csv file.

public class LogTestExecutionAttribute: BeforeAfterTestAttribute
{
    public override void Before(MethodInfo methodUnderTest)
    {
        TestExecutionDataLogger.LogBegin(methodUnderTest);
    }

    public override void After(MethodInfo methodUnderTest)
    {
        TestExecutionDataLogger.LogEnd(methodUnderTest);
    }
}

public static class TestExecutionDataLogger
{
    private static readonly string LogFileName = Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData), "DbCoud", $"UnitTests_{DateTime.UtcNow:yyyy_MM_dd_HH_mm}_D_{AppDomain.CurrentDomain.Id}.csv");

    private static int _startedOrder = 0;
    private static int _endedOrder = 0;
    private static readonly ConcurrentDictionary<string, testExecutionData> testDataDict = new ConcurrentDictionary<string, testExecutionData>();
    private static readonly ConcurrentQueue<string> logQueue = new ConcurrentQueue<string>();

    public static void LogBegin(MethodInfo testInfo)
    {
        var name = $"{testInfo.DeclaringType.FullName}.{testInfo.Name}";
        var order = Interlocked.Add(ref _startedOrder, 1);
        var startedUtc = DateTime.UtcNow;
        var data = testDataDict.GetOrAdd(name, new testExecutionData());
        data.StartedUtc = startedUtc;
        data.StartedOrder = order;
        data.TestName = name;
        data.Status = "Started";
        data.StartThreadId = Thread.CurrentThread.ManagedThreadId;
        writeLog(data);
    }

    public static void LogEnd(MethodInfo testInfo)
    {
        var name = $"{testInfo.DeclaringType.FullName}.{testInfo.Name}";
        var dataEndedUtc = DateTime.UtcNow;
        var order = Interlocked.Add(ref _endedOrder, 1);
        var data = testDataDict[name];
        data.EndedUtc = dataEndedUtc;
        data.EndedOrder = order;
        data.Status = "Ended";
        data.EndThreadId = Thread.CurrentThread.ManagedThreadId;
        writeLog(data);
    }

    private static void writeLog(testExecutionData data)
    {
        logQueue.Enqueue(data.ToCsvLine());

        if (data.EndedOrder == 1)
        {
            Directory.CreateDirectory(Path.GetDirectoryName(LogFileName));
            Task.Run(logWriter);
        }
    }

    private static Task logWriter()
    {
        while (true)
        {
            var logs = new List<string>();
            string result;
            while (logQueue.TryDequeue(out result))
            {
                logs.Add(result);
            }
            if (logs.Any())
            {
                File.AppendAllLines(LogFileName, logs);
            }
        }
    }

    private class testExecutionData
    {
        public int StartedOrder { get; set; }
        public int EndedOrder { get; set; }
        public DateTime StartedUtc { get; set; }
        public DateTime EndedUtc { get; set; }
        public string TestName { get; set; }
        public string Status { get; set; }
        public int StartThreadId { get; set; }
        public int EndThreadId { get; set; }

        public string ToCsvLine() { return $"{TestName};{Status};{StartedOrder};{EndedOrder};{StartedUtc:o};{EndedUtc:o};{Math.Max(0, ( EndedUtc - StartedUtc ).TotalMilliseconds)};{StartThreadId};{EndThreadId}"; }
    }
}

To use this code, add the LogTestExecutionAttribute to the test classes you want to log (or to the base classes ;p).

Upvotes: 5

Related Questions