Added stopwatch overhead estimation calculations.

BattletechModders · Jan 7, 2025 · 6228b28 · 6228b28
1 parent 9f9c350
commit 6228b28
Show file tree

Hide file tree

Showing 4 changed files with 91 additions and 15 deletions.
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(100);
+    internal static readonly MTStopwatchWithSampling DispatchStopWatch = new(1000);
     // 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,6 +9,32 @@ internal class MTStopwatch
     protected long _count;
     protected long _ticks;
 
+    internal static readonly double GetTimestampOverheadInMeasurement; // 22.47ns
+    internal static readonly double GetTimestampOverheadInAndAfterMeasurement; // 23.216ns
+    static MTStopwatch()
+    {
+        const int Count = 100_000;
+        const int WarmupCount = Count/2;
+        const double ActualCount = Count - WarmupCount;
+        var smSum = 0L;
+        var seSum = 0L;
+        for (var i = 0; i < Count; i++)
+        {
+            var start = GetTimestamp();
+            // no operation in here, so mid-start should contain captured measurement overhead
+            var mid = GetTimestamp();
+            // we still want the actual total overhead too, so lets measure after the mid again
+            var end = GetTimestamp();
+            if (i >= WarmupCount)
+            {
+                smSum += mid - start;
+                seSum += end - start;
+            }
+        }
+        GetTimestampOverheadInMeasurement = smSum / ActualCount;
+        GetTimestampOverheadInAndAfterMeasurement = ( seSum - smSum ) / ActualCount;
+    }
+
     [MethodImpl(MethodImplOptions.AggressiveInlining)]
     internal static long GetTimestamp()
     {
@@ -32,6 +58,9 @@ protected virtual void AddMeasurement(long elapsedTicks, long delta)
 
     internal static TimeSpan TimeSpanFromTicks(long elapsedTicks)
     {
-        return System.Diagnostics.Stopwatch.IsHighResolution ? TimeSpan.FromTicks(elapsedTicks / (System.Diagnostics.Stopwatch.Frequency / 10000000L)) : TimeSpan.FromTicks(elapsedTicks);
+        return System.Diagnostics.Stopwatch.IsHighResolution ? TimeSpan.FromTicks((long)(elapsedTicks * s_stopWatchTicksToTimeSpanTicksMultiplier)) : TimeSpan.FromTicks(elapsedTicks);
     }
+
+    private static readonly double s_stopWatchTicksToTimeSpanTicksMultiplier = 1e+7 / System.Diagnostics.Stopwatch.Frequency;
+    internal static readonly double TicksToNsMultiplier = 1e+9 / System.Diagnostics.Stopwatch.Frequency;
 }
diff --git a/ModTek/Util/Stopwatch/MTStopwatchStats.cs b/ModTek/Util/Stopwatch/MTStopwatchStats.cs
@@ -4,21 +4,38 @@ namespace ModTek.Util.Stopwatch;
 
 internal readonly struct MTStopwatchStats
 {
-    private readonly string _verb;
+    private readonly long _samplingInterval;
     internal readonly long Count;
     internal readonly long Ticks;
     internal TimeSpan TotalTime => MTStopwatch.TimeSpanFromTicks(Ticks);
-    internal long AverageNanoseconds => Count <= 0 ? 0 : (long)((double)Ticks / Count / System.Diagnostics.Stopwatch.Frequency * 1e+9);
+    internal long AverageNanoseconds => Count <= 0 ? 0 : (long)(MTStopwatch.TicksToNsMultiplier * Ticks / Count);
 
     internal MTStopwatchStats(MTStopwatch sw, long count, long ticks)
     {
         Count = count;
-        Ticks = ticks;
-        _verb = sw is MTStopwatchWithSampling ? "estimated at" : "measured";
+        var overheadInMeasurement = MTStopwatch.GetTimestampOverheadInMeasurement;
+        if (sw is MTStopwatchWithSampling sws)
+        {
+            _samplingInterval = sws._samplingInterval;
+            overheadInMeasurement += MTStopwatchWithSampling.SamplingCheckOverhead;
+        }
+        Ticks = ticks - (long)(overheadInMeasurement * count);
     }
 
     public override string ToString()
     {
-        return $"{_verb} {Count} times, taking a total of {TotalTime} with an average of {AverageNanoseconds}ns";
+        var verb = "measured";
+        var suffix = "";
+        if (_samplingInterval > 1)
+        {
+            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 savedTimeSan = MTStopwatch.TimeSpanFromTicks((long)saved);
+            suffix = $", sampling interval of {_samplingInterval} saved {savedTimeSan}";
+        }
+        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
@@ -2,25 +2,55 @@
 
 namespace ModTek.Util.Stopwatch;
 
+// Stopwatch.GetTimestamp takes about 16-30ns, probably due to "extern" overhead
+// fast random is much faster, runs unrolled and therefore in parallel on the CPU
 internal sealed class MTStopwatchWithSampling : MTStopwatch
 {
-    internal MTStopwatchWithSampling(uint sampling)
+    internal MTStopwatchWithSampling(uint samplingInterval)
     {
-        _sampling = sampling;
-        _sampleIfRandomSmallerOrEqualsTo = ulong.MaxValue / sampling;
+        _samplingInterval = samplingInterval;
+        _sampleIfRandomSmallerOrEqualsTo = ulong.MaxValue / samplingInterval;
     }
-    private readonly uint _sampling;
+    internal readonly uint _samplingInterval;
     private readonly ulong _sampleIfRandomSmallerOrEqualsTo;
     private readonly FastRandom _random = new();
 
+    internal static readonly double SamplingCheckOverhead; // 1.554ns
+    internal static readonly bool DontOptimize;
+    static MTStopwatchWithSampling()
+    {
+        var ws = new MTStopwatchWithSampling(100);
+        const int Count = 100_000;
+        const int WarmupCount = Count/2;
+        const double ActualCount = Count - WarmupCount;
+        var sum = 0L;
+        var dontOptimize = false;
+        for (var i = 0; i < Count; i++)
+        {
+            var start = GetTimestamp();
+            dontOptimize = ws.ShouldMeasure();
+            var end = GetTimestamp();
+            if (i >= WarmupCount)
+            {
+                sum += end - start;
+            }
+        }
+        SamplingCheckOverhead = (sum - GetTimestampOverheadInMeasurement * ActualCount) / ActualCount;
+        DontOptimize = dontOptimize;
+    }
+
+    [MethodImpl(MethodImplOptions.AggressiveInlining)]
+    private bool ShouldMeasure()
+    {
+        return _random.NextUInt64() <= _sampleIfRandomSmallerOrEqualsTo;
+    }
+
     [MethodImpl(MethodImplOptions.AggressiveInlining)]
     internal override void EndMeasurement(long start)
     {
-        // Stopwatch.GetTimestamp takes about 16-30ns, probably due to "extern" overhead
-        // fast random is much faster, runs unrolled and therefore in parallel on the CPU
-        if (_random.NextUInt64() <= _sampleIfRandomSmallerOrEqualsTo)
+        if (ShouldMeasure())
         {
-            AddMeasurement((GetTimestamp() - start) * _sampling, _sampling);
+            AddMeasurement((GetTimestamp() - start) * _samplingInterval, _samplingInterval);
         }
     }
 }