From 645e35b7efed13ed6282a6e8392a605d69ad3c5f Mon Sep 17 00:00:00 2001 From: CptMoore <39010654+CptMoore@users.noreply.github.com> Date: Wed, 1 Jan 2025 20:58:02 +0100 Subject: [PATCH] Moved FastBuffer lifecycle out of Formatter. --- ModTek/Features/Logging/AppenderFile.cs | 20 ++++----- .../Features/Logging/AppenderUnityConsole.cs | 7 ++- ModTek/Features/Logging/FastBuffer.cs | 28 ++++++++++-- ModTek/Features/Logging/Formatter.cs | 45 +++++++------------ .../Logging/LogStreamImpl/Win32ApiImpl.cs | 8 ---- 5 files changed, 58 insertions(+), 50 deletions(-) diff --git a/ModTek/Features/Logging/AppenderFile.cs b/ModTek/Features/Logging/AppenderFile.cs index 33df1a8a..274ce6c6 100644 --- a/ModTek/Features/Logging/AppenderFile.cs +++ b/ModTek/Features/Logging/AppenderFile.cs @@ -34,7 +34,7 @@ internal AppenderFile(string path, AppenderSettings settings) private void Write(string text) { var bytes = System.Text.Encoding.UTF8.GetBytes(text); - Write(bytes, bytes.Length); + _writer.Append(bytes, 0, bytes.Length); } internal static readonly MTStopwatch FlushStopWatch = new() @@ -43,6 +43,7 @@ private void Write(string text) }; internal static readonly MTStopwatch FiltersStopWatch = new(); internal static readonly MTStopwatch FormatterStopWatch = new(); + internal static readonly MTStopwatch WriteStopwatch = new(); internal void Append(ref MTLoggerMessageDto messageDto) { if (messageDto.FlushToDisk) @@ -72,27 +73,26 @@ internal void Append(ref MTLoggerMessageDto messageDto) FiltersStopWatch.Stop(); } - byte[] threadUnsafeBytes; - int length; + // using a pool would allow us to implement file async API via Win32 API + // using thread local instance field would allow to use batching + var buffer = FastBuffer.GetThreadStaticBufferAndReset(); FormatterStopWatch.Start(); try { - length = _formatter.GetFormattedLogLine(ref messageDto, out threadUnsafeBytes); + using (buffer.PinnedUse()) + { + _formatter.GetFormattedLogLine(ref messageDto, buffer); + } } finally { FormatterStopWatch.Stop(); } - Write(threadUnsafeBytes, length); - } - - internal static readonly MTStopwatch WriteStopwatch = new(); - private void Write(byte[] bytes, int length) - { WriteStopwatch.Start(); try { + var length = buffer.GetBytes(out var bytes); _writer.Append(bytes, 0, length); } finally diff --git a/ModTek/Features/Logging/AppenderUnityConsole.cs b/ModTek/Features/Logging/AppenderUnityConsole.cs index 3c86a305..4678c1cc 100644 --- a/ModTek/Features/Logging/AppenderUnityConsole.cs +++ b/ModTek/Features/Logging/AppenderUnityConsole.cs @@ -39,8 +39,13 @@ internal void Append(ref MTLoggerMessageDto messageDto) return; } + var buffer = FastBuffer.GetThreadStaticBufferAndReset(); + using (buffer.PinnedUse()) + { + _formatter.GetFormattedLogLine(ref messageDto, buffer); + } + var count = buffer.GetBytes(out var threadUnsafeBytes); // working with bytes and converting is more costly here, but cheaper elsewhere - var count = _formatter.GetFormattedLogLine(ref messageDto, out var threadUnsafeBytes); var logLine = System.Text.Encoding.UTF8.GetString(threadUnsafeBytes, 0, count); s_ignoreNextUnityCapture = true; _debugUnityLogger.Log(LogLevelToLogType(messageDto.LogLevel), logLine); diff --git a/ModTek/Features/Logging/FastBuffer.cs b/ModTek/Features/Logging/FastBuffer.cs index 52059f5c..1a1ea22f 100644 --- a/ModTek/Features/Logging/FastBuffer.cs +++ b/ModTek/Features/Logging/FastBuffer.cs @@ -12,16 +12,25 @@ namespace ModTek.Features.Logging; // - byte based APIs -> avoids unnecessary conversions and allocations if possible internal unsafe class FastBuffer { + [ThreadStatic] + private static FastBuffer s_buffer; + internal static FastBuffer GetThreadStaticBufferAndReset() + { + s_buffer ??= new FastBuffer(); + s_buffer.Reset(); + return s_buffer; + } + internal FastBuffer() { - EnlargeCapacity(16 * 1024); + EnlargeCapacity(4 * 1024); } private int _length; private byte[] _buffer; - internal int GetThreadUnsafeBytes(out byte[] threadUnsafeBytes) + internal int GetBytes(out byte[] bytes) { - threadUnsafeBytes = _buffer; + bytes = _buffer; return _length; } @@ -30,6 +39,19 @@ internal void Reset() _length = 0; } + internal AutoUnpin PinnedUse() + { + Pin(); + return new AutoUnpin(this); + } + internal readonly struct AutoUnpin(FastBuffer fastBuffer) : IDisposable + { + public void Dispose() + { + fastBuffer.Unpin(); + } + } + private GCHandle _handle; private byte* _bufferPtr; internal void Pin() diff --git a/ModTek/Features/Logging/Formatter.cs b/ModTek/Features/Logging/Formatter.cs index 50fa9ca0..cfa28e2c 100644 --- a/ModTek/Features/Logging/Formatter.cs +++ b/ModTek/Features/Logging/Formatter.cs @@ -21,15 +21,8 @@ internal Formatter(AppenderSettings settings) _startupTimeEnabled = settings.StartupTimeEnabled; } - [ThreadStatic] - private static FastBuffer s_buffer; - - internal int GetFormattedLogLine(ref MTLoggerMessageDto messageDto, out byte[] threadUnsafeBytes) + internal void GetFormattedLogLine(ref MTLoggerMessageDto messageDto, FastBuffer buffer) { - s_buffer ??= new FastBuffer(); - s_buffer.Reset(); - s_buffer.Pin(); - if (_absoluteTimeEnabled) { var dt = messageDto.GetDateTime(); @@ -37,55 +30,51 @@ internal int GetFormattedLogLine(ref MTLoggerMessageDto messageDto, out byte[] t { dt = dt.ToLocalTime(); } - s_buffer.Append(dt); + buffer.Append(dt); } if (_startupTimeEnabled) { var ts = messageDto.StartupTime(); - s_buffer.Append(ts); + buffer.Append(ts); } if (messageDto.ThreadId != s_unityMainThreadId) { - s_buffer.Append(s_threadIdPrefix); - s_buffer.Append(messageDto.ThreadId); - s_buffer.Append(s_threadIdSuffix); + buffer.Append(s_threadIdPrefix); + buffer.Append(messageDto.ThreadId); + buffer.Append(s_threadIdSuffix); } // TODO create injector and add a nameAsBytes field that should be passed along instead of string - s_buffer.Append(messageDto.LoggerName); + buffer.Append(messageDto.LoggerName); - s_buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel)); + buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel)); var prefix = s_whitespaceBytes; if (!string.IsNullOrEmpty(messageDto.Message)) { - s_buffer.Append(prefix); - s_buffer.Append(messageDto.Message); + buffer.Append(prefix); + buffer.Append(messageDto.Message); prefix = s_environmentNewline; } if (messageDto.Exception != null) { - s_buffer.Append(prefix); - s_buffer.Append(messageDto.Exception.ToString()); + buffer.Append(prefix); + buffer.Append(messageDto.Exception.ToString()); prefix = s_environmentNewline; } if (messageDto.Location != null) { - s_buffer.Append(prefix); - s_buffer.Append(s_locationTraceLabel); - s_buffer.Append(s_environmentNewline); - s_buffer.Append(GetLocationString(messageDto.Location)); + buffer.Append(prefix); + buffer.Append(s_locationTraceLabel); + buffer.Append(s_environmentNewline); + buffer.Append(GetLocationString(messageDto.Location)); } - s_buffer.Append(s_environmentNewline); - - s_buffer.Unpin(); - - return s_buffer.GetThreadUnsafeBytes(out threadUnsafeBytes); + buffer.Append(s_environmentNewline); } private static string GetLocationString(IStackTrace st) diff --git a/ModTek/Features/Logging/LogStreamImpl/Win32ApiImpl.cs b/ModTek/Features/Logging/LogStreamImpl/Win32ApiImpl.cs index 633797a6..a406d408 100644 --- a/ModTek/Features/Logging/LogStreamImpl/Win32ApiImpl.cs +++ b/ModTek/Features/Logging/LogStreamImpl/Win32ApiImpl.cs @@ -140,14 +140,6 @@ private static extern unsafe int WriteFile( out int numBytesWritten, NativeOverlapped* lpOverlapped); - [DllImport("kernel32.dll", SetLastError = true)] - private static extern unsafe int WriteFile( - SafeHandle handle, - byte* bytes, - int numBytesToWrite, - out int numBytesWritten, - IntPtr mustBeZero); - [DllImport("kernel32.dll", SetLastError = true)] [return: MarshalAs(UnmanagedType.Bool)] private static extern bool FlushFileBuffers(SafeHandle hHandle);