Skip to content

Commit

Permalink
Reduce heap allocation of the default log message formatting logic in…
Browse files Browse the repository at this point in the history
… the FileLogger.Log (#74)

* Reduce heap allocation of the default log message formatting logic in FileLogger.Log

* Hide TryFormat extensions under preprocessor directives for target frameworks greater than netstandard2.0

* Add tests for int and DateTime extensions, multi-target the test project to cover netstandard2.0

* Improve DateTimeExtensionsTests a tiny bit

* Tests: update .NET Framework target from net462 to net481
  • Loading branch information
aannenko authored Nov 18, 2024
1 parent 83558ad commit ef7c0f9
Show file tree
Hide file tree
Showing 10 changed files with 691 additions and 76 deletions.
80 changes: 80 additions & 0 deletions src/NReco.Logging.File/Extensions/DateTimeExtensions.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,80 @@
using System;

#nullable enable

namespace NReco.Logging.File.Extensions {
public static class DateTimeExtensions {

Check warning on line 6 in src/NReco.Logging.File/Extensions/DateTimeExtensions.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'DateTimeExtensions'
public static int GetFormattedLength(this DateTime dateTime) {

Check warning on line 7 in src/NReco.Logging.File/Extensions/DateTimeExtensions.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'DateTimeExtensions.GetFormattedLength(DateTime)'
const int BaseCharCountInFormatO = 27;

return BaseCharCountInFormatO + dateTime.Kind switch {
DateTimeKind.Local => 6,
DateTimeKind.Utc => 1,
_ => 0
};
}

#if NETSTANDARD2_0
public static bool TryFormatO(this DateTime dateTime, Span<char> destination, out int charsWritten) {
var charsRequired = dateTime.GetFormattedLength();

if (destination.Length < charsRequired) {
charsWritten = 0;
return false;
}

charsWritten = charsRequired;

var year = (uint)dateTime.Year;
var month = (uint)dateTime.Month;
var day = (uint)dateTime.Day;
var hour = (uint)dateTime.Hour;
var minute = (uint)dateTime.Minute;
var second = (uint)dateTime.Second;
var tick = (uint)(dateTime.Ticks - (dateTime.Ticks / TimeSpan.TicksPerSecond * TimeSpan.TicksPerSecond));

year.WriteDigits(destination, 4);
destination[4] = '-';
month.WriteDigits(destination.Slice(5), 2);
destination[7] = '-';
day.WriteDigits(destination.Slice(8), 2);
destination[10] = 'T';
hour.WriteDigits(destination.Slice(11), 2);
destination[13] = ':';
minute.WriteDigits(destination.Slice(14), 2);
destination[16] = ':';
second.WriteDigits(destination.Slice(17), 2);
destination[19] = '.';
tick.WriteDigits(destination.Slice(20), 7);

var kind = dateTime.Kind;
if (kind == DateTimeKind.Local) {
var offset = TimeZoneInfo.Local.GetUtcOffset(dateTime);
var offsetTotalMinutes = (int)(offset.Ticks / TimeSpan.TicksPerMinute);

var sign = '+';
if (offsetTotalMinutes < 0) {
sign = '-';
offsetTotalMinutes = -offsetTotalMinutes;
}

var offsetHours = Math.DivRem(offsetTotalMinutes, 60, out var offsetMinutes);

destination[27] = sign;
((uint)offsetHours).WriteDigits(destination.Slice(28), 2);
destination[30] = ':';
((uint)offsetMinutes).WriteDigits(destination.Slice(31), 2);
}
else if (kind == DateTimeKind.Utc) {
destination[27] = 'Z';
}

return true;
}
#else
public static bool TryFormatO(this DateTime dateTime, Span<char> destination, out int charsWritten) {

Check warning on line 75 in src/NReco.Logging.File/Extensions/DateTimeExtensions.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'DateTimeExtensions.TryFormatO(DateTime, Span<char>, out int)'
return dateTime.TryFormat(destination, out charsWritten, format: "O");
}
#endif
}
}
41 changes: 41 additions & 0 deletions src/NReco.Logging.File/Extensions/IntExtensions.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
using System;

#nullable enable

namespace NReco.Logging.File.Extensions {
public static class IntExtensions {

Check warning on line 6 in src/NReco.Logging.File/Extensions/IntExtensions.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'IntExtensions'
public static int GetFormattedLength(this int value) {

Check warning on line 7 in src/NReco.Logging.File/Extensions/IntExtensions.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'IntExtensions.GetFormattedLength(int)'
return value == 0 ? 1 : (int)Math.Floor(Math.Log10(Math.Abs((double)value))) + (value > 0 ? 1 : 2);
}

#if NETSTANDARD2_0
public static bool TryFormat(this int value, Span<char> destination, out int charsWritten) {
charsWritten = value.GetFormattedLength();
if (destination.Length < charsWritten) {
charsWritten = 0;
return false;
}

var dst = destination.Slice(0, charsWritten);

if (value < 0) {
dst[0] = '-';
dst = dst.Slice(1);
}

((uint)Math.Abs((long)value)).WriteDigits(dst, dst.Length);
return true;
}

internal static void WriteDigits(this uint value, Span<char> destination, int count) {
for (var cur = count - 1; cur > 0; cur--) {
uint temp = '0' + value;
value /= 10;
destination[cur] = (char)(temp - (value * 10));
}

destination[0] = (char)('0' + value);
}
#endif
}
}
117 changes: 72 additions & 45 deletions src/NReco.Logging.File/FileLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
* NReco file logging provider (https://github.com/nreco/logging)
* Copyright 2017 Vitaliy Fedorchenko
* Distributed under the MIT license
*
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
Expand All @@ -13,16 +13,11 @@
#endregion

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using System.IO;
using System.Collections.Concurrent;
using System.Buffers;
using System.Text;

using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Configuration;

using NReco.Logging.File.Extensions;
namespace NReco.Logging.File {

/// <summary>
Expand All @@ -46,21 +41,16 @@ public bool IsEnabled(LogLevel logLevel) {
}

string GetShortLogLevel(LogLevel logLevel) {
switch (logLevel) {
case LogLevel.Trace:
return "TRCE";
case LogLevel.Debug:
return "DBUG";
case LogLevel.Information:
return "INFO";
case LogLevel.Warning:
return "WARN";
case LogLevel.Error:
return "FAIL";
case LogLevel.Critical:
return "CRIT";
}
return logLevel.ToString().ToUpper();
return logLevel switch {
LogLevel.Trace => "TRCE",
LogLevel.Debug => "DBUG",
LogLevel.Information => "INFO",
LogLevel.Warning => "WARN",
LogLevel.Error => "FAIL",
LogLevel.Critical => "CRIT",
LogLevel.None => "NONE",
_ => logLevel.ToString().ToUpper(),
};
}

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state,

Check warning on line 56 in src/NReco.Logging.File/FileLogger.cs

View workflow job for this annotation

GitHub Actions / build

Missing XML comment for publicly visible type or member 'FileLogger.Log<TState>(LogLevel, EventId, TState, Exception, Func<TState, Exception, string>)'
Expand All @@ -79,34 +69,71 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state,
if (!LoggerPrv.Options.FilterLogEntry(new LogMessage(logName, logLevel, eventId, message, exception)))
return;

if (LoggerPrv.FormatLogEntry!=null) {
if (LoggerPrv.FormatLogEntry != null) {
LoggerPrv.WriteEntry(LoggerPrv.FormatLogEntry(
new LogMessage(logName, logLevel, eventId, message, exception)));
} else {
// default formatting logic
var logBuilder = new StringBuilder();
if (!string.IsNullOrEmpty(message)) {
DateTime timeStamp = LoggerPrv.UseUtcTimestamp ? DateTime.UtcNow : DateTime.Now;
logBuilder.Append(timeStamp.ToString("o"));
logBuilder.Append('\t');
logBuilder.Append(GetShortLogLevel(logLevel));
logBuilder.Append("\t[");
logBuilder.Append(logName);
logBuilder.Append("]");
logBuilder.Append("\t[");
logBuilder.Append(eventId);
logBuilder.Append("]\t");
logBuilder.Append(message);
}
else {
const int MaxStackAllocatedBufferLength = 256;
DateTime timeStamp = LoggerPrv.UseUtcTimestamp ? DateTime.UtcNow : DateTime.Now;
var logMessageLength = CalculateLogMessageLength(timeStamp, eventId, message);
char[] charBuffer = null;
try {
Span<char> buffer = logMessageLength <= MaxStackAllocatedBufferLength
? stackalloc char[MaxStackAllocatedBufferLength]
: (charBuffer = ArrayPool<char>.Shared.Rent(logMessageLength));

FormatLogEntryDefault(buffer, timeStamp, message, logLevel, eventId, exception);
}

if (exception != null) {
// exception message
logBuilder.AppendLine(exception.ToString());
finally {
if (charBuffer is not null) {
ArrayPool<char>.Shared.Return(charBuffer);
}
}
LoggerPrv.WriteEntry(logBuilder.ToString());
}
}
}

private void FormatLogEntryDefault(Span<char> buffer, DateTime timeStamp, string message,
LogLevel logLevel, EventId eventId, Exception exception) {
// default formatting logic
using var logBuilder = new ValueStringBuilder(buffer);
if (!string.IsNullOrEmpty(message)) {
timeStamp.TryFormatO(logBuilder.RemainingRawChars, out var charsWritten);
logBuilder.AppendSpan(charsWritten);
logBuilder.Append('\t');
logBuilder.Append(GetShortLogLevel(logLevel));
logBuilder.Append("\t[");
logBuilder.Append(logName);
logBuilder.Append("]\t[");
if (eventId.Name is not null) {
logBuilder.Append(eventId.Name);
}
else {
eventId.Id.TryFormat(logBuilder.RemainingRawChars, out charsWritten);
logBuilder.AppendSpan(charsWritten);
}
logBuilder.Append("]\t");
logBuilder.Append(message);
}

if (exception != null) {
// exception message
logBuilder.Append(exception.ToString());
logBuilder.Append(Environment.NewLine);
}
LoggerPrv.WriteEntry(logBuilder.ToString());
}

private int CalculateLogMessageLength(DateTime timeStamp, EventId eventId, string message) {
return timeStamp.GetFormattedLength()
+ 1 /* '\t' */
+ 4 /* GetShortLogLevel */
+ 2 /* "\t[" */
+ (logName?.Length ?? 0)
+ 3 /* "]\t[" */
+ (eventId.Name?.Length ?? eventId.Id.GetFormattedLength())
+ 2 /* "]\t" */
+ (message?.Length ?? 0);
}
}
}
6 changes: 2 additions & 4 deletions src/NReco.Logging.File/LogMessage.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
* NReco file logging provider (https://github.com/nreco/logging)
* Copyright 2017 Vitaliy Fedorchenko
* Distributed under the MIT license
*
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
Expand All @@ -13,13 +13,11 @@
#endregion

using System;
using System.Collections.Generic;
using System.Text;
using Microsoft.Extensions.Logging;

namespace NReco.Logging.File {

public struct LogMessage {
public readonly struct LogMessage {
public readonly string LogName;
public readonly string Message;
public readonly LogLevel LogLevel;
Expand Down
23 changes: 12 additions & 11 deletions src/NReco.Logging.File/NReco.Logging.File.csproj
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,12 @@

<PropertyGroup>
<Description>Lightweight file logging provider implementation for NET6 / NET8+ / .NET Core without dependencies on logging frameworks.

How to use:

using NReco.Logging.File;

services.AddLogging(loggingBuilder => {
services.AddLogging(loggingBuilder =&gt; {
loggingBuilder.AddFile("app.log", append:true);
});

Expand All @@ -19,6 +19,7 @@ More details and examples: https://github.com/nreco/logging
<VersionPrefix>1.2.1</VersionPrefix>
<Authors>Vitalii Fedorchenko</Authors>
<TargetFrameworks>netstandard2.0;net6.0;net8.0</TargetFrameworks>
<LangVersion>12.0</LangVersion>
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<AssemblyName>NReco.Logging.File</AssemblyName>
<PackageId>NReco.Logging.File</PackageId>
Expand All @@ -27,10 +28,10 @@ More details and examples: https://github.com/nreco/logging
<PackageProjectUrl>https://github.com/nreco/logging</PackageProjectUrl>
<PackageLicenseUrl>https://raw.githubusercontent.com/nreco/logging/master/LICENSE</PackageLicenseUrl>
<PackageReleaseNotes>How to use: https://github.com/nreco/logging

Version 1.2.1 changes:
- Added different rolling name conventions #66 (unix-style is supported with 'Descending' convention)

Version 1.2.0 changes:
- NReco's FileLoggerExtensions should NOT be in the Microsoft.Extensions.Logging namespace #61
- Added net6 and net8 builds to reference appropriate Microsoft.Logging.Extensions versions
Expand Down Expand Up @@ -65,7 +66,7 @@ Version 1.1.0 changes:
Version 1.0.5 changes:
- log file folder is created automatically if not exists
- environment variables are expanded in the file path

Version 1.0.4 changes:
- added "File" provider alias for MVC Core 2 filtering rules
- added 'rolling file' behaviour controlled with new FileLoggerProvider properties (FileSizeLimitBytes and MaxRollingFiles)</PackageReleaseNotes>
Expand All @@ -81,11 +82,11 @@ Version 1.0.4 changes:
<SignAssembly>false</SignAssembly>
<AssemblyOriginatorKeyFile>NReco.Logging.File.snk</AssemblyOriginatorKeyFile>
</PropertyGroup>

<ItemGroup Condition="'$(TargetFramework)' == 'netstandard2.0'">
<PackageReference Include="Microsoft.Extensions.Logging" Version="3.*" />
<PackageReference Include="Microsoft.Extensions.Logging.Configuration" Version="3.*" />
<PackageReference Include="Microsoft.Extensions.Options.ConfigurationExtensions" Version="3.*" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.*" />
<PackageReference Include="Microsoft.Extensions.Logging.Configuration" Version="8.0.*" />
<PackageReference Include="Microsoft.Extensions.Options.ConfigurationExtensions" Version="8.0.*" />
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' == 'net6.0'">
Expand All @@ -97,7 +98,7 @@ Version 1.0.4 changes:
<ItemGroup Condition="'$(TargetFramework)' == 'net8.0'">
<PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.*" />
<PackageReference Include="Microsoft.Extensions.Logging.Configuration" Version="8.0.*" />
<PackageReference Include="Microsoft.Extensions.Options.ConfigurationExtensions" Version="8.0.*" />
<PackageReference Include="Microsoft.Extensions.Options.ConfigurationExtensions" Version="8.0.*" />
</ItemGroup>

</Project>
Loading

0 comments on commit ef7c0f9

Please sign in to comment.