From b86c619ddde369e6240797ccdd3bf2a99cb88958 Mon Sep 17 00:00:00 2001 From: CptMoore <39010654+CptMoore@users.noreply.github.com> Date: Fri, 3 Jan 2025 23:10:09 +0100 Subject: [PATCH] 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 | 50 +++++++++++++------ .../Features/Logging/AppenderUnityConsole.cs | 9 ++-- ModTek/Features/Logging/FastBuffer.cs | 27 +++------- ModTek/Features/Logging/Formatter.cs | 9 +++- ModTek/Features/Logging/FormattingHelpers.cs | 7 +-- .../Logging/LightWeightBlockingQueue.cs | 5 +- ModTek/Features/Logging/LoggingFeature.cs | 14 +++--- ModTek/Features/Logging/MTLoggerAsyncQueue.cs | 16 +++--- ModTek/Features/Logging/MTStopwatch.cs | 13 ++--- 9 files changed, 77 insertions(+), 73 deletions(-) diff --git a/ModTek/Features/Logging/AppenderFile.cs b/ModTek/Features/Logging/AppenderFile.cs index a9f7af52..bd5981f2 100644 --- a/ModTek/Features/Logging/AppenderFile.cs +++ b/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() diff --git a/ModTek/Features/Logging/AppenderUnityConsole.cs b/ModTek/Features/Logging/AppenderUnityConsole.cs index 52299650..d262748f 100644 --- a/ModTek/Features/Logging/AppenderUnityConsole.cs +++ b/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); } diff --git a/ModTek/Features/Logging/FastBuffer.cs b/ModTek/Features/Logging/FastBuffer.cs index 9efdc6e4..e444f88c 100644 --- a/ModTek/Features/Logging/FastBuffer.cs +++ b/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 }; diff --git a/ModTek/Features/Logging/Formatter.cs b/ModTek/Features/Logging/Formatter.cs index 370d729f..14e3a9b6 100644 --- a/ModTek/Features/Logging/Formatter.cs +++ b/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) diff --git a/ModTek/Features/Logging/FormattingHelpers.cs b/ModTek/Features/Logging/FormattingHelpers.cs index 4256bffe..d1ab04ff 100644 --- a/ModTek/Features/Logging/FormattingHelpers.cs +++ b/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 = [ diff --git a/ModTek/Features/Logging/LightWeightBlockingQueue.cs b/ModTek/Features/Logging/LightWeightBlockingQueue.cs index f151342b..bc9e21fa 100644 --- a/ModTek/Features/Logging/LightWeightBlockingQueue.cs +++ b/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 diff --git a/ModTek/Features/Logging/LoggingFeature.cs b/ModTek/Features/Logging/LoggingFeature.cs index c253f0b9..1df71214 100644 --- a/ModTek/Features/Logging/LoggingFeature.cs +++ b/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 diff --git a/ModTek/Features/Logging/MTLoggerAsyncQueue.cs b/ModTek/Features/Logging/MTLoggerAsyncQueue.cs index d248d208..8da72872 100644 --- a/ModTek/Features/Logging/MTLoggerAsyncQueue.cs +++ b/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(); } } } diff --git a/ModTek/Features/Logging/MTStopwatch.cs b/ModTek/Features/Logging/MTStopwatch.cs index aac2a6d9..3a30d380 100644 --- a/ModTek/Features/Logging/MTStopwatch.cs +++ b/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);