Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 6 commits into from
Nov 18, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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) {
Copy link
Contributor Author

@aannenko aannenko Nov 9, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 @@ -33,37 +28,32 @@
private readonly string logName;
private readonly FileLoggerProvider LoggerPrv;

public FileLogger(string logName, FileLoggerProvider loggerPrv) {

Check warning on line 31 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.FileLogger(string, FileLoggerProvider)'
this.logName = logName;
this.LoggerPrv = loggerPrv;
}
public IDisposable BeginScope<TState>(TState state) {

Check warning on line 35 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.BeginScope<TState>(TState)'
return null;
}

public bool IsEnabled(LogLevel logLevel) {

Check warning on line 39 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.IsEnabled(LogLevel)'
return logLevel>=LoggerPrv.MinLevel;
}

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>)'
Exception exception, Func<TState, Exception, string> formatter) {
if (!IsEnabled(logLevel)) {
return;
Expand All @@ -79,34 +69,71 @@
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'">
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All these packages in their version 8 are compiled for netstandard2.0, net6.0 and net8.0, so there's no need to create branches for separate frameworks.

<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
Loading