Skip to content

Commit

Permalink
Address nblumhardt review comments
Browse files Browse the repository at this point in the history
  • Loading branch information
bartelink committed Apr 22, 2018
1 parent d3b5309 commit 510db8d
Show file tree
Hide file tree
Showing 5 changed files with 43 additions and 41 deletions.
14 changes: 7 additions & 7 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -32,18 +32,18 @@ Because the memory buffer may contain events that have not yet been written to t

### Buffering & Dropping

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. One can determine whether events have been dropped via `IQueueState.DroppedMessagesCount` (see Buffer Inspection interface below).
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. One can determine whether events have been dropped via `Serilog.Async.IAsyncLogEventSinkState.DroppedMessagesCount` (see Sink State Inspection interface below).

```csharp
// Reduce the buffer to 500 events
.WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500)
```

### Health Monitoring via the Buffer Inspection interface
### Health Monitoring via the Sink State Inspection interface

The Async wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a File sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe in that it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrades to a major degree.
The `Async` wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a `File` Sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe; it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrade to a major degree.

In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load gracefully. The key risk is of course that events may be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice.
In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load safely. The key risk is of course that events get be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice.

```csharp
// Example check: log message to an out of band alarm channel if logging is showing signs of getting overwhelmed
Expand All @@ -54,10 +54,10 @@ In practice, this configuration (assuming one provisions an adequate `bufferSize
}

// Allow a backlog of up to 10,000 items to be maintained (dropping extras if full)
.WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out IQueueState inspector) ...
.WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out Async.IAsyncLogEventSinkState inspector) ...

// Wire the inspector through to health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc.
... healthMonitoring.RegisterCheck(() => new PeriodicMonitorCheck(inspector));
// Wire the inspector through to application health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc.
... HealthMonitor.RegisterAsyncLogSink(inspector);
```

### Blocking
Expand Down
29 changes: 3 additions & 26 deletions src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -67,12 +67,12 @@ public static LoggerConfiguration Async(
public static LoggerConfiguration Async(
this LoggerSinkConfiguration loggerSinkConfiguration,
Action<LoggerSinkConfiguration> configure,
out IQueueState inspector,
out IAsyncLogEventSinkState inspector,
int bufferSize = 10000,
bool blockWhenFull = false)
{
// Cannot assign directly to the out param from within the lambda, so we need a temp
IQueueState stateLens = null;
IAsyncLogEventSinkState stateLens = null;
var result = LoggerSinkConfiguration.Wrap(
loggerSinkConfiguration,
wrappedSink =>
Expand All @@ -86,27 +86,4 @@ public static LoggerConfiguration Async(
return result;
}
}

/// <summary>
/// Provides a way to inspect the current state of Async wrapper's ingestion queue.
/// </summary>
public interface IQueueState
{
/// <summary>
/// Count of items currently awaiting ingestion.
/// </summary>
/// <exception cref="T:System.ObjectDisposedException">The Sink has been disposed.</exception>
int Count { get; }

/// <summary>
/// Accumulated number of messages dropped due to attempted submission having breached <see cref="BufferSize"/> limit.
/// </summary>
long DroppedMessagesCount { get; }

/// <summary>
/// Maximum number of items permitted to be held in the buffer awaiting ingestion.
/// </summary>
/// <exception cref="T:System.ObjectDisposedException">The Sink has been disposed.</exception>
int BufferSize { get; }
}
}
}
8 changes: 4 additions & 4 deletions src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@

namespace Serilog.Sinks.Async
{
sealed class BackgroundWorkerSink : ILogEventSink, IQueueState, IDisposable
sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkState, IDisposable
{
readonly ILogEventSink _pipeline;
readonly bool _blockWhenFull;
Expand Down Expand Up @@ -79,10 +79,10 @@ void Pump()
}
}

int IQueueState.Count => _queue.Count;
int IAsyncLogEventSinkState.BufferSize => _queue.BoundedCapacity;

int IQueueState.BufferSize => _queue.BoundedCapacity;
int IAsyncLogEventSinkState.Count => _queue.Count;

long IQueueState.DroppedMessagesCount => _droppedMessages;
long IAsyncLogEventSinkState.DroppedMessagesCount => _droppedMessages;
}
}
25 changes: 25 additions & 0 deletions src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,25 @@
namespace Serilog.Sinks.Async
{
/// <summary>
/// Provides a way to monitor the state of Async wrapper's ingestion queue.
/// </summary>
public interface IAsyncLogEventSinkState
{
/// <summary>
/// Configured maximum number of items permitted to be held in the buffer awaiting ingestion.
/// </summary>
/// <exception cref="T:System.ObjectDisposedException">The Sink has been disposed.</exception>
int BufferSize { get; }

/// <summary>
/// Current moment-in-time Count of items currently awaiting ingestion.
/// </summary>
/// <exception cref="T:System.ObjectDisposedException">The Sink has been disposed.</exception>
int Count { get; }

/// <summary>
/// Accumulated number of messages dropped due to breach of <see cref="BufferSize"/> limit.
/// </summary>
long DroppedMessagesCount { get; }
}
}
8 changes: 4 additions & 4 deletions test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,7 @@ public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock()

// Allow at least one to propagate
await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false);
Assert.NotEqual(0, ((IQueueState)sink).DroppedMessagesCount);
Assert.NotEqual(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount);
}
// Sanity check the overall timing
batchTiming.Stop();
Expand Down Expand Up @@ -145,7 +145,7 @@ from e in _innerSink.Events
Assert.InRange(2, 2 * 3 / 2 - 1, propagatedExcludingFinal.Count());
// Final event should have made it through
Assert.Contains(_innerSink.Events, x => Object.ReferenceEquals(finalEvent, x));
Assert.NotEqual(0, ((IQueueState)sink).DroppedMessagesCount);
Assert.NotEqual(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount);
}
}

Expand Down Expand Up @@ -184,7 +184,7 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks()

// No events should be dropped
Assert.Equal(3, _innerSink.Events.Count);
Assert.Equal(0, ((IQueueState)sink).DroppedMessagesCount);
Assert.Equal(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount);
}
}

Expand All @@ -195,7 +195,7 @@ public void InspectorOutParameterAffordsHealthMonitoringHook()
// 2 spaces in queue; 1 would make the second log entry eligible for dropping if consumer does not activate instantaneously
var bufferSize = 2;
using (var logger = new LoggerConfiguration()
.WriteTo.Async(w => w.Sink(collector), bufferSize: 2, inspector: out IQueueState inspector)
.WriteTo.Async(w => w.Sink(collector), bufferSize: 2, inspector: out IAsyncLogEventSinkState inspector)
.CreateLogger())
{
Assert.Equal(bufferSize, inspector.BufferSize);
Expand Down

0 comments on commit 510db8d

Please sign in to comment.