diff --git a/.gitignore b/.gitignore index f1e3d20..b891e4a 100644 --- a/.gitignore +++ b/.gitignore @@ -250,3 +250,4 @@ paket-files/ # JetBrains Rider .idea/ *.sln.iml +BDN.Auto/ diff --git a/Bench.ps1 b/Bench.ps1 new file mode 100644 index 0000000..3dd58ee --- /dev/null +++ b/Bench.ps1 @@ -0,0 +1,18 @@ +echo "bench: Benchmarking started" + +Push-Location $PSScriptRoot + +& dotnet restore --no-cache + +foreach ($test in ls test/*.PerformanceTests) { + Push-Location $test + + echo "bench: Benchmarking project in $test" + + & dotnet test -c Release --framework net4.5.2 + if($LASTEXITCODE -ne 0) { exit 3 } + + Pop-Location +} + +Pop-Location diff --git a/README.md b/README.md index 7353103..3683188 100644 --- a/README.md +++ b/README.md @@ -1,40 +1,50 @@ -# Serilog.Sinks.Async [![Build status](https://ci.appveyor.com/api/projects/status/ewlh5x6xl4se5ech?svg=true)](https://ci.appveyor.com/project/JezzSantos/serilog-sinks-async) -An async Serilog sink +# Serilog.Sinks.Async [![Build status](https://ci.appveyor.com/api/projects/status/gvk0wl7aows14spn?svg=true)](https://ci.appveyor.com/project/serilog/serilog-sinks-async) [![NuGet](https://img.shields.io/nuget/vpre/Serilog.Sinks.Async.svg?maxAge=2592000)](https://www.nuget.org/packages/Serilog.Sinks.Async) [![Join the chat at https://gitter.im/serilog/serilog](https://img.shields.io/gitter/room/serilog/serilog.svg)](https://gitter.im/serilog/serilog) -Use this buffered, async, delegating, sink to reduce the time it takes for your app to write your log events to your sinks. This sink can work with any `IEventLogSink` you use. +An asynchronous wrapper for other [Serilog](https://serilog.net) sinks. Use this sink to reduce the overhead of logging calls by delegating work to a background thread. This is especially suited to non-batching sinks like the [File](https://github.com/serilog/serilog-sinks-file) and [RollingFile](https://github.com/serilog-serilog-sinks-rollingfile) sinks that may be affected by I/O bottlenecks. -Especially suited to sinks that are either slow to write or have I/O bottlenecks (like http, databases, file writes etc.). -This sink uses a separate thread pool thread to write to your sink, freeing up the calling thread to run in your app without having to wait. +**Note:** many of the network-based sinks (_CouchDB_, _Elasticsearch_, _MongoDB_, _Seq_, _Splunk_...) already perform asychronous batching natively and do not benefit from this wrapper. -Utilizes the producer/consumer pattern (using the TPL `BufferBlock` class), where the calling thread produces log events (on your main thread), and the consumer runs on a thread pool thread consuming log events and writing them to your sink. +### Getting started -Install from NuGet: +Install from [NuGet](https://nuget.org/packages/serilog.sinks.async): ```powershell -Install-Package Serilog.Sinks.Async +Install-Package Serilog.Sinks.Async -Pre ``` -Add this sink to your pipeline: +Assuming you have already installed the target sink, such as the rolling file sink, move the wrapped sink's configuration within a `WriteTo.Async()` statement: ```csharp Log.Logger = new LoggerConfiguration() - .WriteTo.Async(x => x.Sink(new YourSink())) + .WriteTo.Async(a => a.RollingFile("logs/myapp-{Date}.txt")) // Other logger configuration .CreateLogger() + +Log.Information("This will be written to disk on the worker thread"); + +// At application shutdown +Log.CloseAndFlush(); ``` -Now `YourSink` will write messages using another [thread pool] thread while your logging thread gets on with more important stuff. +The wrapped sink (`RollingFile` in this case) will be invoked on a worker thread while your application's thread gets on with more important stuff. + +Because the memory buffer may contain events that have not yet been written to the target sink, it is important to call `Log.CloseAndFlush()` or `Logger.Dispose()` when the application exits. + +### Buffering -If you think your code is producing log events faster than your sink can consume and write them, then the buffer is going to grow in memory, until you run out! -Set a maximum size of the buffer so that your memory is not filled up. -Buffered log events are then (async) postponed in your app thread until your sink catches up. +This sink uses a separate worker thread to write to your sink, freeing up the calling thread to run in your app without having to wait. + +The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. ```csharp -Log.Logger = new LoggerConfiguration() - .WriteTo.Async(x => x.Sink(new YourSink), 500) //Max number of logevents to buffer in memory - // Other logger configurationg - .CreateLogger() + // Reduce the buffer to 500 events + .WriteTo.Async(a => a.RollingFile("logs/myapp-{Date}.txt"), 500) ``` -## About this Sink -This sink was created by this conversation thread: https://github.com/serilog/serilog/issues/809 +### XML `` and JSON configuration + +XML and JSON configuration support has not yet been added for this wrapper. + +### About this sink + +This sink was created following this conversation thread: https://github.com/serilog/serilog/issues/809. diff --git a/serilog-sinks-async.sln b/serilog-sinks-async.sln index 782de6e..29c66c6 100644 --- a/serilog-sinks-async.sln +++ b/serilog-sinks-async.sln @@ -10,6 +10,7 @@ EndProject Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "global", "global", "{154C7C14-E737-40DF-A631-B1673FE76187}" ProjectSection(SolutionItems) = preProject appveyor.yml = appveyor.yml + Bench.ps1 = Bench.ps1 Build.ps1 = Build.ps1 global.json = global.json LICENSE = LICENSE diff --git a/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs b/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs index 9e50f70..40b6d72 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs @@ -1,52 +1,78 @@ using System; +using System.IO; using BenchmarkDotNet.Attributes; -using Serilog; using Serilog.Core; +using Serilog.Debugging; using Serilog.Events; using Serilog.Parsing; +using Serilog.Sinks.Async.PerformanceTests.Support; namespace Serilog.Sinks.Async.PerformanceTests { public class LatencyBenchmark { - private const int Count = 10000; - private readonly LogEvent _evt = new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, null, new MessageTemplate(new[] {new TextToken("Hello")}), new LogEventProperty[0]); - private Logger _syncLogger, _asyncLogger; + private Logger _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger; + + static LatencyBenchmark() + { + SelfLog.Enable(new TerminatingTextWriter()); + } [Setup] public void Reset() { - _syncLogger?.Dispose(); - _asyncLogger?.Dispose(); + foreach (var logger in new[] { _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger}) + { + logger?.Dispose(); + } + + foreach (var tmp in Directory.GetFiles(".", "*.tmplog")) + { + System.IO.File.Delete(tmp); + } _syncLogger = new LoggerConfiguration() .WriteTo.Sink(new SilentSink()) .CreateLogger(); _asyncLogger = new LoggerConfiguration() - .WriteTo.Async(a => a.Sink(new SilentSink())) + .WriteTo.Async(a => a.Sink(new SilentSink()), 10000000) + .CreateLogger(); + + _fileLogger = new LoggerConfiguration() + .WriteTo.File("sync-file.tmplog") + .CreateLogger(); + + _asyncFileLogger = new LoggerConfiguration() + .WriteTo.Async(a => a.File("async-file.tmplog"), 10000000) .CreateLogger(); } [Benchmark(Baseline = true)] public void Sync() { - for (var i = 0; i < Count; ++i) - { - _syncLogger.Write(_evt); - } + _syncLogger.Write(_evt); } [Benchmark] public void Async() { - for (var i = 0; i < Count; ++i) - { - _asyncLogger.Write(_evt); - } + _asyncLogger.Write(_evt); + } + + [Benchmark] + public void File() + { + _fileLogger.Write(_evt); + } + + [Benchmark] + public void AsyncFile() + { + _asyncFileLogger.Write(_evt); } } -} \ No newline at end of file +} diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs b/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs new file mode 100644 index 0000000..deae8ba --- /dev/null +++ b/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs @@ -0,0 +1,17 @@ +using System; +using System.IO; +using System.Text; + +namespace Serilog.Sinks.Async.PerformanceTests.Support +{ + public class TerminatingTextWriter : TextWriter + { + public override Encoding Encoding { get; } = Encoding.ASCII; + + public override void Write(char value) + { + Console.WriteLine("SelfLog triggered"); + Environment.Exit(1); + } + } +} \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/project.json b/test/Serilog.Sinks.Async.PerformanceTests/project.json index b706e14..5e76d51 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/project.json +++ b/test/Serilog.Sinks.Async.PerformanceTests/project.json @@ -3,6 +3,7 @@ "dependencies": { "Serilog.Sinks.Async": { "target": "project" }, + "Serilog.Sinks.File": "2.2.0", "xunit": "2.1.0", "dotnet-test-xunit": "1.0.0-rc2-build10025", "BenchmarkDotNet": "0.9.7-beta" @@ -18,8 +19,7 @@ "Microsoft.NETCore.App": { "type": "platform", "version": "1.0.0" - }, - "System.Collections": "4.0.11" + } }, "imports": [ "dnxcore50",