From d0fa80947bfcc164792ac1d2ee15c9618365eac4 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] Reverted FastBuffer back to ThreadStatic since it seems 2-5 times faster. --- ModTek/Features/Logging/AppenderFile.cs | 10 ++-- .../Features/Logging/AppenderUnityConsole.cs | 8 +--- ModTek/Features/Logging/FastBuffer.cs | 17 +------ ModTek/Features/Logging/Formatter.cs | 48 ++++++++++++------- ModTek/Features/Logging/FormattingHelpers.cs | 7 +-- 5 files changed, 39 insertions(+), 51 deletions(-) diff --git a/ModTek/Features/Logging/AppenderFile.cs b/ModTek/Features/Logging/AppenderFile.cs index a9f7af5..5be55d4 100644 --- a/ModTek/Features/Logging/AppenderFile.cs +++ b/ModTek/Features/Logging/AppenderFile.cs @@ -10,7 +10,6 @@ internal class AppenderFile : IDisposable private readonly Filters _filters; private readonly Formatter _formatter; private readonly LogStream _writer; - private readonly FastBuffer _buffer = new(); internal AppenderFile(string path, AppenderSettings settings) { @@ -64,18 +63,15 @@ internal void Append(ref MTLoggerMessageDto messageDto) } } + int length; + byte[] threadUnsafeBytes; using (FormatterStopWatch.BeginMeasurement()) { - _buffer.Reset(); - using (_buffer.PinnedUse()) - { - _formatter.SerializeMessageToBuffer(ref messageDto, _buffer); - } + length = _formatter.SerializeMessage(ref messageDto, out threadUnsafeBytes); } using (WriteStopwatch.BeginMeasurement()) { - var length = _buffer.GetBytes(out var threadUnsafeBytes); _writer.Append(threadUnsafeBytes, 0, length); } } diff --git a/ModTek/Features/Logging/AppenderUnityConsole.cs b/ModTek/Features/Logging/AppenderUnityConsole.cs index 5229965..3c6aafd 100644 --- a/ModTek/Features/Logging/AppenderUnityConsole.cs +++ b/ModTek/Features/Logging/AppenderUnityConsole.cs @@ -12,7 +12,6 @@ internal class AppenderUnityConsole private readonly Filters _filters; private readonly Formatter _formatter; private readonly ILogger _debugUnityLogger; - private readonly FastBuffer _buffer = new(); internal AppenderUnityConsole(AppenderSettings settings) { @@ -40,12 +39,7 @@ internal void Append(ref MTLoggerMessageDto messageDto) return; } - _buffer.Reset(); - using (_buffer.PinnedUse()) - { - _formatter.SerializeMessageToBuffer(ref messageDto, _buffer); - } - var count = _buffer.GetBytes(out var threadUnsafeBytes); + var count = _formatter.SerializeMessage(ref messageDto, 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); diff --git a/ModTek/Features/Logging/FastBuffer.cs b/ModTek/Features/Logging/FastBuffer.cs index 9efdc6e..3a14990 100644 --- a/ModTek/Features/Logging/FastBuffer.cs +++ b/ModTek/Features/Logging/FastBuffer.cs @@ -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) { diff --git a/ModTek/Features/Logging/Formatter.cs b/ModTek/Features/Logging/Formatter.cs index 370d729..474de1e 100644 --- a/ModTek/Features/Logging/Formatter.cs +++ b/ModTek/Features/Logging/Formatter.cs @@ -21,8 +21,15 @@ internal Formatter(AppenderSettings settings) _startupTimeEnabled = settings.StartupTimeEnabled; } - internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBuffer buffer) + [ThreadStatic] + private static FastBuffer s_buffer; + + internal int SerializeMessage(ref MTLoggerMessageDto messageDto, out byte[] threadUnsafeBytes) { + s_buffer ??= new FastBuffer(); + s_buffer.Reset(); + s_buffer.Pin(); + if (_absoluteTimeEnabled) { var dt = messageDto.GetDateTime(); @@ -30,51 +37,58 @@ internal void SerializeMessageToBuffer(ref MTLoggerMessageDto messageDto, FastBu { dt = dt.ToLocalTime(); } - buffer.Append(dt); + s_buffer.Append(dt); } if (_startupTimeEnabled) { var ts = messageDto.StartupTime(); - buffer.Append(ts); + s_buffer.Append(ts); } if (messageDto.ThreadId != s_unityMainThreadId) { - buffer.Append(s_threadIdPrefix); - buffer.Append(messageDto.ThreadId); - buffer.Append(s_threadIdSuffix); + s_buffer.Append(s_threadIdPrefix); + s_buffer.Append(messageDto.ThreadId); + s_buffer.Append(s_threadIdSuffix); } // TODO create injector and add a nameAsBytes field that should be passed along instead of string - buffer.Append(messageDto.LoggerName); + // should improve performance by 20% since string/char[] -> byte[] is slow + s_buffer.Append(messageDto.LoggerName); - buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel)); + s_buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel)); var prefix = s_whitespaceBytes; if (!string.IsNullOrEmpty(messageDto.Message)) { - buffer.Append(prefix); - buffer.Append(messageDto.Message); + s_buffer.Append(prefix); + s_buffer.Append(messageDto.Message); prefix = s_environmentNewline; } if (messageDto.Exception != null) { - buffer.Append(prefix); - buffer.Append(messageDto.Exception.ToString()); + s_buffer.Append(prefix); + // TODO find a faster (pinvoke?) method for conversion + // this takes like 60-80% of the formatting time + s_buffer.Append(messageDto.Exception.ToString()); prefix = s_environmentNewline; } if (messageDto.Location != null) { - buffer.Append(prefix); - buffer.Append(s_locationTraceLabel); - buffer.Append(s_environmentNewline); - buffer.Append(GetLocationString(messageDto.Location)); + s_buffer.Append(prefix); + s_buffer.Append(s_locationTraceLabel); + s_buffer.Append(s_environmentNewline); + s_buffer.Append(GetLocationString(messageDto.Location)); } - buffer.Append(s_environmentNewline); + s_buffer.Append(s_environmentNewline); + + s_buffer.Unpin(); + + return s_buffer.GetBytes(out threadUnsafeBytes); } private static string GetLocationString(IStackTrace st) diff --git a/ModTek/Features/Logging/FormattingHelpers.cs b/ModTek/Features/Logging/FormattingHelpers.cs index 4256bff..d1ab04f 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 = [