Skip to content

Commit

Permalink
Merge pull request serilog#750 from nblumhardt/f-forcontextallocs
Browse files Browse the repository at this point in the history
Optimize ForContext() by removing allocations
nblumhardt committed May 25, 2016
2 parents cbb93e5 + 2abc8d4 commit 9c23571
Showing 9 changed files with 190 additions and 42 deletions.
25 changes: 25 additions & 0 deletions src/Serilog/Core/Enrichers/EmptyEnricher.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,25 @@
// Copyright 2013-2015 Serilog Contributors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// 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.
// See the License for the specific language governing permissions and
// limitations under the License.

using Serilog.Events;

namespace Serilog.Core.Enrichers
{
class EmptyEnricher : ILogEventEnricher
{
public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
}
}
}
48 changes: 48 additions & 0 deletions src/Serilog/Core/Enrichers/SafeAggregateEnricher.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
// Copyright 2013-2015 Serilog Contributors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// 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.
// See the License for the specific language governing permissions and
// limitations under the License.

using System;
using System.Collections.Generic;
using System.Linq;
using Serilog.Debugging;
using Serilog.Events;

namespace Serilog.Core.Enrichers
{
class SafeAggregateEnricher : ILogEventEnricher
{
readonly ILogEventEnricher[] _enrichers;

public SafeAggregateEnricher(IEnumerable<ILogEventEnricher> enrichers)
{
if (enrichers == null) throw new ArgumentNullException(nameof(enrichers));
_enrichers = enrichers.ToArray();
}

public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
foreach (var enricher in _enrichers)
{
try
{
enricher.Enrich(logEvent, propertyFactory);
}
catch (Exception ex)
{
SelfLog.WriteLine("Exception {0} caught while enriching {1} with {2}.", ex, logEvent, enricher);
}
}
}
}
}
86 changes: 55 additions & 31 deletions src/Serilog/Core/Logger.cs
Original file line number Diff line number Diff line change
@@ -14,7 +14,6 @@

using System;
using System.Collections.Generic;
using System.Linq;
using Serilog.Core.Enrichers;
using Serilog.Debugging;
using Serilog.Events;
@@ -34,7 +33,7 @@ public sealed class Logger : ILogger, ILogEventSink, IDisposable
readonly MessageTemplateProcessor _messageTemplateProcessor;
readonly ILogEventSink _sink;
readonly Action _dispose;
readonly ILogEventEnricher[] _enrichers;
readonly ILogEventEnricher _enricher;

// It's important that checking minimum level is a very
// quick (CPU-cacheable) read in the simple case, hence
@@ -48,39 +47,57 @@ internal Logger(
MessageTemplateProcessor messageTemplateProcessor,
LogEventLevel minimumLevel,
ILogEventSink sink,
ILogEventEnricher[] enrichers,
ILogEventEnricher enricher,
Action dispose = null)
: this(messageTemplateProcessor, minimumLevel, sink, enrichers, dispose, null)
: this(messageTemplateProcessor, minimumLevel, sink, enricher, dispose, null)
{
}

internal Logger(
MessageTemplateProcessor messageTemplateProcessor,
LoggingLevelSwitch levelSwitch,
ILogEventSink sink,
ILogEventEnricher[] enrichers,
ILogEventEnricher enricher,
Action dispose = null)
: this(messageTemplateProcessor, LevelAlias.Minimum, sink, enrichers, dispose, levelSwitch)
: this(messageTemplateProcessor, LevelAlias.Minimum, sink, enricher, dispose, levelSwitch)
{
}

// The messageTemplateProcessor, sink and enricher are required. Argument checks are dropped because
// throwing from here breaks the logger's no-throw contract, and callers are all in this file anyway.
Logger(
MessageTemplateProcessor messageTemplateProcessor,
LogEventLevel minimumLevel,
ILogEventSink sink,
ILogEventEnricher[] enrichers,
ILogEventEnricher enricher,
Action dispose = null,
LoggingLevelSwitch levelSwitch = null)
{
if (sink == null) throw new ArgumentNullException(nameof(sink));
if (enrichers == null) throw new ArgumentNullException(nameof(enrichers));

_messageTemplateProcessor = messageTemplateProcessor;
_minimumLevel = minimumLevel;
_sink = sink;
_dispose = dispose;
_levelSwitch = levelSwitch;
_enrichers = enrichers;
_enricher = enricher;
}

