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

High performance logging (NET6+) #361

Merged
merged 2 commits into from
Jan 13, 2025
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
2 changes: 1 addition & 1 deletion src/Host.Plugin.Properties.xml
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
<Import Project="Common.NuGet.Properties.xml" />

<PropertyGroup>
<Version>3.0.0-rc902</Version>
<Version>3.0.0-rc904</Version>
</PropertyGroup>

</Project>
Original file line number Diff line number Diff line change
Expand Up @@ -3,24 +3,46 @@
/// <summary>
/// Resolves the <see cref="IMessageBus"/> from the current ASP.NET Core web request (if present, otherwise falls back to the application root container).
/// </summary>
public class HttpContextAccessorCurrentMessageBusProvider(
public partial class HttpContextAccessorCurrentMessageBusProvider(
ILogger<HttpContextAccessorCurrentMessageBusProvider> logger,
IHttpContextAccessor httpContextAccessor,
IServiceProvider serviceProvider)
: CurrentMessageBusProvider(serviceProvider)
{
private readonly ILogger<HttpContextAccessorCurrentMessageBusProvider> _logger = logger;

public override IMessageBus GetCurrent()
{
// When the call to resolve the given type is made within an HTTP Request, use the request scope service provider
var httpContext = httpContextAccessor?.HttpContext;
if (httpContext != null)
{
logger.LogTrace("The type IMessageBus will be requested from the per-request scope");
LogCurrentFrom("request");
return httpContext.RequestServices.GetService<IMessageBus>();
}

// otherwise use the app wide scope provider
logger.LogTrace("The type IMessageBus will be requested from the app scope");
LogCurrentFrom("root");
return base.GetCurrent();
}

#region Logging

[LoggerMessage(
EventId = 0,
Level = LogLevel.Trace,
Message = "The type IMessageBus will be requested from the {ScopeName} scope")]
private partial void LogCurrentFrom(string scopeName);

#endregion
}

#if NETSTANDARD2_0

public partial class HttpContextAccessorCurrentMessageBusProvider
{
private partial void LogCurrentFrom(string scopeName)
=> _logger.LogTrace("The type IMessageBus will be requested from the {ScopeName} scope", scopeName);
}

#endif
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
/// <summary>
/// Circuit breaker to toggle consumer status on an external events.
/// </summary>
internal sealed class CircuitBreakerAbstractConsumerInterceptor : IAbstractConsumerInterceptor
internal sealed class CircuitBreakerAbstractConsumerInterceptor(ILogger logger) : IAbstractConsumerInterceptor
{
public int Order => 100;

Expand Down Expand Up @@ -33,12 +33,12 @@ async Task BreakerChanged(Circuit state)
var bus = consumer.Settings[0].MessageBusSettings.Name ?? "default";
if (shouldPause)
{
consumer.Logger.LogWarning("Circuit breaker tripped for '{Path}' on '{Bus}' bus. Consumer paused.", path, bus);
logger.LogWarning("Circuit breaker tripped for '{Path}' on '{Bus}' bus. Consumer paused.", path, bus);
await consumer.DoStop().ConfigureAwait(false);
}
else
{
consumer.Logger.LogInformation("Circuit breaker restored for '{Path}' on '{Bus}' bus. Consumer resumed.", path, bus);
logger.LogInformation("Circuit breaker restored for '{Path}' on '{Bus}' bus. Consumer resumed.", path, bus);
await consumer.DoStart().ConfigureAwait(false);
}
consumer.SetIsPaused(shouldPause);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@
<Description>Core configuration interfaces of SlimMessageBus</Description>
<PackageTags>SlimMessageBus</PackageTags>
<RootNamespace>SlimMessageBus.Host</RootNamespace>
<Version>3.0.0-rc901</Version>
<Version>3.0.0-rc904</Version>
</PropertyGroup>

<ItemGroup>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
<Import Project="../Common.NuGet.Properties.xml" />

<PropertyGroup>
<Version>3.0.0-rc901</Version>
<Version>3.0.0-rc904</Version>
<Description>Core interceptor interfaces of SlimMessageBus</Description>
<PackageTags>SlimMessageBus</PackageTags>
</PropertyGroup>
Expand Down
Original file line number Diff line number Diff line change
@@ -1,7 +1,9 @@
namespace SlimMessageBus.Host.Memory;

public abstract class AbstractMessageProcessorQueue(IMessageProcessor<object> messageProcessor, ILogger logger) : IMessageProcessorQueue
public abstract partial class AbstractMessageProcessorQueue(IMessageProcessor<object> messageProcessor, ILogger logger) : IMessageProcessorQueue
{
private readonly ILogger _logger = logger;

public abstract void Enqueue(object transportMessage, IReadOnlyDictionary<string, object> messageHeaders);

protected async Task ProcessMessage(object transportMessage, IReadOnlyDictionary<string, object> messageHeaders, CancellationToken cancellationToken)
Expand All @@ -23,7 +25,27 @@ protected async Task ProcessMessage(object transportMessage, IReadOnlyDictionary
if (r.Exception != null)
{
// We rely on the IMessageProcessor to execute the ConsumerErrorHandler<T>, but if it's not registered in the DI, it fails, or there is another fatal error then the message will be lost.
logger.LogError(r.Exception, "Error processing message {Message} of type {MessageType}", transportMessage, transportMessage.GetType());
LogMessageError(transportMessage, transportMessage.GetType(), r.Exception);
}
}

#region Logging

[LoggerMessage(
EventId = 0,
Level = LogLevel.Error,
Message = "Error processing message {TransportMessage} of type {TransportMessageType}")]
private partial void LogMessageError(object transportMessage, Type transportMessageType, Exception e);

#endregion
}

#if NETSTANDARD2_0

public abstract partial class AbstractMessageProcessorQueue
{
private partial void LogMessageError(object transportMessage, Type transportMessageType, Exception e)
=> _logger.LogError(e, "Error processing message {TransportMessage} of type {TransportMessageType}", transportMessage, transportMessageType);
}

#endif
Original file line number Diff line number Diff line change
@@ -1,6 +1,9 @@
namespace SlimMessageBus.Host.Memory;

public class MessageProcessorQueue(IMessageProcessor<object> messageProcessor, ILogger<MessageProcessorQueue> logger, CancellationToken cancellationToken) : AbstractMessageProcessorQueue(messageProcessor, logger)
public class MessageProcessorQueue(IMessageProcessor<object> messageProcessor,
ILogger<MessageProcessorQueue> logger,
CancellationToken cancellationToken)
: AbstractMessageProcessorQueue(messageProcessor, logger)
{
private readonly object _prevTaskLock = new();
private Task _prevTask = null;
Expand Down
29 changes: 23 additions & 6 deletions src/SlimMessageBus.Host.Memory/MemoryMessageBus.cs
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@
/// <summary>
/// In-memory message bus <see cref="IMessageBus"/> implementation to use for in process message passing.
/// </summary>
public class MemoryMessageBus : MessageBusBase<MemoryMessageBusSettings>
public partial class MemoryMessageBus : MessageBusBase<MemoryMessageBusSettings>
{
private readonly ILogger _logger;
private IDictionary<string, IMessageProcessor<object>> _messageProcessorByPath;
Expand Down Expand Up @@ -63,11 +63,8 @@ public override IDictionary<string, object> CreateHeaders()

public override bool IsMessageScopeEnabled(ConsumerSettings consumerSettings, IDictionary<string, object> consumerContextProperties)
{
#if NETSTANDARD2_0
if (consumerSettings is null) throw new ArgumentNullException(nameof(consumerSettings));
#else
ArgumentNullException.ThrowIfNull(consumerSettings);
#endif

if (consumerContextProperties != null && consumerContextProperties.ContainsKey(MemoryMessageBusProperties.CreateScope))
{
return true;
Expand Down Expand Up @@ -133,7 +130,7 @@ private async Task<TResponseMessage> ProduceInternal<TResponseMessage>(object me
path ??= GetDefaultPath(producerSettings.MessageType, producerSettings);
if (!_messageProcessorByPath.TryGetValue(path, out var messageProcessor))
{
_logger.LogDebug("No consumers interested in message type {MessageType} on path {Path}", messageType, path);
LogNoConsumerInterestedInMessageType(path, messageType);
return default;
}

Expand Down Expand Up @@ -165,4 +162,24 @@ private async Task<TResponseMessage> ProduceInternal<TResponseMessage>(object me
}
return (TResponseMessage)r.Response;
}

#region Logging

[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "No consumers interested in message type {MessageType} on path {Path}")]
private partial void LogNoConsumerInterestedInMessageType(string path, Type messageType);

#endregion
}

#if NETSTANDARD2_0

public partial class MemoryMessageBus
{
private partial void LogNoConsumerInterestedInMessageType(string path, Type messageType)
=> _logger.LogDebug("No consumers interested in message type {MessageType} on path {Path}", messageType, path);
}

#endif
Original file line number Diff line number Diff line change
Expand Up @@ -52,8 +52,8 @@ public AvroMessageSerializer(ILoggerFactory loggerFactory = null)
var mf = new ReflectionMessageCreationStrategy(loggerFactory.CreateLogger<ReflectionMessageCreationStrategy>());
var ml = new ReflectionSchemaLookupStrategy(loggerFactory.CreateLogger<ReflectionSchemaLookupStrategy>());

MessageFactory = (Type type) => mf.Create(type);
WriteSchemaLookup = (Type type) => ml.Lookup(type);
MessageFactory = mf.Create;
WriteSchemaLookup = ml.Lookup;
ReadSchemaLookup = WriteSchemaLookup;
}

Expand All @@ -73,7 +73,7 @@ public AvroMessageSerializer(ILoggerFactory loggerFactory, IMessageCreationStrat
public object Deserialize(Type t, byte[] payload)
{
using var ms = ReadMemoryStreamFactory(payload);

var dec = new BinaryDecoder(ms);

var message = MessageFactory(t);
Expand All @@ -84,7 +84,7 @@ public object Deserialize(Type t, byte[] payload)
var writerSchema = WriteSchemaLookup(t);
AssertSchemaNotNull(t, writerSchema, true);

_logger.LogDebug("Type {0} writer schema: {1}, reader schema: {2}", t, writerSchema, readerSchema);
_logger.LogDebug("Type {Type} writer schema: {WriterSchema}, reader schema: {ReaderSchema}", t, writerSchema, readerSchema);

var reader = new SpecificDefaultReader(writerSchema, readerSchema);
reader.Read(message, dec);
Expand All @@ -108,7 +108,7 @@ public byte[] Serialize(Type t, object message)
var writerSchema = WriteSchemaLookup(t);
AssertSchemaNotNull(t, writerSchema, true);

_logger.LogDebug("Type {0} writer schema: {1}", t, writerSchema);
_logger.LogDebug("Type {Type} writer schema: {WriterSchema}", t, writerSchema);

var writer = new SpecificDefaultWriter(writerSchema); // Schema comes from pre-compiled, code-gen phase
writer.Write(message, enc);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
<Import Project="../Common.NuGet.Properties.xml" />

<PropertyGroup>
<Version>3.0.0-rc901</Version>
<Version>3.0.0-rc904</Version>
<Description>Core serialization interfaces of SlimMessageBus</Description>
<PackageTags>SlimMessageBus</PackageTags>
</PropertyGroup>
Expand Down
4 changes: 2 additions & 2 deletions src/SlimMessageBus.Host/Collections/KindMapping.cs
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,8 @@

public class KindMapping
{
private readonly Dictionary<string, PathKind> _kindByTopic = new();
private readonly Dictionary<Type, PathKind> _kindByMessageType = new();
private readonly Dictionary<string, PathKind> _kindByTopic = [];
private readonly Dictionary<Type, PathKind> _kindByMessageType = [];

public void Configure(MessageBusSettings settings)
{
Expand Down Expand Up @@ -63,7 +63,7 @@
// determine the SMB topic name if its a Azure SB queue or topic
if (!_kindByTopic.TryGetValue(path, out var kind))
{
if (!_kindByMessageType.TryGetValue(messageType, out kind))

Check warning on line 66 in src/SlimMessageBus.Host/Collections/KindMapping.cs

View workflow job for this annotation

GitHub Actions / build

Merge this if statement with the enclosing one. (https://rules.sonarsource.com/csharp/RSPEC-1066)
{
// by default this will be a topic
kind = PathKind.Topic;
Expand Down
37 changes: 33 additions & 4 deletions src/SlimMessageBus.Host/Collections/ProducerByMessageTypeCache.cs
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@
/// The message type hierarchy is discovered at runtime and cached for faster access.
/// </summary>
/// <typeparam name="TProducer">The producer type</typeparam>
public class ProducerByMessageTypeCache<TProducer> : IReadOnlyCache<Type, TProducer>
public partial class ProducerByMessageTypeCache<TProducer> : IReadOnlyCache<Type, TProducer>
where TProducer : class
{
private readonly ILogger _logger;
Expand Down Expand Up @@ -37,7 +37,7 @@ private TProducer CalculateProducer(Type messageType)
var assignableProducer = assignableProducers.FirstOrDefault();
if (assignableProducer.Key != null)
{
_logger.LogDebug("Matched producer for message type {ProducerMessageType} for dispatched message type {MessageType}", assignableProducer.Key, messageType);
LogMatchedProducerForMessageType(messageType, assignableProducer.Key);
return assignableProducer.Value;
}

Expand All @@ -52,7 +52,7 @@ private TProducer CalculateProducer(Type messageType)
}
}

_logger.LogDebug("Unable to match any declared producer for dispatched message type {MessageType}", messageType);
LogUnmatchedProducerForMessageType(messageType);

// Note: Nulls are also added to dictionary, so that we don't look them up using reflection next time (cached).
return null;
Expand All @@ -74,4 +74,33 @@ private static int CalculateBaseClassDistance(Type type, Type baseType)

return distance;
}
}

#region Logging

[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "Matched producer for message type {ProducerMessageType} for dispatched message type {MessageType}")]
private partial void LogMatchedProducerForMessageType(Type messageType, Type producerMessageType);

[LoggerMessage(
EventId = 1,
Level = LogLevel.Debug,
Message = "Unable to match any declared producer for dispatched message type {MessageType}")]
private partial void LogUnmatchedProducerForMessageType(Type messageType);

#endregion
}

#if NETSTANDARD2_0

public partial class ProducerByMessageTypeCache<TProducer>
{
private partial void LogMatchedProducerForMessageType(Type messageType, Type producerMessageType)
=> _logger.LogDebug("Matched producer for message type {ProducerMessageType} for dispatched message type {MessageType}", producerMessageType, messageType);

private partial void LogUnmatchedProducerForMessageType(Type messageType)
=> _logger.LogDebug("Unable to match any declared producer for dispatched message type {MessageType}", messageType);
}

#endif
27 changes: 24 additions & 3 deletions src/SlimMessageBus.Host/Consumer/AbstractConsumer.cs
Original file line number Diff line number Diff line change
@@ -1,7 +1,8 @@
namespace SlimMessageBus.Host;

public abstract class AbstractConsumer : HasProviderExtensions, IAsyncDisposable, IConsumerControl
public abstract partial class AbstractConsumer : HasProviderExtensions, IAsyncDisposable, IConsumerControl
{
protected readonly ILogger Logger;
private readonly SemaphoreSlim _semaphore;
private readonly IReadOnlyList<IAbstractConsumerInterceptor> _interceptors;
private CancellationTokenSource _cancellationTokenSource;
Expand All @@ -10,7 +11,6 @@ public abstract class AbstractConsumer : HasProviderExtensions, IAsyncDisposable

public bool IsStarted { get; private set; }
public string Path { get; }
public ILogger Logger { get; }
public IReadOnlyList<AbstractConsumerSettings> Settings { get; }
protected CancellationToken CancellationToken => _cancellationTokenSource.Token;

Expand Down Expand Up @@ -39,7 +39,7 @@ private async Task<bool> CallInterceptor(Func<IAbstractConsumerInterceptor, Task
}
catch (Exception e)
{
Logger.LogError(e, "Interceptor {Interceptor} failed with error: {Error}", interceptor.GetType().Name, e.Message);
LogInterceptorFailed(interceptor.GetType(), e.Message, e);
}
}
return true;
Expand Down Expand Up @@ -178,4 +178,25 @@ protected async virtual ValueTask DisposeAsyncCore()
}

#endregion

#region Logging

[LoggerMessage(
EventId = 0,
Level = LogLevel.Error,
Message = "Interceptor {InterceptorType} failed with error: {Error}")]
private partial void LogInterceptorFailed(Type interceptorType, string error, Exception ex);

#endregion
}


#if NETSTANDARD2_0

public partial class AbstractConsumer
{
private partial void LogInterceptorFailed(Type interceptorType, string error, Exception ex)
=> Logger.LogError(ex, "Interceptor {InterceptorType} failed with error: {Error}", interceptorType, error);
}

#endif
Loading
Loading