diff --git a/test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEngine.cs b/test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEngine.cs index 922dd103ac..e164807cad 100644 --- a/test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEngine.cs +++ b/test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEngine.cs @@ -107,16 +107,39 @@ [.. publicMethod.GetParameters().Select(x => x.ParameterType.FullName!)], progressNode.Properties.Add(InProgressTestNodeStateProperty.CachedInstance); await messageBus.PublishAsync(this, new TestNodeUpdateMessage(request.Session.SessionUid, progressNode)); + DateTimeOffset startTime = DateTimeOffset.UtcNow; bool isSuccessRun = false; + bool isSuccessTeardown = false; + List stepTimings = []; - object? testClassInstance = await TryRunSetupMethodAsync(testContainerType, setupMethod, testNode, PublishNodeUpdateAsync); - if (testClassInstance is not null) + try { - isSuccessRun = await RunTestMethodAsync(testClassInstance, publicMethod, testNode, PublishNodeUpdateAsync); + (object? testClassInstance, StepTimingInfo? setupTiming) = await TryRunSetupMethodAsync(testContainerType, setupMethod, testNode, PublishNodeUpdateAsync); + if (setupTiming is not null) + { + stepTimings.Add(setupTiming); + } + + if (testClassInstance is not null) + { + (isSuccessRun, StepTimingInfo? testTiming) = await RunTestMethodAsync(testClassInstance, publicMethod, testNode, PublishNodeUpdateAsync); + if (testTiming is not null) + { + stepTimings.Add(testTiming); + } + } + + // Always call teardown even if previous steps failed because we want to try to clean as much as we can. + (isSuccessTeardown, StepTimingInfo? teardownTiming) = await RunTestTeardownAsync(testClassInstance, testContainerType, teardownMethod, testNode, PublishNodeUpdateAsync); + if (teardownTiming is not null) + { + stepTimings.Add(teardownTiming); + } + } + finally + { + testNode.Properties.Add(CreateTimingProperty(startTime, stepTimings)); } - - // Always call teardown even if previous steps failed because we want to try to clean as much as we can. - bool isSuccessTeardown = await RunTestTeardownAsync(testClassInstance, testContainerType, teardownMethod, testNode, PublishNodeUpdateAsync); if (isSuccessRun && isSuccessTeardown) { @@ -199,29 +222,37 @@ private static bool IsTestContainer(Type typeInfo) return false; } - private async Task TryRunSetupMethodAsync(TypeInfo testContainerType, ConstructorInfo setupMethod, TestNode testNode, + private async Task<(object? TestClassInstance, StepTimingInfo? SetupTiming)> TryRunSetupMethodAsync(TypeInfo testContainerType, ConstructorInfo setupMethod, TestNode testNode, Func publishNodeUpdateAsync) { + DateTimeOffset stepStartTime = DateTimeOffset.UtcNow; try { _logger.LogDebug($"Executing test '{testNode.DisplayName}' setup (ctor for '{testContainerType.FullName}')"); - return setupMethod.Invoke(null); + object? instance = setupMethod.Invoke(null); + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; + return (instance, new StepTimingInfo("init", "Test initialization", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))); } catch (Exception ex) { Exception realException = ex.InnerException ?? ex; _logger.LogError("Error during test setup", realException); + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; TestNode errorNode = CloneTestNode(testNode); + errorNode.Properties.Add(new TimingProperty( + new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime), + [new StepTimingInfo("init", "Test initialization", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))])); errorNode.Properties.Add(new ErrorTestNodeStateProperty(ex)); errorNode.Properties.Add(new TrxExceptionProperty(ex.Message, ex.StackTrace)); await publishNodeUpdateAsync(errorNode); - return null; + return (null, null); } } - private async Task RunTestMethodAsync(object testClassInstance, MethodInfo publicMethod, TestNode testNode, + private async Task<(bool IsSuccess, StepTimingInfo? TestTiming)> RunTestMethodAsync(object testClassInstance, MethodInfo publicMethod, TestNode testNode, Func publishNodeUpdateAsync) { + DateTimeOffset stepStartTime = DateTimeOffset.UtcNow; try { _logger.LogDebug($"Executing test '{testNode.DisplayName}'"); @@ -230,24 +261,30 @@ private async Task RunTestMethodAsync(object testClassInstance, MethodInfo await task; } - return true; + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; + return (true, new StepTimingInfo("test", "Test method execution", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))); } catch (Exception ex) { Exception realException = ex is TargetInvocationException ? ex.InnerException! : ex; _logger.LogError("Error during test", realException); + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; TestNode errorNode = CloneTestNode(testNode); + errorNode.Properties.Add(new TimingProperty( + new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime), + [new StepTimingInfo("test", "Test method execution", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))])); errorNode.Properties.Add(new ErrorTestNodeStateProperty(realException)); errorNode.Properties.Add(new TrxExceptionProperty(realException.Message, realException.StackTrace)); await publishNodeUpdateAsync(errorNode); - return false; + return (false, null); } } - private async Task RunTestTeardownAsync(object? testClassInstance, TypeInfo testContainerType, MethodInfo teardownMethod, TestNode testNode, + private async Task<(bool IsSuccess, StepTimingInfo? TeardownTiming)> RunTestTeardownAsync(object? testClassInstance, TypeInfo testContainerType, MethodInfo teardownMethod, TestNode testNode, Func publishNodeUpdateAsync) { + DateTimeOffset stepStartTime = DateTimeOffset.UtcNow; try { if (testClassInstance is not null) @@ -256,20 +293,32 @@ private async Task RunTestTeardownAsync(object? testClassInstance, TypeInf teardownMethod.Invoke(testClassInstance, null); } - return true; + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; + return (true, new StepTimingInfo("cleanup", "Test cleanup", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))); } catch (Exception ex) { Exception realException = ex.InnerException ?? ex; _logger.LogError("Error during test teardown", realException); + DateTimeOffset stepEndTime = DateTimeOffset.UtcNow; TestNode errorNode = CloneTestNode(testNode); + errorNode.Properties.Add(new TimingProperty( + new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime), + [new StepTimingInfo("cleanup", "Test cleanup", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))])); errorNode.Properties.Add(new ErrorTestNodeStateProperty(ex)); await publishNodeUpdateAsync(errorNode); - return false; + return (false, null); } } + private static TimingProperty CreateTimingProperty(DateTimeOffset startTime, List stepTimings) + { + DateTimeOffset endTime = DateTimeOffset.UtcNow; + TimeSpan duration = endTime - startTime; + return new TimingProperty(new TimingInfo(startTime, endTime, duration), [.. stepTimings]); + } + private static TestNode CloneTestNode(TestNode testNode) => new() {