Added aggressive inlining. Remove one GetTimestamp() from on-thread p…

…rocessing.
BattletechModders · Jan 5, 2025 · 4d43fcb · 4d43fcb
1 parent 46e3f47
commit 4d43fcb
Show file tree

Hide file tree

Showing 4 changed files with 16 additions and 10 deletions.
diff --git a/ModTek/Features/Logging/LoggingFeature.cs b/ModTek/Features/Logging/LoggingFeature.cs
@@ -2,10 +2,10 @@
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.IO;
+using System.Runtime.CompilerServices;
 using System.Threading;
 using HBS.Logging;
 using ModTek.Misc;
-using UnityEngine;
 
 namespace ModTek.Features.Logging;
 
@@ -139,9 +139,8 @@ internal static void LogAtLevel(string loggerName, LogLevel logLevel, object mes
             }
         }
 
-        var measurement = DispatchStopWatch.StartMeasurement();
+        var timestampDispatch = Stopwatch.GetTimestamp();
         ref var updateDto = ref _queue.AcquireUncommitedOrWait();
-        measurement.Stop();
 
         updateDto.Timestamp = timestamp;
         updateDto.LoggerName = loggerName;
@@ -152,7 +151,9 @@ internal static void LogAtLevel(string loggerName, LogLevel logLevel, object mes
         updateDto.ThreadId = threadId;
         updateDto.Commit();
 
-        MessageSetupStopWatch.AddMeasurement(Stopwatch.GetTimestamp() - timestamp);
+        var timestampEnd = Stopwatch.GetTimestamp();
+        DispatchStopWatch.AddMeasurement(timestampEnd - timestampDispatch);
+        MessageSetupStopWatch.AddMeasurement(timestampDispatch - timestamp);
     }
 
     internal static void Flush()
@@ -182,6 +183,7 @@ internal static void Flush()
         flushEvent.Wait();
     }
 
+    [MethodImpl(MethodImplOptions.AggressiveInlining)]
     private static bool IsDispatchAvailable(out int currentThreadId)
     {
         // capture caller thread

diff --git a/ModTek/Features/Logging/MTLoggerAsyncQueue.cs b/ModTek/Features/Logging/MTLoggerAsyncQueue.cs
@@ -34,17 +34,21 @@ internal MTLoggerAsyncQueue()
                 return;
             }
 
-            var dispatchStats = LoggingFeature.DispatchStopWatch.GetStats(); // fetch the overhead introduced by async logging
-            var offloadedTime = stats.TotalTime.Subtract(dispatchStats.TotalTime);
+            var dispatchStats = LoggingFeature.DispatchStopWatch.GetStats();
+            var messagePrepareStats = LoggingFeature.MessageSetupStopWatch.GetStats();
+            var onThreadTotal = dispatchStats.TotalTime + messagePrepareStats.TotalTime;
+            var onThreadAverage = dispatchStats.AverageNanoseconds + messagePrepareStats.AverageNanoseconds;
 
+            // estimated overhead introduced by async logging is subtracted
+            var offloadedTime = stats.TotalTime.Subtract(dispatchStats.TotalTime);
             var latencyStats = MTLoggerMessageDto.LatencyStopWatch.GetStats();
-            var dtoStats = LoggingFeature.MessageSetupStopWatch.GetStats();
 
             logger.Log(
                 $"""
                 Asynchronous logging offloaded {offloadedTime} from the main thread.
                 Async internal processing had an average latency of {latencyStats.AverageNanoseconds / 1_000}us.
-                  On-thread processing took a total of {dtoStats.TotalTime} with an average of {dtoStats.AverageNanoseconds}ns.
+                  On-thread processing took a total of {onThreadTotal} with an average of {onThreadAverage}ns.
+                    Message prepare {messagePrepareStats}.
                     Dispatch {dispatchStats}.
                   Off-thread processing took a total of {stats.TotalTime} with an average of {stats.AverageNanoseconds}ns.
                     Flushed (to disk) {AppenderFile.FlushStopWatch.GetStats()}.

diff --git a/ModTek/Features/Logging/MTLoggerMessageDto.cs b/ModTek/Features/Logging/MTLoggerMessageDto.cs
@@ -1,5 +1,6 @@
 using System;
 using System.Diagnostics;
+using System.Runtime.CompilerServices;
 using System.Threading;
 using HBS.Logging;
 using UnityEngine;
@@ -51,6 +52,7 @@ private TimeSpan GetElapsedSinceInitial()
     }
 
     // allow queue to read it
+    [MethodImpl(MethodImplOptions.AggressiveInlining)]
     internal void Commit()
     {
         this.CommittedToQueue = true;

diff --git a/ModTek/Features/Logging/MTStopwatch.cs b/ModTek/Features/Logging/MTStopwatch.cs
@@ -1,6 +1,5 @@
 using System;
 using System.Diagnostics;
-using System.Runtime.CompilerServices;
 using System.Threading;
 
 namespace ModTek.Features.Logging;
@@ -21,7 +20,6 @@ internal Measurement StartMeasurement()
     internal readonly struct Measurement(MTStopwatch stopwatch)
     {
         private readonly long _begin = Stopwatch.GetTimestamp();
-        [MethodImpl(MethodImplOptions.AggressiveInlining)]
         internal void Stop()
         {
             var elapsed = Stopwatch.GetTimestamp() - _begin;