From a1ab1944332b396125556011b921b52a302b7288 Mon Sep 17 00:00:00 2001 From: YevgeniyShunevych Date: Fri, 13 Oct 2023 17:42:41 +0200 Subject: [PATCH] #782 Add more information to log about AtataContext finish --- src/Atata/Context/AtataContext.cs | 76 ++++++++++++++++++++++-- src/Atata/Context/AtataContextBuilder.cs | 2 +- src/Atata/Logging/Report`1.cs | 54 +++++++++++------ 3 files changed, 108 insertions(+), 24 deletions(-) diff --git a/src/Atata/Context/AtataContext.cs b/src/Atata/Context/AtataContext.cs index dc208912..137432e5 100644 --- a/src/Atata/Context/AtataContext.cs +++ b/src/Atata/Context/AtataContext.cs @@ -350,7 +350,9 @@ internal set internal Stopwatch ExecutionStopwatch { get; } = Stopwatch.StartNew(); - internal Stopwatch PureExecutionStopwatch { get; } = new Stopwatch(); + internal Stopwatch BodyExecutionStopwatch { get; } = new Stopwatch(); + + internal Stopwatch SetupExecutionStopwatch { get; } = new Stopwatch(); internal ScreenshotTaker ScreenshotTaker { get; set; } @@ -921,7 +923,8 @@ private void DisposeTogetherWithDriver(bool disposeDriver) if (_disposed) return; - PureExecutionStopwatch.Stop(); + BodyExecutionStopwatch.Stop(); + Stopwatch deinitializationStopwatch = Stopwatch.StartNew(); Log.ExecuteSection( new LogSection("Deinitialize AtataContext", LogLevel.Trace), @@ -948,11 +951,10 @@ private void DisposeTogetherWithDriver(bool disposeDriver) EventBus.Publish(new AtataContextDeInitCompletedEvent(this)); }); + deinitializationStopwatch.Stop(); ExecutionStopwatch.Stop(); - string testUnitKindName = GetTestUnitKindName(); - Log.InfoWithExecutionTimeInBrackets($"Finished {testUnitKindName}", ExecutionStopwatch.Elapsed); - Log.InfoWithExecutionTime($"Pure {testUnitKindName} execution time:", PureExecutionStopwatch.Elapsed); + LogTestFinish(deinitializationStopwatch.Elapsed); Log = null; @@ -971,4 +973,68 @@ private void DisposeTogetherWithDriver(bool disposeDriver) throw VerificationUtils.CreateAggregateAssertionException(copyOfPendingFailureAssertionResults); } } + + private void LogTestFinish(TimeSpan deinitializationTime) + { + string testUnitKindName = GetTestUnitKindName(); + + TimeSpan overallTime = ExecutionStopwatch.Elapsed; + TimeSpan setupTime = SetupExecutionStopwatch.Elapsed; + TimeSpan testBodyTime = BodyExecutionStopwatch.Elapsed; + TimeSpan initializationTime = overallTime - setupTime - testBodyTime - deinitializationTime; + + string totalTimeString = overallTime.ToLongIntervalString(); + string initializationTimeString = initializationTime.ToLongIntervalString(); + string setupTimeString = setupTime.ToLongIntervalString(); + string testBodyTimeString = testBodyTime.ToLongIntervalString(); + string deinitializationTimeString = deinitializationTime.ToLongIntervalString(); + + int maxTimeStringLength = new[] + { + totalTimeString.Length, + initializationTimeString.Length, + setupTimeString.Length, + testBodyTimeString.Length, + deinitializationTimeString.Length + }.Max(); + + double initializationTimePercent = initializationTime.TotalMilliseconds / overallTime.TotalMilliseconds; + double setupTimePercent = setupTime.TotalMilliseconds / overallTime.TotalMilliseconds; + double deinitializationTimePercent = deinitializationTime.TotalMilliseconds / overallTime.TotalMilliseconds; + double testBodyPercent = 1 - initializationTimePercent - setupTimePercent - deinitializationTimePercent; + + const string percentFormat = "P1"; + CultureInfo percentCulture = CultureInfo.InvariantCulture; + string initializationTimePercentString = initializationTimePercent.ToString(percentFormat, percentCulture); + string setupTimePercentString = setupTimePercent.ToString(percentFormat, percentCulture); + string deinitializationTimePercentString = deinitializationTimePercent.ToString(percentFormat, percentCulture); + string testBodyPercentString = testBodyPercent.ToString(percentFormat, percentCulture); + + int maxPercentStringLength = new[] + { + initializationTimePercentString.Length, + setupTimePercentString.Length, + deinitializationTimePercentString.Length, + testBodyPercentString.Length + }.Max(); + + var messageBuilder = new StringBuilder( + $""" + Finished {testUnitKindName} + Total time: {totalTimeString.PadLeft(maxTimeStringLength)} + Initialization: {initializationTimeString.PadLeft(maxTimeStringLength)} | {initializationTimePercentString.PadLeft(maxPercentStringLength)} + """); + + if (setupTime > TimeSpan.Zero) + messageBuilder.AppendLine().Append( + $"Setup: {setupTimeString.PadLeft(maxTimeStringLength)} | {setupTimePercentString.PadLeft(maxPercentStringLength)}"); + + messageBuilder.AppendLine().Append( + $""" + {$"{testUnitKindName.ToUpperFirstLetter()} body:",-17} {testBodyTimeString.PadLeft(maxTimeStringLength)} | {testBodyPercentString.PadLeft(maxPercentStringLength)} + Deinitialization: {deinitializationTimeString.PadLeft(maxTimeStringLength)} | {deinitializationTimePercentString.PadLeft(maxPercentStringLength)} + """); + + Log.Info(messageBuilder.ToString()); + } } diff --git a/src/Atata/Context/AtataContextBuilder.cs b/src/Atata/Context/AtataContextBuilder.cs index 0b4fa0a8..ef790a1e 100644 --- a/src/Atata/Context/AtataContextBuilder.cs +++ b/src/Atata/Context/AtataContextBuilder.cs @@ -1119,7 +1119,7 @@ public AtataContext Build() new LogSection("Initialize AtataContext", LogLevel.Trace), () => InitializeContext(context)); - context.PureExecutionStopwatch.Start(); + context.BodyExecutionStopwatch.Start(); return context; } diff --git a/src/Atata/Logging/Report`1.cs b/src/Atata/Logging/Report`1.cs index c5db7576..d35b7839 100644 --- a/src/Atata/Logging/Report`1.cs +++ b/src/Atata/Logging/Report`1.cs @@ -201,7 +201,7 @@ public TOwner EndSection() /// /// Executes the specified action and represents it in a log as a setup section with the specified message. - /// The setup action time is not counted as pure test execution time. + /// The setup action time is not counted as a "Test body" execution time, but counted as "Setup" time. /// /// The setup message. /// The setup action. @@ -213,21 +213,30 @@ public TOwner Setup(string message, Action action) _context.Log.ExecuteSection(message, () => { - bool shouldStopPureExecutionStopwatch = _context.PureExecutionStopwatch.IsRunning; - if (shouldStopPureExecutionStopwatch) - _context.PureExecutionStopwatch.Stop(); - - action.Invoke(_owner); - - if (shouldStopPureExecutionStopwatch) - _context.PureExecutionStopwatch.Start(); + bool shouldStopBodyExecutionStopwatch = _context.BodyExecutionStopwatch.IsRunning; + if (shouldStopBodyExecutionStopwatch) + _context.BodyExecutionStopwatch.Stop(); + + _context.SetupExecutionStopwatch.Start(); + + try + { + action.Invoke(_owner); + } + finally + { + _context.SetupExecutionStopwatch.Stop(); + + if (shouldStopBodyExecutionStopwatch) + _context.BodyExecutionStopwatch.Start(); + } }); return _owner; } /// /// Executes the specified function and represents it in a log as a setup section with the specified message. - /// The setup function time is not counted as pure test execution time. + /// The setup function time is not counted as a "Test body" execution time, but counted as "Setup" time. /// /// The type of the result. /// The setup message. @@ -242,14 +251,23 @@ public TResult Setup(string message, Func function) _context.Log.ExecuteSection(message, () => { - bool shouldStopPureExecutionStopwatch = _context.PureExecutionStopwatch.IsRunning; - if (shouldStopPureExecutionStopwatch) - _context.PureExecutionStopwatch.Stop(); - - result = function.Invoke(_owner); - - if (shouldStopPureExecutionStopwatch) - _context.PureExecutionStopwatch.Start(); + bool shouldStopBodyExecutionStopwatch = _context.BodyExecutionStopwatch.IsRunning; + if (shouldStopBodyExecutionStopwatch) + _context.BodyExecutionStopwatch.Stop(); + + _context.SetupExecutionStopwatch.Start(); + + try + { + result = function.Invoke(_owner); + } + finally + { + _context.SetupExecutionStopwatch.Stop(); + + if (shouldStopBodyExecutionStopwatch) + _context.BodyExecutionStopwatch.Start(); + } }); return result;