#782 Add more information to log about AtataContext finish

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());
+    }
 }

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;
     }

src/Atata/Logging/Report`1.cs

@@ -201,7 +201,7 @@ public TOwner EndSection()
 
     /// <summary>
     /// 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.
     /// </summary>
     /// <param name="message">The setup message.</param>
     /// <param name="action">The setup action.</param>
@@ -213,21 +213,30 @@ public TOwner Setup(string message, Action<TOwner> 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;
     }
 
     /// <summary>
     /// 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.
     /// </summary>
     /// <typeparam name="TResult">The type of the result.</typeparam>
     /// <param name="message">The setup message.</param>
@@ -242,14 +251,23 @@ public TResult Setup<TResult>(string message, Func<TOwner, TResult> 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;