Migrate to High Performance Logging for Enhanced Observability and Performance

[paulomorgado]

Migrate to High Performance Logging for Enhanced Observability and Performance

Overview

This PR proposes replacing traditional logging methods (LogError, LogWarning, etc.) with High Performance Logging patterns to improve our application's observability, performance, and maintainability.

Key Benefits

1. 🚀 Performance Improvements

• Reduced Allocations: High-performance logging minimizes heap allocations by using value types and struct-based logging
• Efficient Message Formatting: Defers string formatting until absolutely necessary, reducing CPU overhead
• Source Generation: Uses source generators to create efficient logging code at compile time
• Zero Allocation Logging: When properly configured, can achieve zero-allocation for not enabled logging scenarios

2. 📊 Better Observability

• Structured Logging: First-class support for structured data instead of parsing message strings
• Semantic Logging: Clear separation between log message template and values
• Consistent Schema: Enforced schema for log entries makes querying and analysis more reliable
• Built-in Support for OpenTelemetry: Better integration with modern observability stacks

3. 🔍 Enhanced Maintainability

• Type Safety: Compile-time verification of logging statements
• Self-Documenting: Clear correlation between code and log output
• Consistent Formatting: Template-based approach ensures consistent log message structure
• Easier to Test: Better testability with strongly-typed logging interfaces

4. 💡 Developer Experience

• IntelliSense Support: Better IDE support for logging methods and parameters
• Compile-Time Validation: Catch logging issues during development
• Clear Category Hierarchy: Logical organization of log categories
• Source Link Integration: Direct navigation to logging source code

Technical Resources

For more information about High Performance Logging patterns and best practices:

• Logging Overview
• Write high-performance logging code in .NET

Implementation Example

// Before - Traditional Logging
_logger.LogError("User {UserId} failed to authenticate due to {Reason}", userId, reason);

// After - High Performance Logging
private static readonly Action<ILogger, string, string, Exception?> _userAuthenticationFailed =
    LoggerMessage.Define<string, string>(
        LogLevel.Error,
        new EventId(1, nameof(UserAuthenticationFailed)),
        "User {UserId} failed to authenticate due to {Reason}");

public void UserAuthenticationFailed(string userId, string reason)
    => _userAuthenticationFailed(_logger, userId, reason, null);

Performance Impact

• Reduced allocations in hot paths
• Lower CPU usage for logging operations
• Improved throughput in high-load scenarios
• Smaller memory footprint

Next Steps

1. Review the changes
2. Review event names
3. Assign event IDS

Let me know if you need any clarification or have suggestions for improvement!

[sipsorcery]

Minor not but 3 of the reference links go to the same page and one returns a 404.

Hopefully this PR was generated with an automated tool. It's a large amount of work!

Overall this approach feels disconcerting to me. The amount of code in the delegates seems to be quadrupling what's required for a single log message. Maybe it is making logging more efficient but isn't the solution to do that in the logging frameworks/libraries and allow application code can stay concise,

Additionally, IMHO instrumenation and analytics should be separate from logging. They serve different purposes and combiing them creates a maintenance burden, paricularly for simple debug log messages.

[paulomorgado]

Hopefully this PR was generated with an automated tool. It's a large amount of work!

-50% GitHub Copilot
+150% Manual work

😄

This PR is all about making logging efficient when not logging. There's a lot of heavy CPU and memory work in Debug and Trace logging, that are usually disabled in production.

If someone has a good test bench for SIPSorcery, I would appreciate to test this and see the difference.

Additionally, IMHO instrumenation and analytics should be separate from logging. They serve different purposes and combiing them creates a maintenance burden, paricularly for simple debug log messages.

I don't understand what you mean.

[sipsorcery]

Additionally, IMHO instrumenation and analytics should be separate from logging. They serve different purposes and combiing them creates a maintenance burden, paricularly for simple debug log messages.

I don't understand what you mean.

You list observability, structured & semantic logging, consistent schema and telemetry as benefits. Those make sense for a small number of the "high value" log events. The majority of log messages don't qualify. Incurring the additional overhead for 10% (guess) of the log messages that would be useful for telemetery etc. will introduce a significant burden for the 90% that don't.

In other code bases I've worked on we've used a different framework for telemetery, analytics and not tried to double up the logging framework.

[paulomorgado]

OpenTelemetry covers logging, tracing and metrics.

In OpenTelemery (https://opentelemetry.io/), structured & semantic logging is a first class citizen. But, in the end, it's just a common protocol that all players are using.

For logging, it's not a lot more that using Serilog with a JSON sink. Apart the well-known communication protocol being supported by major players like Microsoft Azure Application Insights, AWS, DataDog, Honneycomb, a lots more, incluiding Serilog.Sinks.OpenTelemetry.

Metrics and tracing (Activity) are also first citizens in .NET. But that will be a subject to another PR. 😄

Do you have any sample web (or "webifyable") project that I can setup with Aspire (https://learn.microsoft.com/en-us/dotnet/aspire/whats-new/dotnet-aspire-9.1) for you to see?

[sipsorcery]

Ok I've mixed myself up (partly due to the PR description listing a lot of things). The structured and semantic logging is fine and makes sense. Your previous logging PR made a lot of changes for that, The telemetery is not really a factor here since that will be part of the logging framework (or app insights etc).

So it boils down exclusively to using logging delegates for performance. And same argument as originally I don't think the extra maintenance and less concise code justifies it.

Do you have any sample web (or "webifyable") project that I can setup with Aspire

I'm a Kubernetes man myself, it has equivalent tools to Aspire, but if it helps there's an ASP.NET WebRTC demo.

[paulomorgado]

So it boils down exclusively to using logging delegates for performance. And same argument as originally I don't think the extra maintenance and less concise code justifies it.

I'm sad you fill that way.

Kubernetes is a run-time hosting/deployment infrastructure. Aspire is a development environment.

I'll make an Aspire demo.

[sipsorcery]

Kubernetes is a run-time hosting/deployment infrastructure. Aspire is a development environment.

We're clutching at straws here but my point is Aspire is an SDK with the sole purpose of deploying apps to Azure which is where the k8s comparison comes from.

[paulomorgado]

Kubernetes is a run-time hosting/deployment infrastructure. Aspire is a development environment.

We're clutching at straws here but my point is Aspire is an SDK with the sole purpose of deploying apps to Azure which is where the k8s comparison comes from.

That's not what Aspire is.

[DavidMartynWood]

It is my understanding that the only difference between doing something like...
logger.information("Hello {World}", world);
...and using an extension method is that you save on the boxing/unboxing of the world variable in the above scenario if logging is not enabled for that level.
So while there are some performance improvements in these changes, it should be weighed against the possibility that we've made it harder to add a simple logger.Trace() call if they feel they should follow this convention.
Having said that, these changes do not preclude anybody from adding logger.Trace("Hello world") if they want to.

[paulomorgado]

And the allocation of the object[] that contains the the world variable.

There's also pre-processing of the message template.

There aren't "some performance" improvements in this PR. There are huge performance improvements in this PR because, besides the documented performance improvements of using high performance logging, all calculations needed just for logging are now guarded by a log level check.

logger.LogTrace("Hello world") still allocates an empty object[] for some of the targets, regardless of trace level being enabled or not..

[paulomorgado]

Added Aspire demo project.

• examples\WebRTCExamples\WebRTCAspire
  • WebRTCAspire.Web - the web test project
  • WebRTCAspire.ServiceDefaults - common project defaults
  • WebRTCAspire.AppHost - Aspire host - this is where you start

You can play with this with the current implementation or with the NuGet of a version at your choice and check logs, .NET metrics, etc.