Improved logging stats slightly.

ModTek/Features/Logging/LightWeightBlockingQueue.cs

@@ -15,8 +15,8 @@ internal class LightWeightBlockingQueue
     internal void Shutdown() => _shutdown = true;
     private volatile bool _shutdown; // some way to break the waiting
 
-    // 100k leads to about ~30MB, pre-allocation uses much less due to absent strings
-    private const int MaxRingBufferSize = 1 << 16; // power of 2 required by FastModuloMaskForBitwiseAnd
+    // 100k leads to about ~30MB, pre-allocation reports less due to absent strings
+    private const int MaxRingBufferSize = 100_000;
     private const int MaxQueueSize = MaxRingBufferSize - 1; // Start=End need to be distinguishable
     // ring buffer is used by Disruptor(.NET), seems to work well for them
     // typed based exchanges are 56ns (fixed as of .NET 7) hence why we use object based ones
@@ -26,23 +26,35 @@ internal class LightWeightBlockingQueue
     private volatile int _nextWritingIndex; // sync in between writers
     private volatile int _nextReadIndex; // sync between readers -> writers
 
-    // see https://en.wikipedia.org/wiki/Modulo#Performance_issues
-    // Bitwise AND is faster than modulo, just requires size to be power of 2
-    // only gained like 1-2ns though (meaning it is within measurement error...)
-    private const int FastModuloMaskForBitwiseAnd = MaxRingBufferSize - 1;
     [MethodImpl(MethodImplOptions.AggressiveInlining)]
     private static int Next(int index)
     {
-        return (index + 1) & FastModuloMaskForBitwiseAnd;
-        // return (index + 1) % MaxRingBufferSize;
+        return (index + 1) % MaxRingBufferSize;
     }
     [MethodImpl(MethodImplOptions.AggressiveInlining)]
     private static int Size(int startIndex, int endIndex)
     {
-        return (endIndex - startIndex) & FastModuloMaskForBitwiseAnd;
-        // return (endIndex - startIndex + MaxRingBufferSize) % MaxRingBufferSize;
+        return (endIndex - startIndex + MaxRingBufferSize) % MaxRingBufferSize;
     }
 
+    // the following trick is faster but less human consumption friendly
+    // my guess is that modulo is already optimized and only the addition for the Size calc is what makes a difference
+    // see https://en.wikipedia.org/wiki/Modulo#Performance_issues
+    // Bitwise AND is faster than modulo, just requires size to be power of 2
+    // only gained like 1-2ns though (meaning it is within measurement error...)
+    // private const int MaxRingBufferSize = 1 << 16; // power of 2 required by FastModuloMaskForBitwiseAnd
+    // private const int FastModuloMaskForBitwiseAnd = MaxRingBufferSize - 1;
+    // [MethodImpl(MethodImplOptions.AggressiveInlining)]
+    // private static int Next(int index)
+    // {
+    //     return (index + 1) & FastModuloMaskForBitwiseAnd;
+    // }
+    // [MethodImpl(MethodImplOptions.AggressiveInlining)]
+    // private static int Size(int startIndex, int endIndex)
+    // {
+    //     return (endIndex - startIndex) & FastModuloMaskForBitwiseAnd;
+    // }
+
     internal ref MTLoggerMessageDto AcquireCommittedOrWait()
     {
         var spinWait = new SpinWait();

ModTek/Features/Logging/LoggingFeature.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.Threading;
 using HBS.Logging;
@@ -109,14 +110,14 @@ internal static void AddModLogAppender(string logPath, string loggerName)
         _logsAppenders = logsAppenders;
     }
 
