Skip to content

Commit ae8a9ef

Browse files
NikolayPianikovNikolayPianikov
committed
Merge commit '1653ec031635ef07deb3383ea34360f4427a98fc' into dev
# Conflicts: # src/Matrix.Logging/Log4NetFixture.cs # src/Matrix.Logging/LoggingChecks.cs # src/Matrix.Logging/LoggingData.cs
2 parents 2089175 + 1653ec0 commit ae8a9ef

12 files changed

Lines changed: 262 additions & 8 deletions

File tree

‎.gitignore‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,3 +62,5 @@ nunit-*.xml
6262

6363
# Temporary BenchmarkDotNet output from older runs
6464
/reports/DependencyInjection/raw/
65+
/.vs
66+
*.user

‎metadata/Logging/features.json‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,12 @@
4848
"order": 8,
4949
"name": "Create Logger",
5050
"description": "Creates, verifies, and releases one Information-enabled logger with an in-memory sink."
51+
},
52+
{
53+
"id": "FileAppend",
54+
"order": 9,
55+
"name": "File Append",
56+
"description": "Appends one event to an already open file with buffering enabled and no flush per event."
5157
}
5258
]
5359
}

‎src/Matrix.Logging/Benchmarks/Common/09_FileAppend.cs‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
namespace Matrix.Logging.Benchmarks;
2+
3+
[MemoryDiagnoser]
4+
[Orderer(SummaryOrderPolicy.FastestToSlowest)]
5+
[FeatureUnavailable(
6+
LibraryCatalog.MicrosoftExtensionsLogging,
7+
FeatureStatus.Unsupported,
8+
"Microsoft.Extensions.Logging defines no file provider in the core package.")]
9+
[MatrixFeature(
10+
"FileAppend",
11+
9,
12+
"File Append",
13+
"Appends one event to an already open file with buffering enabled and no flush per event.")]
14+
public partial class FileAppend
15+
{
16+
private static readonly string _workDirectory =
17+
Path.Combine(Path.GetTempPath(), "matrix-logging-fileappend");
18+
19+
private static string CreateFilePath(string library)
20+
{
21+
Directory.CreateDirectory(_workDirectory);
22+
return Path.Combine(_workDirectory, $"{library}.{Guid.NewGuid():N}.log");
23+
}
24+
25+
/// <summary>
26+
/// Reads the file back once every arm has closed its writer, so delivery is validated against
27+
/// what actually reached the disk rather than against an in-memory sink.
28+
/// </summary>
29+
private static void Verify(string library, string path)
30+
{
31+
string[] lines = File.Exists(path) ? File.ReadAllLines(path) : [];
32+
LoggingChecks.FileAppended(
33+
library,
34+
lines.Length,
35+
lines.Length == 0 ? null : lines[^1]);
36+
37+
try
38+
{
39+
File.Delete(path);
40+
}
41+
catch (IOException)
42+
{
43+
// Each arm closes its writer before this runs, so this is unexpected - but a leftover
44+
// file in the temp directory is not worth failing a benchmark over.
45+
}
46+
}
47+
}

