Better logging overhead message and calculations.

BattletechModders · Jan 8, 2025 · 5a17e63 · 5a17e63
1 parent a1ee1cc
commit 5a17e63
Show file tree

Hide file tree

Showing 5 changed files with 26 additions and 23 deletions.
diff --git a/ModTek/Features/Logging/AppenderFile.cs b/ModTek/Features/Logging/AppenderFile.cs
@@ -30,7 +30,7 @@ internal AppenderFile(string path, AppenderSettings settings)
             $"""
             ModTek v{GitVersionInformation.InformationalVersion} ({GitVersionInformation.CommitDate}) ; HarmonyX {typeof(Harmony).Assembly.GetName().Version}
             {Environment.OSVersion} ; BattleTech {Application.version} ; Unity {Application.unityVersion} ; CLR {Environment.Version} ; {System.Runtime.InteropServices.RuntimeInformation.FrameworkDescription}"
-            {dateTime.ToLocalTime().ToString("o", CultureInfo.InvariantCulture)} ; Startup {unityStartupTime.ToString(null, CultureInfo.InvariantCulture)} ; Ticks {stopwatchTimestamp}
+            {dateTime.ToLocalTime().ToString("o", CultureInfo.InvariantCulture)} ; Startup {unityStartupTime.ToString(null, CultureInfo.InvariantCulture)} ; Ticks {stopwatchTimestamp} ; Timestamp Overhead {MTStopwatch.OverheadPerTimestampInNanoseconds}ns
             {new string('-', 80)}
 
             """

diff --git a/ModTek/Features/Logging/LoggingFeature.cs b/ModTek/Features/Logging/LoggingFeature.cs
@@ -101,7 +101,7 @@ internal static void AddModLogAppender(string logPath, string loggerName)
         _logsAppenders = logsAppenders;
     }
 
-    internal static readonly MTStopwatchWithSampling DispatchStopWatch = new(1000);
+    internal static readonly MTStopwatchWithSampling DispatchStopWatch = new(1000) { TimestampCountPerMeasurement = 1 };
     // used for intercepting all logging attempts and to log centrally
     internal static void LogAtLevel(string loggerName, LogLevel logLevel, object message, Exception exception, IStackTrace location)
     {

diff --git a/ModTek/Util/Stopwatch/MTStopwatch.cs b/ModTek/Util/Stopwatch/MTStopwatch.cs
@@ -9,8 +9,14 @@ internal class MTStopwatch
     protected long _count;
     protected long _ticks;
 
-    internal static readonly double GetTimestampOverheadInMeasurement; // 22.47ns
-    internal static readonly double GetTimestampOverheadInAndAfterMeasurement; // 23.216ns
+    internal double _overheadInMeasurement = s_timestampOverheadInMeasurement;
+
+    internal byte TimestampCountPerMeasurement { get; init; } = 2;
+    protected double OverheadPerMeasurement => s_timestampOverheadInAndAfterMeasurement * TimestampCountPerMeasurement;
+    internal static double OverheadPerTimestampInNanoseconds => s_timestampOverheadInAndAfterMeasurement * TicksToNsMultiplier;
+
+    protected static readonly double s_timestampOverheadInMeasurement; // 22.47ns
+    private static readonly double s_timestampOverheadInAndAfterMeasurement; // 23.216ns
     static MTStopwatch()
     {
         const int Count = 100_000;
@@ -31,8 +37,8 @@ static MTStopwatch()
                 seSum += end - start;
             }
         }
-        GetTimestampOverheadInMeasurement = smSum / ActualCount;
-        GetTimestampOverheadInAndAfterMeasurement = ( seSum - smSum ) / ActualCount;
+        s_timestampOverheadInMeasurement = smSum / ActualCount;
+        s_timestampOverheadInAndAfterMeasurement = ( seSum - smSum ) / ActualCount;
     }
 
     [MethodImpl(MethodImplOptions.AggressiveInlining)]