-    internal static readonly MTStopwatch MessageDtoStopWatch = new();
+    internal static readonly MTStopwatch MessageSetupStopWatch = new();
     // tracks all overhead on the main thread that happens due to async logging
     internal static readonly MTStopwatch DispatchStopWatch = new();
     // used for intercepting all logging attempts and to log centrally
     internal static void LogAtLevel(string loggerName, LogLevel logLevel, object message, Exception exception, IStackTrace location)
     {
         // capture timestamp as early as possible, to be as close to the callers intended time
-        var timestamp = MTLoggerMessageDto.GetTimestamp();
+        var timestamp = Stopwatch.GetTimestamp();
 
         // convert message to string while still in caller thread
         var messageAsString = message?.ToString(); // do this asap too, as this can throw exceptions
@@ -160,7 +161,7 @@ internal static void LogAtLevel(string loggerName, LogLevel logLevel, object mes
 
         updateDto.Commit();
 
-        MessageDtoStopWatch.AddMeasurement(MTLoggerMessageDto.GetTimestamp() - timestamp);
+        MessageSetupStopWatch.AddMeasurement(Stopwatch.GetTimestamp() - timestamp);
     }
 
     private static DiagnosticsStackTrace GrabStackTrace()

ModTek/Features/Logging/MTLoggerAsyncQueue.cs

@@ -48,19 +48,24 @@ internal MTLoggerAsyncQueue(IMessageProcessor processor)
                 {
                     var sb = new StringBuilder();
 
-                    var dtoStats = LoggingFeature.MessageDtoStopWatch.GetStats();
-                    sb.Append($"\nDTO setup took a total of {dtoStats.TotalTime} with an average of {dtoStats.AverageNanoseconds}ns.");
+                    var latencyStats = MTLoggerMessageDto.LatencyStopWatch.GetStats();
+                    sb.Append($"\nEnd-to-end processing had a latency average of {latencyStats.AverageNanoseconds / 1_000_000}ms.");
 
-                    sb.Append($"\nDispatched {dispatchStats.Count} times, taking a total of {dispatchStats.TotalTime} with an average of {dispatchStats.AverageNanoseconds}ns.");
+                    var dtoStats = LoggingFeature.MessageSetupStopWatch.GetStats();
+                    sb.Append($"\n  On-thread processing took a total of {dtoStats.TotalTime} with an average of {dtoStats.AverageNanoseconds}ns.");
+
+                    sb.Append($"\n    Dispatched {dispatchStats.Count} times, taking a total of {dispatchStats.TotalTime} with an average of {dispatchStats.AverageNanoseconds}ns.");
+
+                    sb.Append($"\n  Off-thread processing took a total of {stats.TotalTime} with an average of {stats.AverageNanoseconds}ns.");
 
                     var filterStats = AppenderFile.FiltersStopWatch.GetStats();
-                    sb.Append($"\nFilters took a total of {filterStats.TotalTime} with an average of {filterStats.AverageNanoseconds}ns.");
+                    sb.Append($"\n    Filters took a total of {filterStats.TotalTime} with an average of {filterStats.AverageNanoseconds}ns.");
 
                     var formatterStats = AppenderFile.FormatterStopWatch.GetStats();
-                    sb.Append($"\nFormatter took a total of {formatterStats.TotalTime} with an average of {formatterStats.AverageNanoseconds}ns.");
+                    sb.Append($"\n    Formatter took a total of {formatterStats.TotalTime} with an average of {formatterStats.AverageNanoseconds}ns.");
 
                     var writeStats = AppenderFile.WriteStopwatch.GetStats();
-                    sb.Append($"\nWrite called {writeStats.Count} times, taking a total of {writeStats.TotalTime} with an average of {writeStats.AverageNanoseconds}ns.");
+                    sb.Append($"\n    Write called {writeStats.Count} times, taking a total of {writeStats.TotalTime} with an average of {writeStats.AverageNanoseconds}ns.");
 
                     trace.Log(sb.ToString());
                 }

ModTek/Features/Logging/MTLoggerMessageDto.cs

@@ -64,17 +64,17 @@ private TimeSpan GetElapsedSinceInitial()
         return MTStopwatch.TimeSpanFromTicks(Timestamp - s_stopwatchTimestamp);
     }
 
-    internal static long GetTimestamp() => Stopwatch.GetTimestamp();
-
     // allow queue to read it
     internal void Commit()
     {
         this.CommittedToQueue = true;
     }
 
+    internal static readonly MTStopwatch LatencyStopWatch = new();
     // uncommit, prepare for re-use
     internal void Reset()
     {
+        LatencyStopWatch.AddMeasurement(Stopwatch.GetTimestamp() - Timestamp);
         this = default;
     }
 }