/// <summary>
/// Create a logger that enriches log events via the provided enrichers.
/// </summary>
/// <param name="enricher">Enricher that applies in the context.</param>
/// <returns>A logger that will enrich log events as specified.</returns>
public ILogger ForContext(ILogEventEnricher enricher)
{
if (enricher == null)
return this; // No context here, so little point writing to SelfLog.

return new Logger(
_messageTemplateProcessor,
_minimumLevel,
this,
enricher,
null,
_levelSwitch);
}

/// <summary>
@@ -90,13 +107,10 @@ internal Logger(
/// <returns>A logger that will enrich log events as specified.</returns>
public ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
{
return new Logger(
_messageTemplateProcessor,
_minimumLevel,
this,
(enrichers ?? new ILogEventEnricher[0]).ToArray(),
null,
_levelSwitch);
if (enrichers == null)
return this; // No context here, so little point writing to SelfLog.

return ForContext(new SafeAggregateEnricher(enrichers));
}

/// <summary>
@@ -105,9 +119,18 @@ public ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
/// <returns>A logger that will enrich log events as specified.</returns>
public ILogger ForContext(string propertyName, object value, bool destructureObjects = false)
{
return ForContext(new[] {
new FixedPropertyEnricher(
_messageTemplateProcessor.CreateProperty(propertyName, value, destructureObjects)) });
if (!LogEventProperty.IsValidName(propertyName))
{
SelfLog.WriteLine("Attempt to call ForContext() with invalid property name `{0}` (value: `{1}`)", propertyName, value);
return this;
}

// It'd be nice to do the destructuring lazily, but unfortunately `value` may be mutated between
// now and the first log event written...
// A future optimization opportunity may be to implement ILogEventEnricher on LogEventProperty to
// remove one more allocation.
return ForContext(new FixedPropertyEnricher(
_messageTemplateProcessor.CreateProperty(propertyName, value, destructureObjects)));
}

/// <summary>
@@ -118,7 +141,9 @@ public ILogger ForContext(string propertyName, object value, bool destructureObj
/// <returns>A logger that will enrich log events as specified.</returns>
public ILogger ForContext(Type source)
{
if (source == null) throw new ArgumentNullException(nameof(source));
if (source == null)
return this; // Little point in writing to SelfLog here because we don't have any contextual information

return ForContext(Constants.SourceContextPropertyName, source.FullName);
}

@@ -343,16 +368,15 @@ void ILogEventSink.Emit(LogEvent logEvent)

void Dispatch(LogEvent logEvent)
{
foreach (var enricher in _enrichers)
// The enricher may be a "safe" aggregate one, but is most commonly bare and so
// the exception handling from SafeAggregateEnricher is duplicated here.
try
{
_enricher.Enrich(logEvent, _messageTemplateProcessor);
}
catch (Exception ex)
{
try
{
enricher.Enrich(logEvent, _messageTemplateProcessor);
}
catch (Exception ex)
{
SelfLog.WriteLine("Exception {0} caught while enriching {1} with {2}.", ex, logEvent, enricher);
}
SelfLog.WriteLine("Exception {0} caught while enriching {1} with {2}.", ex, logEvent, _enricher);
}

_sink.Emit(logEvent);
5 changes: 5 additions & 0 deletions src/Serilog/Core/Pipeline/SilentLogger.cs
Original file line number Diff line number Diff line change
@@ -20,6 +20,11 @@ namespace Serilog.Core.Pipeline
{
class SilentLogger : ILogger
{
public ILogger ForContext(ILogEventEnricher enricher)
{
return this;
}

public ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
{
return this;
18 changes: 13 additions & 5 deletions src/Serilog/Core/Sinks/FilteringSink.cs
Original file line number Diff line number Diff line change
@@ -15,6 +15,7 @@
using System;
using System.Collections.Generic;
using System.Linq;
using Serilog.Debugging;
using Serilog.Events;

namespace Serilog.Core.Sinks
@@ -34,13 +35,20 @@ public FilteringSink(ILogEventSink sink, IEnumerable<ILogEventFilter> filters)

public void Emit(LogEvent logEvent)
{
foreach (var logEventFilter in _filters)
try
{
if (!logEventFilter.IsEnabled(logEvent))
return;
}
foreach (var logEventFilter in _filters)
{
if (!logEventFilter.IsEnabled(logEvent))
return;
}

_sink.Emit(logEvent);
_sink.Emit(logEvent);
}
catch (Exception ex)
{
SelfLog.WriteLine("Caught exception {0} while applying filters.", ex);
}
}
}
}
9 changes: 8 additions & 1 deletion src/Serilog/ILogger.cs
Original file line number Diff line number Diff line change
@@ -24,7 +24,7 @@ namespace Serilog
/// </summary>
/// <example>
/// var log = new LoggerConfiguration()
/// .WithConsoleSink()
/// .WriteTo.Console()
/// .CreateLogger();
///
/// var thing = "World";
@@ -36,6 +36,13 @@ namespace Serilog
/// </remarks>
public interface ILogger
{
/// <summary>
/// Create a logger that enriches log events via the provided enrichers.
/// </summary>
/// <param name="enricher">Enricher that applies in the context.</param>
/// <returns>A logger that will enrich log events as specified.</returns>
ILogger ForContext(ILogEventEnricher enricher);

/// <summary>
/// Create a logger that enriches log events via the provided enrichers.
/// </summary>
10 changes: 10 additions & 0 deletions src/Serilog/Log.cs
Original file line number Diff line number Diff line change
@@ -65,6 +65,16 @@ public static void CloseAndFlush()
(logger as IDisposable)?.Dispose();
}

/// <summary>
/// Create a logger that enriches log events via the provided enrichers.
/// </summary>
/// <param name="enricher">Enricher that applies in the context.</param>
/// <returns>A logger that will enrich log events as specified.</returns>
public static ILogger ForContext(ILogEventEnricher enricher)
{
return Logger.ForContext(enricher);
}

/// <summary>
/// Create a logger that enriches log events via the provided enrichers.
/// </summary>
26 changes: 21 additions & 5 deletions src/Serilog/LoggerConfiguration.cs
Original file line number Diff line number Diff line change
@@ -17,6 +17,7 @@
using System.Linq;
using Serilog.Configuration;
using Serilog.Core;
using Serilog.Core.Enrichers;
using Serilog.Core.Sinks;
using Serilog.Events;
using Serilog.Parameters;
@@ -134,7 +135,7 @@ public LoggerSettingsConfiguration ReadFrom
public Logger CreateLogger()
{
if (_loggerCreated)
throw new InvalidOperationException("CreateLogger was previously called and can only be called once.");
throw new InvalidOperationException("CreateLogger() was previously called and can only be called once.");
_loggerCreated = true;

Action dispose = () =>
@@ -143,17 +144,32 @@ public Logger CreateLogger()
disposable.Dispose();
};

var sink = new SafeAggregateSink(_logEventSinks);
ILogEventSink sink = new SafeAggregateSink(_logEventSinks);

if (_filters.Any())
sink = new SafeAggregateSink(new[] { new FilteringSink(sink, _filters) });
sink = new FilteringSink(sink, _filters);

var converter = new PropertyValueConverter(_maximumDestructuringDepth, _additionalScalarTypes, _additionalDestructuringPolicies);
var processor = new MessageTemplateProcessor(converter);

ILogEventEnricher enricher;
switch (_enrichers.Count)
{
case 0:
// Should be a rare case, so no problem making that extra interface dispatch.
enricher = new EmptyEnricher();
break;
case 1:
enricher = _enrichers[0];
break;
default:
enricher = new SafeAggregateEnricher(_enrichers);
break;
}

return _levelSwitch == null ?
new Logger(processor, _minimumLevel, sink, _enrichers.ToArray(), dispose) :
new Logger(processor, _levelSwitch, sink, _enrichers.ToArray(), dispose);
new Logger(processor, _minimumLevel, sink, enricher, dispose) :
new Logger(processor, _levelSwitch, sink, enricher, dispose);
}
}
}
5 changes: 5 additions & 0 deletions test/Serilog.Tests/Support/DisposableLogger.cs
Original file line number Diff line number Diff line change
@@ -14,6 +14,11 @@ public void Dispose()
Disposed = true;
}

public ILogger ForContext(ILogEventEnricher enricher)
{
throw new NotImplementedException();
}

public ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
{
throw new NotImplementedException();

0 comments on commit 9c23571

Please sign in to comment.