diff --git a/ModTek/Util/Stopwatch/MTStopwatchStats.cs b/ModTek/Util/Stopwatch/MTStopwatchStats.cs
@@ -4,37 +4,30 @@ namespace ModTek.Util.Stopwatch;
 
 internal readonly struct MTStopwatchStats
 {
-    private readonly long _samplingInterval;
+    private readonly MTStopwatch _sw;
     internal readonly long Count;
     internal readonly long Ticks;
     internal TimeSpan TotalTime => MTStopwatch.TimeSpanFromTicks(Ticks);
     internal long AverageNanoseconds => Count <= 0 ? 0 : (long)(MTStopwatch.TicksToNsMultiplier * Ticks / Count);
 
     internal MTStopwatchStats(MTStopwatch sw, long count, long ticks)
     {
+        _sw = sw;
         Count = count;
-        var overheadInMeasurement = MTStopwatch.GetTimestampOverheadInMeasurement;
-        if (sw is MTStopwatchWithSampling sws)
-        {
-            _samplingInterval = sws._samplingInterval;
-            overheadInMeasurement += MTStopwatchWithSampling.SamplingCheckOverhead;
-        }
-        Ticks = ticks - (long)(overheadInMeasurement * count);
+        Ticks = ticks - (long)(sw._overheadInMeasurement * count);
     }
 
     public override string ToString()
     {
         var verb = "measured";
         var suffix = "";
-        if (_samplingInterval > 1)
+        if (_sw is MTStopwatchWithSampling sws)
         {
             verb = "estimated at";
-            var sampled = Count / _samplingInterval;
-            var ifAllMeasured = Count * MTStopwatch.GetTimestampOverheadInAndAfterMeasurement;
-            var onlySampledMeasured = sampled * MTStopwatch.GetTimestampOverheadInAndAfterMeasurement + Count * MTStopwatchWithSampling.SamplingCheckOverhead;
-            var saved = ifAllMeasured - onlySampledMeasured;
-            var savedPercent = (byte)(saved / (Ticks + saved) * 100);
-            suffix = $", sampling interval of {_samplingInterval} saved {savedPercent}%";
+            var overheadWithoutSampling = sws.OverheadPerMeasurementWithoutSampling * Count;
+            var saved = overheadWithoutSampling - sws.OverheadPerMeasurementWithSampling * Count;
+            var savedPercent = (byte)(saved / (Ticks + overheadWithoutSampling) * 100);
+            suffix = $", sampling interval of {sws._samplingInterval} reduced measurement overhead by {savedPercent}%";
         }
         return $"{verb} {Count} times, taking a total of {TotalTime} with an average of {AverageNanoseconds}ns{suffix}";
     }

diff --git a/ModTek/Util/Stopwatch/MTStopwatchWithSampling.cs b/ModTek/Util/Stopwatch/MTStopwatchWithSampling.cs
@@ -10,12 +10,16 @@ internal MTStopwatchWithSampling(uint samplingInterval)
     {
         _samplingInterval = samplingInterval;
         _sampleIfRandomSmallerOrEqualsTo = ulong.MaxValue / samplingInterval;
+        _overheadInMeasurement = _overheadInMeasurement / _samplingInterval + s_samplingCheckOverhead;
     }
     internal readonly uint _samplingInterval;
     private readonly ulong _sampleIfRandomSmallerOrEqualsTo;
     private readonly FastRandom _random = new();
 
-    internal static readonly double SamplingCheckOverhead; // 1.554ns
+    internal double OverheadPerMeasurementWithSampling => OverheadPerMeasurement/_samplingInterval + s_samplingCheckOverhead;
+    internal double OverheadPerMeasurementWithoutSampling => OverheadPerMeasurement;
+
+    private static readonly double s_samplingCheckOverhead; // 1.554ns
     internal static readonly bool DontOptimize;
     static MTStopwatchWithSampling()
     {
@@ -35,7 +39,7 @@ static MTStopwatchWithSampling()
                 sum += end - start;
             }
         }
-        SamplingCheckOverhead = (sum - GetTimestampOverheadInMeasurement * ActualCount) / ActualCount;
+        s_samplingCheckOverhead = (sum - s_timestampOverheadInMeasurement * ActualCount) / ActualCount;
         DontOptimize = dontOptimize;
     }