Write to OS buffers in batches. Avoid struct structures. Set logging …

…thread priority to higher than normal, we don't support single core cpus.

ModTek/Features/Logging/AppenderFile.cs

@@ -10,7 +10,10 @@ internal class AppenderFile : IDisposable
     private readonly Filters _filters;
     private readonly Formatter _formatter;
     private readonly LogStream _writer;
-    private readonly FastBuffer _buffer = new();
+
+    private const int _bufferFlushThreshold = 16 * 1024; // 16kb seems to bring most gains
+    private const int _bufferInitialCapacity = _bufferFlushThreshold + 8 * 1024;
+    private readonly FastBuffer _buffer = new(_bufferInitialCapacity);
 
     internal AppenderFile(string path, AppenderSettings settings)
     {
@@ -45,39 +48,56 @@ private void Write(string text)
     internal static readonly MTStopwatch FiltersStopWatch = new();
     internal static readonly MTStopwatch FormatterStopWatch = new();
     internal static readonly MTStopwatch WriteStopwatch = new() { SkipFirstNumberOfMeasurements = 0 };
-    internal void Append(ref MTLoggerMessageDto messageDto)
+    internal void Append(ref MTLoggerMessageDto messageDto, int queueSize)
     {
+        var hasMore = queueSize > 1;
+
         if (messageDto.FlushToDisk)
         {
-            using (FlushStopWatch.BeginMeasurement())
+            if (_buffer._length > 0)
             {
-                _writer.FlushToDisk();
+                FlushToOS();
             }
+
+            var measurement = FlushStopWatch.StartMeasurement();
+            _writer.FlushToDisk();
+            measurement.Stop();
             return;
         }
 
-        using (FiltersStopWatch.BeginMeasurement())
         {
-            if (!_filters.IsIncluded(ref messageDto))
+            var measurement = FiltersStopWatch.StartMeasurement();
+            var included = _filters.IsIncluded(ref messageDto);
+            measurement.Stop();
+            if (!included)
             {
+                if (!hasMore && _buffer._length > 0)
+                {
+                    FlushToOS();
+                }
                 return;
             }
         }
 
-        using (FormatterStopWatch.BeginMeasurement())
         {
-            _buffer.Reset();
-            using (_buffer.PinnedUse())
+            var measurement = FormatterStopWatch.StartMeasurement();
+            _formatter.SerializeMessage(ref messageDto, _buffer);
+            measurement.Stop();
+
+            if (!hasMore || _buffer._length >= _bufferFlushThreshold)
             {
-                _formatter.SerializeMessageToBuffer(ref messageDto, _buffer);
+                FlushToOS();
             }
         }
+    }
 
-        using (WriteStopwatch.BeginMeasurement())
-        {
-            var length = _buffer.GetBytes(out var threadUnsafeBytes);
-            _writer.Append(threadUnsafeBytes, 0, length);
-        }
+    private void FlushToOS()
+    {
+        var measurement = WriteStopwatch.StartMeasurement();
+        var length = _buffer.GetBytes(out var threadUnsafeBytes);
+        _writer.Append(threadUnsafeBytes, 0, length);
+        _buffer.Reset();
+        measurement.Stop();
     }
 
     public void Dispose()

ModTek/Features/Logging/AppenderUnityConsole.cs

@@ -41,14 +41,11 @@ internal void Append(ref MTLoggerMessageDto messageDto)
         }
 
         _buffer.Reset();
-        using (_buffer.PinnedUse())
-        {
-            _formatter.SerializeMessageToBuffer(ref messageDto, _buffer);
-        }
-        var count = _buffer.GetBytes(out var threadUnsafeBytes);
+        _formatter.SerializeMessage(ref messageDto, _buffer);
+        var length = _buffer.GetBytes(out var threadUnsafeBytes);
         // working with bytes and converting is more costly here, but cheaper elsewhere
         // unity console is slow anyway, and also disabled by default
-        var logLine = System.Text.Encoding.UTF8.GetString(threadUnsafeBytes, 0, count);
+        var logLine = System.Text.Encoding.UTF8.GetString(threadUnsafeBytes, 0, length);
         s_ignoreNextUnityCapture = true;
         _debugUnityLogger.Log(LogLevelToLogType(messageDto.LogLevel), logLine);
     }

ModTek/Features/Logging/FastBuffer.cs