‎src/Matrix.Logging/Benchmarks/Log4Net/03_StructuredProperties.cs‎

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -18,8 +18,13 @@ public partial class StructuredProperties
1818
[LibraryBenchmark(LibraryCatalog.Log4Net)]
1919
public void Log4Net()
2020
{
21-
LogicalThreadContext.Properties["OrderId"] = LoggingData.OrderId;
22-
LogicalThreadContext.Properties["ElapsedMs"] = LoggingData.ElapsedMs;
21+
// ThreadContext rather than LogicalThreadContext: the other arms of this feature pass
22+
// structured parameters straight to the logger and use no ambient context at all, so the
23+
// async-flow-safe variant would charge log4net for propagation nobody else pays for. The
24+
// ScopeOrContext feature is where async-safe context belongs, and it still uses
25+
// LogicalThreadContext there, matching Serilog's LogContext.
26+
ThreadContext.Properties["OrderId"] = LoggingData.OrderId;
27+
ThreadContext.Properties["ElapsedMs"] = LoggingData.ElapsedMs;
2328
try
2429
{
2530
_log4Net.Logger.InfoFormat(
@@ -30,8 +35,8 @@ public void Log4Net()
3035
}
3136
finally
3237
{
33-
LogicalThreadContext.Properties.Remove("OrderId");
34-
LogicalThreadContext.Properties.Remove("ElapsedMs");
38+
ThreadContext.Properties.Remove("OrderId");
39+
ThreadContext.Properties.Remove("ElapsedMs");
3540
}
3641

3742
LoggingChecks.Structured(LibraryCatalog.Log4Net, _log4Net.Sink.Last);

‎src/Matrix.Logging/Benchmarks/Log4Net/09_FileAppend.cs‎

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
using log4net;
2+
using log4net.Appender;
3+
using log4net.Config;
4+
using log4net.Core;
5+
using log4net.Layout;
6+
using log4net.Repository.Hierarchy;
7+
8+
namespace Matrix.Logging.Benchmarks;
9+
10+
public partial class FileAppend
11+
{
12+
private string _log4NetPath = null!;
13+
private string _log4NetRepository = null!;
14+
private FileAppender _log4NetAppender = null!;
15+
private ILog _log4NetLogger = null!;
16+
17+
[GlobalSetup(Target = nameof(Log4Net))]
18+
public void SetupLog4Net()
19+
{
20+
_log4NetPath = CreateFilePath(LibraryCatalog.Log4Net);
21+
_log4NetRepository = $"{LoggingData.Category}.{Guid.NewGuid():N}";
22+
var repository = (Hierarchy)LogManager.CreateRepository(_log4NetRepository);
23+
_log4NetAppender = new FileAppender
24+
{
25+
File = _log4NetPath,
26+
AppendToFile = true,
27+
ImmediateFlush = false,
28+
Layout = new PatternLayout(LoggingData.Log4NetFileLayout)
29+
};
30+
_log4NetAppender.ActivateOptions();
31+
BasicConfigurator.Configure(repository, _log4NetAppender);
32+
repository.Root.Level = Level.Info;
33+
repository.Configured = true;
34+
_log4NetLogger = LogManager.GetLogger(_log4NetRepository, LoggingData.Category);
35+
}
36+
37+
[GlobalCleanup(Target = nameof(Log4Net))]
38+
public void CleanupLog4Net()
39+
{
40+
_log4NetAppender.Close();
41+
LogManager.ShutdownRepository(_log4NetRepository);
42+
Verify(LibraryCatalog.Log4Net, _log4NetPath);
43+
}
44+
45+
[Benchmark]
46+
[LibraryBenchmark(LibraryCatalog.Log4Net)]
47+
public void Log4Net() => _log4NetLogger.Info(LoggingData.FileMessage);
48+
}

‎src/Matrix.Logging/Benchmarks/NLog/09_FileAppend.cs‎

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,42 @@
1+
using NLog;
2+
using NLog.Config;
3+
using NLog.Targets;
4+
5+
namespace Matrix.Logging.Benchmarks;
6+
7+
public partial class FileAppend
8+
{
9+
private string _nlogPath = null!;
10+
private LogFactory _nlogFactory = null!;
11+
private Logger _nlogLogger = null!;
12+
13+
[GlobalSetup(Target = nameof(NLog))]
14+
public void SetupNLog()
15+
{
16+
_nlogPath = CreateFilePath(LibraryCatalog.NLog);
17+
var target = new FileTarget
18+
{
19+
FileName = _nlogPath,
20+
KeepFileOpen = true,
21+
AutoFlush = false,
22+
Layout = LoggingData.NLogFileLayout
23+
};
24+
var configuration = new LoggingConfiguration();
25+
configuration.AddRule(LogLevel.Info, LogLevel.Fatal, target, LoggingData.Category);
26+
_nlogFactory = new LogFactory { Configuration = configuration };
27+
_nlogLogger = _nlogFactory.GetLogger(LoggingData.Category);
28+
}
29+
30+
[GlobalCleanup(Target = nameof(NLog))]
31+
public void CleanupNLog()
32+
{
33+
_nlogFactory.Flush(TimeSpan.FromSeconds(5));
34+
_nlogFactory.Shutdown();
35+
_nlogFactory.Dispose();
36+
Verify(LibraryCatalog.NLog, _nlogPath);
37+
}
38+
39+
[Benchmark]
40+
[LibraryBenchmark(LibraryCatalog.NLog)]
41+
public void NLog() => _nlogLogger.Info(LoggingData.FileMessage);
42+
}

‎src/Matrix.Logging/Benchmarks/Serilog/09_FileAppend.cs‎

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,36 @@
1+
using Serilog;
2+
using Serilog.Events;
3+
4+
namespace Matrix.Logging.Benchmarks;
5+
6+
public partial class FileAppend
7+
{
8+
private string _serilogPath = null!;
9+
private Serilog.Core.Logger _serilogRoot = null!;
10+
private Serilog.ILogger _serilogLogger = null!;
11+
12+
[GlobalSetup(Target = nameof(Serilog))]
13+
public void SetupSerilog()
14+
{
15+
_serilogPath = CreateFilePath(LibraryCatalog.Serilog);
16+
_serilogRoot = new LoggerConfiguration()
17+
.MinimumLevel.Is(LogEventLevel.Information)
18+
.WriteTo.File(
19+
_serilogPath,
20+
buffered: true,
21+
outputTemplate: LoggingData.SerilogFileTemplate)
22+
.CreateLogger();
23+
_serilogLogger = _serilogRoot.ForContext("SourceContext", LoggingData.Category);
24+
}
25+
26+
[GlobalCleanup(Target = nameof(Serilog))]
27+
public void CleanupSerilog()
28+
{
29+
_serilogRoot.Dispose();
30+
Verify(LibraryCatalog.Serilog, _serilogPath);
31+
}
32+
33+
[Benchmark]
34+
[LibraryBenchmark(LibraryCatalog.Serilog)]
35+
public void Serilog() => _serilogLogger.Information(LoggingData.FileMessage);
36+
}

‎src/Matrix.Logging/Benchmarks/ZLogger/09_FileAppend.cs‎

Lines changed: 40 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,40 @@
1+
using Microsoft.Extensions.Logging;
2+
using ZLogger;
3+
4+
namespace Matrix.Logging.Benchmarks;
5+
6+
public partial class FileAppend
7+
{
8+
private string _zloggerPath = null!;
9+
private ILoggerFactory _zloggerFactory = null!;
10+
private ILogger _zloggerLogger = null!;
11+
12+
[GlobalSetup(Target = nameof(ZLogger))]
13+
public void SetupZLogger()
14+
{
15+
_zloggerPath = CreateFilePath(LibraryCatalog.ZLogger);
16+
_zloggerFactory = LoggerFactory.Create(builder =>
17+
{
18+
builder.ClearProviders();
19+
builder.SetMinimumLevel(LogLevel.Information);
20+
builder.AddZLoggerFile(_zloggerPath, options => options.UsePlainTextFormatter(formatter =>
21+
formatter.SetPrefixFormatter(
22+
$"{0:yyyy-MM-dd HH:mm:ss,fff} {1:short} {2} - ",
23+
(in MessageTemplate template, in LogInfo info) =>
24+
template.Format(info.Timestamp.Local.DateTime, info.LogLevel, info.Category))));
25+
});
26+
_zloggerLogger = _zloggerFactory.CreateLogger(LoggingData.Category);
27+
}
28+
29+
[GlobalCleanup(Target = nameof(ZLogger))]
30+
public void CleanupZLogger()
31+
{
32+
// Disposing the factory drains the background queue and closes the file.
33+
_zloggerFactory.Dispose();
34+
Verify(LibraryCatalog.ZLogger, _zloggerPath);
35+
}
36+
37+
[Benchmark]
38+
[LibraryBenchmark(LibraryCatalog.ZLogger)]
39+
public void ZLogger() => _zloggerLogger.LogInformation(LoggingData.FileMessage);
40+
}

‎src/Matrix.Logging/Log4NetFixture.cs‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -14,16 +14,22 @@ public Log4NetFixture(Level minimumLevel, bool buffered = false)
1414
{
1515
var repositoryName = $"{LoggingData.Category}.{Guid.NewGuid():N}";
1616
Repository = (Hierarchy)LogManager.CreateRepository(repositoryName);
17-
Sink = new Log4NetCaptureAppender();
17+
Sink = new();
1818
Sink.ActivateOptions();
1919
IAppender appender = Sink;
2020
if (buffered)
2121
{
22-
_buffer = new BufferingForwardingAppender
22+
_buffer = new()
2323
{
2424
BufferSize = LoggingData.BufferedCapacity,
25-
Fix = FixFlags.Partial,
26-
Lossy = false
25+
Lossy = false,
26+
// log4net defaults to FixFlags.All, which captures caller location (a stack walk)
27+
// and the Windows identity (a local security authority lookup) for every buffered
28+
// event. NLog's AsyncTargetWrapper and Serilog's WriteTo.Async capture neither, so
29+
// the default would charge log4net for work the other arms never do. Partial is the
30+
// set log4net's own FixFlags documentation recommends for performance, and it still
31+
// fixes everything this feature validates: message, level, exception and properties.
32+
Fix = FixFlags.Partial
2733
};
2834
_buffer.AddAppender(Sink);
2935
_buffer.ActivateOptions();

‎src/Matrix.Logging/LoggingChecks.cs‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,19 @@ public static void Buffered(string library, int count, CapturedLogEvent? actual)
5757
public static void Flush(string library, bool flushed) =>
5858
MatrixValidation.Require(library, flushed, "Buffered events did not flush in time.");
5959

60+
[Conditional("MATRIX_VALIDATION")]
61+
public static void FileAppended(string library, int lineCount, string? lastLine)
62+
{
63+
MatrixValidation.Require(
64+
library,
65+
lineCount == 3,
66+
$"Expected 3 appended lines, found {lineCount}.");
67+
MatrixValidation.Require(
68+
library,
69+
lastLine is not null && lastLine.EndsWith(LoggingData.FileMessage, StringComparison.Ordinal),
70+
$"Last appended line does not end with '{LoggingData.FileMessage}': '{lastLine}'.");
71+
}
72+
6073
[Conditional("MATRIX_VALIDATION")]
6174
public static void Prepared(string library, bool informationEnabled) =>
6275
MatrixValidation.Require(

0 commit comments

Comments
 (0)