From 510ad74df1b9137f8b08b1c0a4ca3fb6ce6111ad Mon Sep 17 00:00:00 2001 From: CptMoore <39010654+cptmoore@users.noreply.github.com> Date: Sat, 21 Dec 2024 18:15:18 +0100 Subject: [PATCH] Further improvements to make the logging formatter faster. --- ModTek/Features/Logging/AppenderFile.cs | 5 +- ModTek/Features/Logging/FastBuffer.cs | 312 +++++++++++++++--- ModTek/Features/Logging/Filter.cs | 25 +- ModTek/Features/Logging/Formatter.cs | 48 ++- ModTek/Features/Logging/LogLevelExtension.cs | 36 +- .../LogStreamImpl/MonoIoFileStreamImpl.cs | 45 +-- ModTek/Features/Logging/MTLoggerAsyncQueue.cs | 15 +- ModTek/Features/Logging/MTStopwatch.cs | 22 +- .../Patches/LogImpl_set_Level_Patch.cs | 28 +- 9 files changed, 374 insertions(+), 162 deletions(-) diff --git a/ModTek/Features/Logging/AppenderFile.cs b/ModTek/Features/Logging/AppenderFile.cs index 5019823..1c4cddc 100644 --- a/ModTek/Features/Logging/AppenderFile.cs +++ b/ModTek/Features/Logging/AppenderFile.cs @@ -37,7 +37,10 @@ private void Write(string text) Write(bytes, bytes.Length); } - internal static readonly MTStopwatch FlushStopWatch = new(); + internal static readonly MTStopwatch FlushStopWatch = new() + { + SkipFirstNumberOfMeasurements = 0 + }; internal static readonly MTStopwatch FiltersStopWatch = new(); internal static readonly MTStopwatch FormatterStopWatch = new(); internal void Append(ref MTLoggerMessageDto messageDto) diff --git a/ModTek/Features/Logging/FastBuffer.cs b/ModTek/Features/Logging/FastBuffer.cs index 7db7be1..f7c0882 100644 --- a/ModTek/Features/Logging/FastBuffer.cs +++ b/ModTek/Features/Logging/FastBuffer.cs @@ -1,100 +1,304 @@ using System; +using System.Globalization; +using System.Runtime.CompilerServices; +using System.Runtime.InteropServices; using System.Text; namespace ModTek.Features.Logging; -internal class FastBuffer +// optimizes writing to a byte array: +// - loop unrolling -> allow some parallelism in the absence of SIMD, AVX could improve this 10x though +// - unsafe -> avoid array bounds checks (cpu branch prediction already skips those, so no gain except code size) +// - ascii conversion first -> quick char to byte conversions if compatible +// - byte based APIs -> avoids unnecessary conversions and allocations if possible +internal unsafe class FastBuffer { - private int _position; - private byte[] _buffer = new byte[4 * 1024]; - - internal void Clear() + internal FastBuffer() { - _position = 0; + EnlargeCapacity(16 * 1024); } + private int _length; + private byte[] _buffer; internal int GetBytes(out byte[] bytes) { bytes = _buffer; - return _position; + return _length; + } + + private GCHandle _handle; + private byte* _bufferPtr; + internal void Setup() + { + _length = 0; + + if (_handle.IsAllocated) + { + return; + } + _handle = GCHandle.Alloc(_buffer, GCHandleType.Pinned); + _bufferPtr = (byte*)_handle.AddrOfPinnedObject(); + } + + internal void Append(byte value) + { + var position = GetPointerAndIncrementLength(1); + *position = value; + } + + internal void Append(byte[] value) + { + var position = GetPointerAndIncrementLength(value.Length); + fixed (byte* bytes = value) + { + Memcpy1(position, bytes, value.Length); + } + } + + // mainly used for ThreadId + internal void Append(int value) + { + if (value < 10) + { + var position = GetPointerAndIncrementLength(1); + position[0] = (byte)(value % 10 + AsciiZero); + } + else if (value < 100) + { + var position = GetPointerAndIncrementLength(2); + position[0] = (byte)(value / 10 % 10 + AsciiZero); + position[1] = (byte)(value % 10 + AsciiZero); + } + else if (value < 1000) + { + var position = GetPointerAndIncrementLength(3); + position[0] = (byte)(value / 100 % 10 + AsciiZero); + position[1] = (byte)(value / 10 % 10 + AsciiZero); + position[2] = (byte)(value % 10 + AsciiZero); + } + else + { + Append(value.ToString(CultureInfo.InvariantCulture)); + } + } + + internal void Append(decimal value) + { + // TODO optimize + Append(value.ToString(CultureInfo.InvariantCulture)); } - private readonly char[] _chars = new char[1]; - internal void Append(char value) + const byte AsciiCompatibleWithUnicodeEqualsOrSmallerThan = 127; + internal void Append(string value) { - const int Utf8MaxBytesPerChar = 4; - if (_buffer.Length < _position + Utf8MaxBytesPerChar) + var processingCount = value.Length; + if (processingCount == 0) { - Array.Resize(ref _buffer, 2 * _buffer.Length); + return; } - if (value <= 'ÿ') // char fits in a single byte, see Convert.ToByte(char) + // assume one byte per char, enlarge through AppendUsingEncoding if necessary + EnsureCapacity(_length + processingCount); + void AppendUsingEncoding(int iterSize) { - var valueAsByte = (byte)value; // the code below is twice as fast with byte instead of char + const int Utf8MaxBytesPerChar = 4; + EnsureCapacity(_length + (processingCount - iterSize) + (iterSize * Utf8MaxBytesPerChar)); + var charIndex = value.Length - processingCount; + _length += Encoding.UTF8.GetBytes(value, charIndex, iterSize, _buffer, _length); + } + + fixed (char* chars = value) + { + var positionIterPtr = _bufferPtr + _length; + var charsIterPtr = chars; + + // loop unrolling similar to Buffer.memcpy1 - // filter out most control characters - // https://en.wikipedia.org/wiki/Unicode_control_characters - // const byte C0Start = 0x00; - const byte C0End = 0x1F; - if (valueAsByte <= C0End) { - const byte HT = (byte)'\t'; - const byte LF = (byte)'\n'; - const byte CR = (byte)'\r'; - switch (valueAsByte) + const int IterSize = 8; + for (; processingCount >= IterSize; processingCount -= IterSize) { - case HT: - case LF: - case CR: - break; - default: - return; + var r0 = SetAscii(positionIterPtr, charsIterPtr, 0); + var r1 = SetAscii(positionIterPtr, charsIterPtr, 1); + var r2 = SetAscii(positionIterPtr, charsIterPtr, 2); + var r3 = SetAscii(positionIterPtr, charsIterPtr, 3); + var r4 = SetAscii(positionIterPtr, charsIterPtr, 4); + var r5 = SetAscii(positionIterPtr, charsIterPtr, 5); + var r6 = SetAscii(positionIterPtr, charsIterPtr, 6); + var r7 = SetAscii(positionIterPtr, charsIterPtr, 7); + if (r0 && r1 && r2 && r3 && r4 && r5 && r6 && r7) + { + _length += IterSize; + } + else + { + AppendUsingEncoding(IterSize); + } + positionIterPtr = _bufferPtr + _length; + charsIterPtr += IterSize; } } - else + { - const byte C1Start = 0x7F; - const byte C1End = 0x9F; - if (valueAsByte is >= C1Start and <= C1End) + const int IterSize = 2; + for (; processingCount >= IterSize; processingCount -= IterSize) { - return; + var r0 = SetAscii(positionIterPtr, charsIterPtr, 0); + var r1 = SetAscii(positionIterPtr, charsIterPtr, 1); + if (r0 && r1) + { + _length += IterSize; + } + else + { + AppendUsingEncoding(IterSize); + } + positionIterPtr = _bufferPtr + _length; + charsIterPtr += IterSize; } } - const byte AsciiCompatibleWithUnicodeBelow = 127; - if (valueAsByte <= AsciiCompatibleWithUnicodeBelow) + if (processingCount > 0) { - _buffer[_position++] = valueAsByte; - return; + const int IterSize = 1; + var r0 = SetAscii(positionIterPtr, charsIterPtr, 0); + if (r0) + { + _length += IterSize; + } + else + { + AppendUsingEncoding(IterSize); + } } } + } - _chars[0] = value; - _position += Encoding.UTF8.GetBytes(_chars, 0, 1, _buffer, _position); + [MethodImpl(MethodImplOptions.AggressiveInlining)] + private bool SetAscii(byte* positionIterPtr, char* charsIterPtr, int offset) + { + var valueAsByte = (byte)charsIterPtr[offset]; + positionIterPtr[offset] = valueAsByte; + return valueAsByte <= AsciiCompatibleWithUnicodeEqualsOrSmallerThan; } - internal void Append(string value) + internal void Append(DateTime value) + { + var hour = value.Hour; + var minute = value.Minute; + var second = value.Second; + var ticks = value.Ticks; + + var position = GetPointerAndIncrementLength(17); + position[0] = (byte)(hour / 10 % 10 + AsciiZero); + position[1] = (byte)(hour % 10 + AsciiZero); + position[2] = (byte)':'; + position[3] = (byte)(minute / 10 % 10 + AsciiZero); + position[4] = (byte)(minute % 10 + AsciiZero); + position[5] = (byte)':'; + position[6] = (byte)(second / 10 % 10 + AsciiZero); + position[7] = (byte)(second % 10 + AsciiZero); + position[8] = (byte)'.'; + position[9] = (byte)(ticks / 1_000_000 % 10 + AsciiZero); + position[10] = (byte)(ticks / 100_000 % 10 + AsciiZero); + position[11] = (byte)(ticks / 10_000 % 10 + AsciiZero); + position[12] = (byte)(ticks / 1_000 % 10 + AsciiZero); + position[13] = (byte)(ticks / 100 % 10 + AsciiZero); + position[14] = (byte)(ticks / 10 % 10 + AsciiZero); + position[15] = (byte)(ticks % 10 + AsciiZero); + position[16] = (byte)' '; + } + const byte AsciiZero = (byte)'0'; + + //[MethodImpl(MethodImplOptions.AggressiveInlining)] + private byte* GetPointerAndIncrementLength(int increment) + { + var length = _length; + var requiredCapacity = _length + increment; + EnsureCapacity(requiredCapacity); + _length = requiredCapacity; + return _bufferPtr + length; + } + + [MethodImpl(MethodImplOptions.AggressiveInlining)] + private void EnsureCapacity(int targetLength) + { + if (_buffer.Length < targetLength) + { + EnlargeCapacity(targetLength); + } + } + + private void EnlargeCapacity(int targetLength) { - foreach (var c in value) + var newBuffer = new byte[targetLength]; + var newHandle = GCHandle.Alloc(newBuffer, GCHandleType.Pinned); + try { - Append(c); + var newBufferPtr = (byte*)newHandle.AddrOfPinnedObject(); + + if (_buffer != null) + { + Memcpy1(newBufferPtr, _bufferPtr, _length); + try + { + _handle.Free(); + } + catch + { + _buffer = null; + _bufferPtr = null; + } + } + + _buffer = newBuffer; + _handle = newHandle; + _bufferPtr = newBufferPtr; + } + catch + { + newHandle.Free(); + throw; } } - internal void AppendLast2Digits(long value) + // from Buffer.memcpy1 + private static void Memcpy1(byte* dest, byte* src, int size) { - Append((char)(((value / 10) % 10) + '0')); - Append((char)(((value / 1) % 10) + '0')); + for (; size >= 8; size -= 8) + { + *dest = *src; + dest[1] = src[1]; + dest[2] = src[2]; + dest[3] = src[3]; + dest[4] = src[4]; + dest[5] = src[5]; + dest[6] = src[6]; + dest[7] = src[7]; + dest += 8; + src += 8; + } + for (; size >= 2; size -= 2) + { + *dest = *src; + dest[1] = src[1]; + dest += 2; + src += 2; + } + if (size <= 0) + return; + *dest = *src; } - internal void AppendLast7Digits(long value) + ~FastBuffer() { - Append((char)(((value / 1_000_000) % 10) + '0')); - Append((char)(((value / 100_000) % 10) + '0')); - Append((char)(((value / 10_000) % 10) + '0')); - Append((char)(((value / 1_000) % 10) + '0')); - Append((char)(((value / 100) % 10) + '0')); - Append((char)(((value / 10) % 10) + '0')); - Append((char)(((value / 1) % 10) + '0')); + try + { + _handle.Free(); + } + catch + { + // ignored + } } } \ No newline at end of file diff --git a/ModTek/Features/Logging/Filter.cs b/ModTek/Features/Logging/Filter.cs index f7aa5b6..01cde39 100644 --- a/ModTek/Features/Logging/Filter.cs +++ b/ModTek/Features/Logging/Filter.cs @@ -1,5 +1,4 @@ using System; -using System.Collections.Generic; using System.Linq; using System.Text.RegularExpressions; using HBS.Logging; @@ -16,7 +15,9 @@ internal Filter(FilterSettings settings) { if (settings.LoggerNames != null) { - _loggerNames = settings.LoggerNames; + // Intern allows us to use ReferenceEquals a.k.a == + // since logger names are already interned by LogImpl + _loggerNames = settings.LoggerNames.Select(string.Intern).ToArray(); } if (settings.LogLevels != null) { @@ -39,13 +40,29 @@ internal Filter(FilterSettings settings) internal bool IsMatch(ref MTLoggerMessageDto messageDto) { - if (_loggerNames != null && !_loggerNames.Contains(messageDto.LoggerName)) + if (_loggerNames != null) { + foreach (var loggerName in _loggerNames) + { + if (loggerName == messageDto.LoggerName) + { + return true; + } + } + return false; } - if (_logLevels != null && !_logLevels.Contains(messageDto.LogLevel)) + if (_logLevels != null) { + foreach (var logLevel in _logLevels) + { + if (logLevel == messageDto.LogLevel) + { + return true; + } + } + return false; } diff --git a/ModTek/Features/Logging/Formatter.cs b/ModTek/Features/Logging/Formatter.cs index 48e23ac..e7b6e2f 100644 --- a/ModTek/Features/Logging/Formatter.cs +++ b/ModTek/Features/Logging/Formatter.cs @@ -1,5 +1,5 @@ using System; -using System.Globalization; +using System.Text; using HBS.Logging; namespace ModTek.Features.Logging; @@ -27,7 +27,7 @@ internal Formatter(AppenderSettings settings) internal int GetFormattedLogLine(ref MTLoggerMessageDto messageDto, out byte[] bytes) { s_buffer ??= new FastBuffer(); - s_buffer.Clear(); + s_buffer.Setup(); if (_absoluteTimeEnabled) { @@ -36,62 +36,53 @@ internal int GetFormattedLogLine(ref MTLoggerMessageDto messageDto, out byte[] b { dt = dt.ToLocalTime(); } - s_buffer.AppendLast2Digits(dt.Hour); - s_buffer.Append(':'); - s_buffer.AppendLast2Digits(dt.Minute); - s_buffer.Append(':'); - s_buffer.AppendLast2Digits(dt.Second); - s_buffer.Append('.'); - s_buffer.AppendLast7Digits(dt.Ticks); - s_buffer.Append(' '); + s_buffer.Append(dt); } if (_startupTimeEnabled) { var ts = messageDto.StartupTime(); var secondsWithFraction = ts.Ticks * 1E-07m; - s_buffer.Append(secondsWithFraction.ToString(CultureInfo.InvariantCulture)); - s_buffer.Append(' '); + s_buffer.Append(secondsWithFraction); + s_buffer.Append((byte)' '); } if (messageDto.ThreadId != s_unityMainThreadId) { - s_buffer.Append("[ThreadId="); - s_buffer.Append(messageDto.ThreadId.ToString(CultureInfo.InvariantCulture)); - s_buffer.Append("] "); + 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 s_buffer.Append(messageDto.LoggerName); - s_buffer.Append(' '); - s_buffer.Append('['); - s_buffer.Append(LogLevelExtension.LogToString(messageDto.LogLevel)); - s_buffer.Append(']'); + s_buffer.Append(LogLevelExtension.GetCachedFormattedBytes(messageDto.LogLevel)); - var prefix = " "; + var prefix = s_whitespaceBytes; if (!string.IsNullOrEmpty(messageDto.Message)) { s_buffer.Append(prefix); s_buffer.Append(messageDto.Message); - prefix = Environment.NewLine; + prefix = s_environmentNewline; } if (messageDto.Exception != null) { s_buffer.Append(prefix); s_buffer.Append(messageDto.Exception.ToString()); - prefix = Environment.NewLine; + prefix = s_environmentNewline; } if (messageDto.Location != null) { s_buffer.Append(prefix); - s_buffer.Append("Location Trace"); - s_buffer.Append(Environment.NewLine); + s_buffer.Append(s_locationTraceLabel); + s_buffer.Append(s_environmentNewline); s_buffer.Append(GetLocationString(messageDto.Location)); } - s_buffer.Append(Environment.NewLine); + s_buffer.Append(s_environmentNewline); return s_buffer.GetBytes(out bytes); } @@ -111,4 +102,11 @@ private static string GetLocationString(IStackTrace st) return e.ToString(); } } + + // avoid heap allocations during logging + private static readonly byte[] s_threadIdPrefix = Encoding.UTF8.GetBytes("[ThreadId="); + private static readonly byte[] s_threadIdSuffix = Encoding.UTF8.GetBytes("] "); + private static readonly byte[] s_whitespaceBytes = Encoding.UTF8.GetBytes(" "); + private static readonly byte[] s_environmentNewline = Encoding.UTF8.GetBytes(Environment.NewLine); + private static readonly byte[] s_locationTraceLabel = Encoding.UTF8.GetBytes("Location Trace"); } \ No newline at end of file diff --git a/ModTek/Features/Logging/LogLevelExtension.cs b/ModTek/Features/Logging/LogLevelExtension.cs index 88ab6ec..d8f5c44 100644 --- a/ModTek/Features/Logging/LogLevelExtension.cs +++ b/ModTek/Features/Logging/LogLevelExtension.cs @@ -1,26 +1,46 @@ using System; +using System.Text; using HBS.Logging; namespace ModTek.Features.Logging; internal static class LogLevelExtension { - internal static string LogToString(LogLevel level) + private static readonly byte[] s_trace = GetFormattedBytes(ELogLevels.Trace); + private static readonly byte[] s_debug = GetFormattedBytes(ELogLevels.Debug); + private static readonly byte[] s_log = GetFormattedBytes(ELogLevels.Log); + private static readonly byte[] s_warning = GetFormattedBytes(ELogLevels.Warning); + private static readonly byte[] s_error = GetFormattedBytes(ELogLevels.Error); + private static readonly byte[] s_fatal = GetFormattedBytes(ELogLevels.Fatal); + private static readonly byte[] s_off = GetFormattedBytes(ELogLevels.OFF); + private static byte[] GetFormattedBytes(ELogLevels level) => Encoding.UTF8.GetBytes(" [" + ELogToString(level) + "]"); + // avoid allocations during logging + internal static byte[] GetCachedFormattedBytes(LogLevel level) { var eLogLevel = Convert(level); return eLogLevel switch // fast switch with static string, in order of most occuring { - ELogLevels.Trace => "TRACE", - ELogLevels.Debug => "DEBUG", - ELogLevels.Log => "LOG", - ELogLevels.Warning => "WARNING", - ELogLevels.Error => "ERROR", - ELogLevels.Fatal => "FATAL", - ELogLevels.OFF => "OFF", + ELogLevels.Trace => s_trace, + ELogLevels.Debug => s_debug, + ELogLevels.Log => s_log, + ELogLevels.Warning => s_warning, + ELogLevels.Error => s_error, + ELogLevels.Fatal => s_fatal, + ELogLevels.OFF => s_off, _ => throw new ArgumentOutOfRangeException() }; } + internal static string LogToString(LogLevel level) + { + var eLogLevel = Convert(level); + return ELogToString(eLogLevel); + } + private static string ELogToString(ELogLevels eLogLevel) + { + return eLogLevel.ToString().ToUpperInvariant(); + } + internal static bool IsLogLevelGreaterThan(LogLevel loggerLevel, LogLevel messageLevel) { return Convert(messageLevel) >= Convert(loggerLevel); diff --git a/ModTek/Features/Logging/LogStreamImpl/MonoIoFileStreamImpl.cs b/ModTek/Features/Logging/LogStreamImpl/MonoIoFileStreamImpl.cs index a5a9487..361fcfa 100644 --- a/ModTek/Features/Logging/LogStreamImpl/MonoIoFileStreamImpl.cs +++ b/ModTek/Features/Logging/LogStreamImpl/MonoIoFileStreamImpl.cs @@ -1,5 +1,4 @@ -using System; -using System.IO; +using System.IO; namespace ModTek.Features.Logging.LogStreamImpl; @@ -24,51 +23,9 @@ internal MonoIoFileStreamImpl(string path) public void Append(byte[] bytes, int srcOffset, int count) { - // skip check as our logging never logs less - //EnsureMinimumSize(ref bytes, ref srcOffset, ref count); - _stream.Write(bytes, srcOffset, count); } - private const byte Linefeed = (byte)'\n'; - private const int ZeroWidthSize = 3; // ZWSP is unfortunately 3 bytes and not 2 in UTF8 - private const int ZeroWidthWithNewlineSize = 4; - private static readonly byte[] s_zeroWidthSpaceWithNewline = [0xE2, 0x80, 0x8B, Linefeed]; - private static void EnsureMinimumSize(ref byte[] bytes, ref int srcOffset, ref int count) - { - // the buffer within FileStream is never thread safe - // to avoid it we always have to write at least 2 bytes - if (count >= 2) - { - return; - } - - if (count > 0) - { - if (count == 1 && bytes[srcOffset] == Linefeed) // linux WriteLine() - { - bytes = s_zeroWidthSpaceWithNewline; - srcOffset = 0; - count = ZeroWidthWithNewlineSize; - } - else - { - var newBytes = new byte[ZeroWidthSize + count]; - Buffer.BlockCopy(s_zeroWidthSpaceWithNewline, 0, newBytes, 0, ZeroWidthSize); - Buffer.BlockCopy(bytes, srcOffset, newBytes, ZeroWidthSize, count); - bytes = newBytes; - srcOffset = 0; - count = ZeroWidthSize + count; - } - } - else - { - bytes = s_zeroWidthSpaceWithNewline; - srcOffset = 0; - count = ZeroWidthSize; - } - } - public void FlushToDisk() { _stream.Flush(true); diff --git a/ModTek/Features/Logging/MTLoggerAsyncQueue.cs b/ModTek/Features/Logging/MTLoggerAsyncQueue.cs index 7e3450d..a2bb0cb 100644 --- a/ModTek/Features/Logging/MTLoggerAsyncQueue.cs +++ b/ModTek/Features/Logging/MTLoggerAsyncQueue.cs @@ -1,5 +1,4 @@ using System; -using System.Text; using System.Threading; using UnityEngine; using ThreadPriority = System.Threading.ThreadPriority; @@ -47,22 +46,18 @@ internal MTLoggerAsyncQueue(IMessageProcessor processor) var latencyStats = MTLoggerMessageDto.LatencyStopWatch.GetStats(); var dtoStats = LoggingFeature.MessageSetupStopWatch.GetStats(); - var flushStats = AppenderFile.FlushStopWatch.GetStats(); - var filterStats = AppenderFile.FiltersStopWatch.GetStats(); - var formatterStats = AppenderFile.FormatterStopWatch.GetStats(); - var writeStats = AppenderFile.WriteStopwatch.GetStats(); logger.Log( $""" Asynchronous logging offloaded {offloadedTime} from the main thread. - Flushed explicitly {flushStats.Count} times for a total of {flushStats.TotalTime} and an average of {flushStats.AverageNanoseconds}ns. + Flushed {AppenderFile.FlushStopWatch.GetStats()}. End-to-end processing had an average latency of {latencyStats.AverageNanoseconds / 1_000_000}ms. On-thread processing took a total of {dtoStats.TotalTime} with an average of {dtoStats.AverageNanoseconds}ns. - Dispatched {dispatchStats.Count} times, taking a total of {dispatchStats.TotalTime} with an average of {dispatchStats.AverageNanoseconds}ns. + Dispatch {dispatchStats}. Off-thread processing took a total of {stats.TotalTime} with an average of {stats.AverageNanoseconds}ns. - Filters took a total of {filterStats.TotalTime} with an average of {filterStats.AverageNanoseconds}ns. - Formatter took a total of {formatterStats.TotalTime} with an average of {formatterStats.AverageNanoseconds}ns. - Write called {writeStats.Count} times, taking a total of {writeStats.TotalTime} with an average of {writeStats.AverageNanoseconds}ns. + Filters {AppenderFile.FiltersStopWatch.GetStats()}. + Formatter {AppenderFile.FormatterStopWatch.GetStats()}. + Write {AppenderFile.WriteStopwatch.GetStats()}. """ ); }, diff --git a/ModTek/Features/Logging/MTStopwatch.cs b/ModTek/Features/Logging/MTStopwatch.cs index 1cb9695..1290498 100644 --- a/ModTek/Features/Logging/MTStopwatch.cs +++ b/ModTek/Features/Logging/MTStopwatch.cs @@ -8,6 +8,7 @@ internal class MTStopwatch { internal Action Callback { get; set; } internal long CallbackForEveryNumberOfMeasurements { get; set; } = 100; + internal long SkipFirstNumberOfMeasurements { get; set; } = 1000; // let's wait for the JIT to warm up private long _ticks; private long _count; @@ -39,13 +40,17 @@ internal void Stop() internal void AddMeasurement(long elapsedTicks) { - var ticks = Interlocked.Add(ref _ticks, elapsedTicks); var count = Interlocked.Increment(ref _count); + if (count <= SkipFirstNumberOfMeasurements) + { + return; + } + var ticks = Interlocked.Add(ref _ticks, elapsedTicks); if (Callback != null) { if (count % CallbackForEveryNumberOfMeasurements == 0) { - Callback.Invoke(new Stats(ticks, count)); + Callback.Invoke(new Stats(this, ticks, count)); } } } @@ -70,18 +75,23 @@ internal readonly struct Stats internal long Ticks { get; } internal long Count { get; } internal TimeSpan TotalTime => TimeSpanFromTicks(Ticks); - internal long AverageNanoseconds => Count == 0 ? 0 : (long)((double)Ticks / Count / Stopwatch.Frequency * 1e+9); + internal long AverageNanoseconds => Count <= 0 ? 0 : (long)((double)Ticks / Count / Stopwatch.Frequency * 1e+9); internal Stats(MTStopwatch sw) { Ticks = Interlocked.Read(ref sw._ticks); - Count = Interlocked.Read(ref sw._count); + Count = Interlocked.Read(ref sw._count) - sw.SkipFirstNumberOfMeasurements; } - internal Stats(long ticks, long count) + internal Stats(MTStopwatch sw, long ticks, long count) { Ticks = ticks; - Count = count; + Count = count - sw.SkipFirstNumberOfMeasurements; + } + + public override string ToString() + { + return $"measured {Count} times, taking a total of {TotalTime} with an average of {AverageNanoseconds}ns"; } } diff --git a/ModTek/Features/Logging/Patches/LogImpl_set_Level_Patch.cs b/ModTek/Features/Logging/Patches/LogImpl_set_Level_Patch.cs index 638c024..f2b1533 100644 --- a/ModTek/Features/Logging/Patches/LogImpl_set_Level_Patch.cs +++ b/ModTek/Features/Logging/Patches/LogImpl_set_Level_Patch.cs @@ -21,18 +21,26 @@ public static void Prefix(LogLevel? ___level, out LogLevel? __state) [HarmonyPriority(Priority.Low)] public static void Postfix(string ___name, LogLevel? ___level, LogLevel? __state) { - if (___level != __state) + var log = Log.Main.Trace; + if (log == null) { - var debugText = ModTek.Config.Logging.DebugLogLevelSetters - ? "\n" + DebugUtils.GetStackTraceWithoutPatch() - : ""; - - var oldLevel = __state?.Let(l => LogLevelExtension.LogToString(l) + $"({(int)__state})") ?? "null"; - var newLevel = ___level?.Let(l => LogLevelExtension.LogToString(l) + $"({(int)___level})") ?? "null"; - Log.Main.Trace?.Log( - $"Log Level of logger name={___name} changed from level={oldLevel} to level={newLevel}{debugText}" - ); + return; } + + if (___level == __state) + { + return; + } + + var debugText = ModTek.Config.Logging.DebugLogLevelSetters + ? "\n" + DebugUtils.GetStackTraceWithoutPatch() + : ""; + + var oldLevel = __state?.Let(l => LogLevelExtension.LogToString(l) + $"({(int)__state})") ?? "null"; + var newLevel = ___level?.Let(l => LogLevelExtension.LogToString(l) + $"({(int)___level})") ?? "null"; + log.Log( + $"Log Level of logger name={___name} changed from level={oldLevel} to level={newLevel}{debugText}" + ); } private static R Let(this P s, Func func) where P: notnull