@@ -12,12 +12,12 @@ namespace ModTek.Features.Logging;
 // - byte based APIs -> avoids unnecessary conversions and allocations if possible
 internal unsafe class FastBuffer
 {
-    internal FastBuffer()
+    internal FastBuffer(int initialCapacity = 16 * 1024)
     {
-        EnlargeCapacity(16 * 1024);
+        EnlargeCapacity(initialCapacity);
     }
 
-    private int _length;
+    internal int _length;
     private byte[] _buffer;
     internal int GetBytes(out byte[] bytes)
     {
@@ -30,22 +30,9 @@ internal void Reset()
         _length = 0;
     }
 
-    internal IDisposable PinnedUse()
-    {
-        Pin();
-        return new AutoUnpin(this);
-    }
-    private readonly struct AutoUnpin(FastBuffer fastBuffer) : IDisposable
-    {
-        public void Dispose()
-        {
-            fastBuffer.Unpin();
-        }
-    }
-
     private GCHandle _handle;
     private byte* _bufferPtr;
-    private void Pin()
+    internal void Pin()
     {
         if (_handle.IsAllocated)
         {
@@ -55,7 +42,7 @@ private void Pin()
         _bufferPtr = (byte*)_handle.AddrOfPinnedObject();
     }
 
-    private void Unpin()
+    internal void Unpin()
     {
         if (_handle.IsAllocated)
         {
@@ -167,12 +154,12 @@ internal void Append(string value)
             return;
 
             Utf8Fallback: // this is 10x slower or more (GetBytes has no fast ASCII path and no SIMD in this old .NET)
-            var measurement = UTF8FallbackStopwatch.BeginMeasurement();
+            var measurement = UTF8FallbackStopwatch.StartMeasurement();
             var charIndex = value.Length - processingCount;
             const int Utf8MaxBytesPerChar = 4;
             EnsureCapacity(_length + processingCount * Utf8MaxBytesPerChar);
             _length += Encoding.UTF8.GetBytes(value, charIndex, processingCount, _buffer, _length);
-            measurement.End();
+            measurement.Stop();
         }
     }
     internal static readonly MTStopwatch UTF8FallbackStopwatch = new() { SkipFirstNumberOfMeasurements = 0 };

ModTek/Features/Logging/Formatter.cs

@@ -21,8 +21,10 @@ internal Formatter(AppenderSettings settings)
         _startupTimeEnabled = settings.StartupTimeEnabled;
     }
 
-    internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBuffer buffer)
+    internal void SerializeMessage(ref MTLoggerMessageDto messageDto, FastBuffer buffer)
     {
+        buffer.Pin();
+
         if (_absoluteTimeEnabled)
         {
             var dt = messageDto.GetDateTime();
@@ -47,6 +49,7 @@ internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBu
         }
 
         // TODO create injector and add a nameAsBytes field that should be passed along instead of string
+        //  should improve performance by 20% since string/char[] -> byte[] is slow
         buffer.Append(messageDto.LoggerName);
 
         buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel));
@@ -62,6 +65,8 @@ internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBu
         if (messageDto.Exception != null)
         {
             buffer.Append(prefix);
+            // TODO find a faster (pinvoke?) method for conversion
+            //  this takes like 60-80% of the formatting time
             buffer.Append(messageDto.Exception.ToString());
             prefix = s_environmentNewline;
         }
@@ -75,6 +80,8 @@ internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBu
         }
 
         buffer.Append(s_environmentNewline);
+
+        buffer.Unpin();
     }
 
     private static string GetLocationString(IStackTrace st)

ModTek/Features/Logging/FormattingHelpers.cs

@@ -72,7 +72,7 @@ private static int Log2(uint value)
         // Fallback contract is 0->0
         return Log2SoftwareFallback(value);
     }
-    private static unsafe int Log2SoftwareFallback(uint value)
+    private static int Log2SoftwareFallback(uint value)
     {
         // No AggressiveInlining due to large method size
         // Has conventional contract 0->0 (Log(0) is undefined)
@@ -85,10 +85,7 @@ private static unsafe int Log2SoftwareFallback(uint value)
         value |= value >> 16;
 
         var offset = (value * 0x07C4ACDDu) >> 27;
-        fixed (byte* ptr = s_log2DeBruijn)
-        {
-            return ptr[offset];
-        }
+        return s_log2DeBruijn[offset];
     }
     private static readonly byte[] s_log2DeBruijn =
     [

ModTek/Features/Logging/LightWeightBlockingQueue.cs

@@ -41,13 +41,14 @@ private static int Size(int startIndex, int endIndex)
         return (endIndex - startIndex) & FastModuloMaskForBitwiseAnd;
     }
 
-    internal ref MTLoggerMessageDto AcquireCommittedOrWait()
+    internal ref MTLoggerMessageDto AcquireCommittedOrWait(out int queueSize)
     {
         var spinWait = new SpinWait();
         while (true)
         {
             var index = _nextReadIndex;
-            if (Size(index, _nextWriteIndex) > 0)
+            queueSize = Size(index, _nextWriteIndex);
+            if (queueSize > 0)
             {
                 ref var item = ref _ringBuffer[index];
                 // makes sure no overtake on the ring happens

ModTek/Features/Logging/LoggingFeature.cs

@@ -139,9 +139,9 @@ internal static void LogAtLevel(string loggerName, LogLevel logLevel, object mes
             }
         }
 
-        var measurement = DispatchStopWatch.BeginMeasurement();
+        var measurement = DispatchStopWatch.StartMeasurement();
         ref var updateDto = ref _queue.AcquireUncommitedOrWait();
-        measurement.End();
+        measurement.Stop();
 
         updateDto.Timestamp = timestamp;
         updateDto.LoggerName = loggerName;
@@ -170,9 +170,9 @@ internal static void Flush()
             }
         }
 
-        var measurement = DispatchStopWatch.BeginMeasurement();
+        var measurement = DispatchStopWatch.StartMeasurement();
         ref var updateDto = ref _queue.AcquireUncommitedOrWait();
-        measurement.End();
+        measurement.Stop();
 
         updateDto.FlushToDiskPostEvent = flushEvent;
         updateDto.Commit();
@@ -223,16 +223,16 @@ private static DiagnosticsStackTrace GrabStackTrace()
         return new DiagnosticsStackTrace(6, false);
     }
 
-    internal static void LogMessage(ref MTLoggerMessageDto messageDto)
+    internal static void LogMessage(ref MTLoggerMessageDto messageDto, int queueSize = 0)
     {
         try
         {
             _consoleLog?.Append(ref messageDto);
 
-            _mainLog.Append(ref messageDto);
+            _mainLog.Append(ref messageDto, queueSize);
             foreach (var logAppender in _logsAppenders)
             {
-                logAppender.Append(ref messageDto);
+                logAppender.Append(ref messageDto, queueSize);
             }
         }
         finally

ModTek/Features/Logging/MTLoggerAsyncQueue.cs

@@ -17,7 +17,7 @@ internal MTLoggerAsyncQueue()
         var thread = new Thread(LoggingLoop)
         {
             Name = nameof(MTLoggerAsyncQueue),
-            Priority = ThreadPriority.BelowNormal, // game should take priority
+            Priority = ThreadPriority.AboveNormal,
             IsBackground = false // don't exit automatically
         };
         thread.Start();
@@ -43,15 +43,15 @@ internal MTLoggerAsyncQueue()
             logger.Log(
                 $"""
                 Asynchronous logging offloaded {offloadedTime} from the main thread.
-                Flushed {AppenderFile.FlushStopWatch.GetStats()}.
-                End-to-end processing had an average latency of {latencyStats.AverageNanoseconds / 1_000_000}ms.
+                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.
                     Dispatch {dispatchStats}.
                   Off-thread processing took a total of {stats.TotalTime} with an average of {stats.AverageNanoseconds}ns.
+                    Flushed (to disk) {AppenderFile.FlushStopWatch.GetStats()}.
                     Filters {AppenderFile.FiltersStopWatch.GetStats()}.
                     Formatter {AppenderFile.FormatterStopWatch.GetStats()}.
                       UTF8-Fallback {FastBuffer.UTF8FallbackStopwatch.GetStats()}.
-                    Write {AppenderFile.WriteStopwatch.GetStats()}.
+                    Write (to OS buffers) {AppenderFile.WriteStopwatch.GetStats()}.
                 """
             );
         },
@@ -80,12 +80,12 @@ private void LoggingLoop()
         {
             while (true)
             {
-                ref var message = ref _queue.AcquireCommittedOrWait();
+                ref var message = ref _queue.AcquireCommittedOrWait(out var queueSize);
 
-                var measurement = s_loggingStopwatch.BeginMeasurement();
+                var measurement = s_loggingStopwatch.StartMeasurement();
                 try
                 {
-                    LoggingFeature.LogMessage(ref message);
+                    LoggingFeature.LogMessage(ref message, queueSize);
                 }
                 catch (Exception e)
                 {
@@ -94,7 +94,7 @@ private void LoggingLoop()
                 finally
                 {
                     message.Reset();
-                    measurement.End();
+                    measurement.Stop();
                 }
             }
         }

ModTek/Features/Logging/MTStopwatch.cs

@@ -14,20 +14,15 @@ internal class MTStopwatch
     private long _ticks;
     private long _count;
 
-    internal AutoStop BeginMeasurement()
+    internal Measurement StartMeasurement()
     {
-        return new AutoStop(this);
+        return new Measurement(this);
     }
-    internal readonly struct AutoStop(MTStopwatch stopwatch) : IDisposable
+    internal readonly struct Measurement(MTStopwatch stopwatch)
     {
         private readonly long _begin = Stopwatch.GetTimestamp();
         [MethodImpl(MethodImplOptions.AggressiveInlining)]
-        public void Dispose()
-        {
-            End();
-        }
-        [MethodImpl(MethodImplOptions.AggressiveInlining)]
-        internal void End()
+        internal void Stop()
         {
             var elapsed = Stopwatch.GetTimestamp() - _begin;
             stopwatch.AddMeasurement(elapsed);