Phase one logger optimisations (#2503)

This PR dramatically reduces the overhead of scoped logging, even for
scenarios where the configured log level verbosity was low (e.g.,
Warning). The most critical improvement is caching scoped loggers within
Spans, Traces, and Errors. We lose convenience in no longer having the
span ID in the scope, but it's generally available from the Span
argument.

Previously, a new `ScopedLogger` was created for every span and
transaction, and a new `ConditionalWeakTable` was also allocated. Due to
the use of Finalisers on the CWT, this had an even more significant GC
impact. We now maintain a cache of scoped loggers (of which there are
relatively few).

The ID creation for the Spans has been switched to
`ActivitySpanId.CreateRandom().ToString()` from the MS diagnostics
library, as this has been more heavily optimised than our original
version and achieves the same goal.

In `Tracer.End()`, we used an `Assertion` with a large interpolated
string. This was being interpolated for each transaction as the
`Assertion` path was enabled. However, the condition we assert is
generally not met. Therefore, we now check this manually to only create
the message if we are in an invalid state.

I've also switched two structs to record structs, as these were used as
keys in dictionaries and ended up being boxed due to a lack of
`IEquality` implementations.

These are phase one of optimisations for the logging implementation and
address the general production scenario of using a less verbose log
level.

### Profiling

Profiling was achieved using a .NET 9 ASP.NET Core minimal API project
with 20 concurrent connections and 100,000 requests.

**Before Memory Profile**

![image](https://github.com/user-attachments/assets/6ba52339-dc4e-44a0-811d-039c9807c0fb)

**After Memory Profile**

![image](https://github.com/user-attachments/assets/22a8fdcc-3cab-4b83-bd27-b6107f849899)

**Before Top Retained**

![image](https://github.com/user-attachments/assets/348c837e-a910-4220-8a60-e12b4fd3f961)

**After Top Retained**

![image](https://github.com/user-attachments/assets/d7a31e7b-f5cf-419a-8eaa-ed4042a07470)

Closes #2500

src/Elastic.Apm/Api/Tracer.cs

@@ -21,7 +21,7 @@ internal class Tracer : ITracer
 	{
 		private readonly IApmServerInfo _apmServerInfo;
 		private readonly IConfigurationSnapshotProvider _configurationProvider;
-		private readonly ScopedLogger _logger;
+		private readonly IApmLogger _logger;
 		private readonly IPayloadSender _sender;
 		private readonly Service _service;
 		private readonly BreakdownMetricsProvider _breakdownMetricsProvider;
@@ -83,7 +83,7 @@ private Transaction StartTransactionInternal(string name, string type, Distribut
 				traceId: traceId, links: links, current: current)
 			{ Service = _service };
 
-			_logger.Debug()?.Log("Starting {TransactionValue}", retVal);
+			_logger?.Debug()?.Log("Starting {TransactionValue}", retVal);
 			return retVal;
 		}
 

src/Elastic.Apm/Config/Net4FullFramework/AppSettingsConfigurationKeyValueProvider.cs

@@ -3,8 +3,8 @@
 // Elasticsearch B.V licenses this file to you under the Apache 2.0 License.
 // See the LICENSE file in the project root for more information
 
-#if NETFRAMEWORK
 #nullable enable
+#if NETFRAMEWORK
 using System.Configuration;
 using Elastic.Apm.Logging;
 
@@ -14,8 +14,7 @@ internal class AppSettingsConfigurationKeyValueProvider : IConfigurationKeyValue
 {
 	private readonly IApmLogger? _logger;
 
-	public AppSettingsConfigurationKeyValueProvider(IApmLogger? logger) =>
-		_logger = logger?.Scoped(nameof(AppSettingsConfigurationKeyValueProvider));
+	public AppSettingsConfigurationKeyValueProvider(IApmLogger? logger) => _logger = logger?.Scoped(nameof(AppSettingsConfigurationKeyValueProvider));
 
 	public string Description => nameof(AppSettingsConfigurationKeyValueProvider);
 
@@ -29,9 +28,10 @@ public AppSettingsConfigurationKeyValueProvider(IApmLogger? logger) =>
 		}
 		catch (ConfigurationErrorsException ex)
 		{
-			_logger.Error()?.LogException(ex, "Exception thrown from ConfigurationManager.AppSettings - falling back on environment variables");
+			_logger?.Error()?.LogException(ex, "Exception thrown from ConfigurationManager.AppSettings - falling back on environment variables");
 		}
 		return null;
 	}
 }
 #endif
+#nullable restore

src/Elastic.Apm/Logging/IApmLoggingExtensions.cs

@@ -3,6 +3,7 @@
 // See the LICENSE file in the project root for more information
 
 using System;
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.IO;
@@ -12,13 +13,53 @@
 
 namespace Elastic.Apm.Logging;
 
+#nullable enable
 internal static class LoggingExtensions
 {
-	private static ConditionalWeakTable<string, LogValuesFormatter> Formatters { get; } = new();
+	// Using a ConcurrentDictionary rather than ConditionalWeakTable as we expect few distinct scopes
+	// and we want to retain them for reuse across the application lifetime. We use the scope name and the
+	// instance of the base logger for the key, for rare scenarios when different base loggers might be
+	// used. In reality, this only seems to affect testing scenarios.
+	private static readonly ConcurrentDictionary<(string, IApmLogger), ScopedLogger> ScopedLoggers = new();
 
-	internal static ScopedLogger Scoped(this IApmLogger logger, string scope) => new(logger is ScopedLogger s ? s.Logger : logger, scope);
+	private static readonly ConditionalWeakTable<string, LogValuesFormatter> Formatters = new();
 
-	private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception e, params object[] args)
+	/// <summary>
+	/// Returns a ScopedLogger, potentially from the cache.
+	/// </summary>
+	/// <param name="logger">An existing <see cref="IApmLogger"/>.</param>
+	/// <param name="scope">The name of the scope.</param>
+	/// <returns>A new scoped logger or <c>null</c> of the <see cref="IApmLogger"/> is <c>null</c>.</returns>
+	/// <exception cref="ArgumentException">Requires <paramref name="scope"/> to be non-null and non-empty.</exception>
+	internal static ScopedLogger? Scoped(this IApmLogger? logger, string scope)
+	{
+		if (string.IsNullOrEmpty(scope))
+			throw new ArgumentException("Scope is required to be non-null and non-empty.", nameof(scope));
+
+		if (logger is null)
+			return null;
+
+		var baseLogger = logger is ScopedLogger s ? s.Logger : logger;
+
+		if (!ScopedLoggers.TryGetValue((scope, baseLogger), out var scopedLogger))
+		{
+			// Ensure we don't allow creations of scoped loggers 'wrapping' other scoped loggers
+			var potentialScopedLogger = new ScopedLogger(baseLogger, scope);
+
+			if (ScopedLoggers.TryAdd((scope, baseLogger), potentialScopedLogger))
+			{
+				scopedLogger = potentialScopedLogger;
+			}
+			else
+			{
+				scopedLogger = ScopedLoggers[(scope, baseLogger)];
+			}
+		}
+
+		return scopedLogger;
+	}
+
+	private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception? exception, params object?[]? args)
 	{
 		try
 		{
@@ -28,9 +69,9 @@ private static void DoLog(this IApmLogger logger, LogLevel level, string message
 
 			var logValues = formatter.GetState(args);
 
-			logger?.Log(level, logValues, e, static (l, _) => l.Formatter.Format(l.Args));
+			logger?.Log(level, logValues, exception, static (l, _) => l.Formatter.Format(l.Args));
 		}
-		catch (Exception exception)
+		catch (Exception ex)
 		{
 			// For now we will just print it to System.Diagnostics.Trace
 			// In the future we should consider error counters to increment and log periodically on a worker thread
@@ -44,12 +85,12 @@ private static void DoLog(this IApmLogger logger, LogLevel level, string message
 
 				System.Diagnostics.Trace.WriteLine("Elastic APM .NET Agent: [CRITICAL] Exception thrown by logging implementation."
 					+ $" Log message: `{message.AsNullableToString()}'."
-					+ $" args.Length: {args.Length}."
+					+ $" args.Length: {args?.Length ?? 0}."
 					+ $" Current thread: {DbgUtils.CurrentThreadDesc}"
 					+ newLine
-					+ $"+-> Exception (exception): {exception.GetType().FullName}: {exception.Message}{newLine}{exception.StackTrace}"
-					+ (e != null
-						? newLine + $"+-> Exception (e): {e.GetType().FullName}: {e.Message}{newLine}{e.StackTrace}"
+					+ $"+-> Exception (exception): {ex.GetType().FullName}: {ex.Message}{newLine}{ex.StackTrace}"
+					+ (exception != null
+						? newLine + $"+-> Exception (e): {exception.GetType().FullName}: {exception.Message}{newLine}{exception.StackTrace}"
 						: $"e: {ObjectExtensions.NullAsString}")
 					+ newLine
 					+ "+-> Current stack trace:" + currentStackTrace
@@ -62,11 +103,11 @@ private static void DoLog(this IApmLogger logger, LogLevel level, string message
 		}
 	}
 
-#if !NET6_0_OR_GREATER
+#if !NET8_0_OR_GREATER
 	private static readonly object _lock = new();
 #endif
 
-	private static LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection<object> args)
+	private static LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection<object?>? args)
 	{
 		if (Formatters.TryGetValue(message, out var formatter))
 			return formatter;
@@ -162,7 +203,7 @@ internal readonly struct MaybeLogger
 
 		public MaybeLogger(IApmLogger logger, LogLevel level) => (_logger, _level) = (logger, level);
 
-		public void Log(string message, params object[] args) => _logger.DoLog(_level, message, null, args);
+		public void Log(string message, params object?[]? args) => _logger.DoLog(_level, message, null, args);
 
 		public void LogException(Exception exception, string message, params object[] args) =>
 			_logger.DoLog(_level, message, exception, args);
@@ -179,3 +220,4 @@ public void LogExceptionWithCaller(Exception exception,
 		}
 	}
 }
+#nullable restore

src/Elastic.Apm/Logging/ScopedLogger.cs

@@ -16,7 +16,7 @@ internal class ScopedLogger : IApmLogger
 
 	public IApmLogger Logger { get; }
 
-#if !NET6_0_OR_GREATER
+#if !NET8_0_OR_GREATER
 	private readonly object _lock = new();
 #endif
 

src/Elastic.Apm/Metrics/MetricsProvider/BreakdownMetricsProvider.cs

@@ -17,7 +17,7 @@ internal class BreakdownMetricsProvider : IMetricsProvider
 		/// <summary>
 		/// Encapsulates types which are used as key to group MetricSets.
 		/// </summary>
-		private struct GroupKey
+		private readonly record struct GroupKey
 		{
 			public TransactionInfo Transaction { get; }
 			public SpanInfo Span { get; }

src/Elastic.Apm/Model/Error.cs

@@ -20,16 +20,14 @@ internal class Error : IError
 		[JsonIgnore]
 		internal IConfiguration Configuration { get; }
 
-		public Error(CapturedException capturedException, Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary<string, Label> labels = null
-		)
-			: this(transaction, parentId, loggerArg, labels) => Exception = capturedException;
+		public Error(CapturedException capturedException, Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary<string, Label> labels = null) :
+			this(transaction, parentId, loggerArg, labels) => Exception = capturedException;
 
 		public Error(ErrorLog errorLog, Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary<string, Label> labels = null) :
 			this(transaction, parentId, loggerArg, labels)
-			=> Log = errorLog;
-
+				=> Log = errorLog;
 
-		private Error(Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary<string, Label> labels = null)
+		private Error(Transaction transaction, string parentId, IApmLogger logger, Dictionary<string, Label> labels = null)
 		{
 			Timestamp = TimeUtils.TimestampNow();
 			Id = RandomGenerator.GenerateRandomBytesAsString(new byte[16]);
@@ -57,9 +55,7 @@ private Error(Transaction transaction, string parentId, IApmLogger loggerArg, Di
 
 			CheckAndCaptureBaggage(transaction);
 
-			IApmLogger logger = loggerArg?.Scoped($"{nameof(Error)}.{Id}");
-			logger.Trace()
-				?.Log("New Error instance created: {Error}. Time: {Time} (as timestamp: {Timestamp})",
+			logger?.Scoped(nameof(Error))?.Trace()?.Log("New Error instance created: {Error}. Time: {Time} (as timestamp: {Timestamp})",
 					this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp);
 		}
 

src/Elastic.Apm/Model/Span.cs

@@ -72,16 +72,16 @@ public Span(string name,
 			Activity current = null
 		)
 		{
-			InstrumentationFlag = instrumentationFlag;
-			Timestamp = timestamp ?? TimeUtils.TimestampNow();
-			Id = id ?? RandomGenerator.GenerateRandomBytesAsString(new byte[8]);
-			_logger = logger?.Scoped($"{nameof(Span)}.{Id}");
-
+			_logger = logger?.Scoped(nameof(Span));
 			_payloadSender = payloadSender;
 			_currentExecutionSegmentsContainer = currentExecutionSegmentsContainer;
 			_parentSpan = parentSpan;
 			_enclosingTransaction = enclosingTransaction;
 			_apmServerInfo = apmServerInfo;
+
+			InstrumentationFlag = instrumentationFlag;
+			Timestamp = timestamp ?? TimeUtils.TimestampNow();
+			Id = id ?? ActivitySpanId.CreateRandom().ToString();
 			IsExitSpan = isExitSpan;
 			Name = name;
 			Type = type;
@@ -123,9 +123,10 @@ public Span(string name,
 
 			_currentExecutionSegmentsContainer.CurrentSpan = this;
 
-			_logger.Trace()
-				?.Log("New Span instance created: {Span}. Start time: {Time} (as timestamp: {Timestamp}). Parent span: {Span}",
-					this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, _parentSpan);
+			var formattedTimestamp = _logger.IsEnabled(LogLevel.Trace) ? TimeUtils.FormatTimestampForLog(Timestamp) : string.Empty;
+
+			_logger?.Trace()?.Log("New Span instance created: {Span}. Start time: {Time} (as timestamp: {Timestamp}). Parent span: {Span}",
+				this, formattedTimestamp, Timestamp, _parentSpan);
 		}
 
 		private void CheckAndCaptureBaggage()
@@ -138,7 +139,7 @@ private void CheckAndCaptureBaggage()
 				if (!WildcardMatcher.IsAnyMatch(Configuration.BaggageToAttach, baggage.Key))
 					continue;
 
-				Otel ??= new OTel { Attributes = new Dictionary<string, object>() };
+				Otel ??= new OTel { Attributes = [] };
 
 				var newKey = $"baggage.{baggage.Key}";
 				Otel.Attributes[newKey] = baggage.Value;
@@ -392,17 +393,18 @@ internal Span StartSpanInternal(string name, string type, string subType = null,
 			string id = null, bool isExitSpan = false, IEnumerable<SpanLink> links = null, Activity current = null
 		)
 		{
-			var retVal = new Span(name, type, Id, TraceId, _enclosingTransaction, _payloadSender, _logger, _currentExecutionSegmentsContainer,
+			var span = new Span(name, type, Id, TraceId, _enclosingTransaction, _payloadSender, _logger, _currentExecutionSegmentsContainer,
 				_apmServerInfo, this, instrumentationFlag, captureStackTraceOnStart, timestamp, isExitSpan, id, links, current: current);
 
 			if (!string.IsNullOrEmpty(subType))
-				retVal.Subtype = subType;
+				span.Subtype = subType;
 
 			if (!string.IsNullOrEmpty(action))
-				retVal.Action = action;
+				span.Action = action;
 
-			_logger.Trace()?.Log("Starting {SpanDetails}", retVal.ToString());
-			return retVal;
+			_logger?.Trace()?.Log("Starting {SpanDetails}", span.ToString());
+
+			return span;
 		}
 
 		/// <summary>
@@ -416,12 +418,13 @@ public void End()
 			if (Outcome == Outcome.Unknown && !_outcomeChangedThroughApi)
 				Outcome = Outcome.Success;
 
+			var formattedTimestamp = _logger.IsEnabled(LogLevel.Trace) ? TimeUtils.FormatTimestampForLog(Timestamp) : string.Empty;
+
 			if (Duration.HasValue)
 			{
-				_logger.Trace()
-					?.Log("Ended {Span} (with Duration already set)." +
+				_logger?.Trace()?.Log("Ended {Span} (with Duration already set)." +
 						" Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
-						this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, Duration);
+						this, formattedTimestamp, Timestamp, Duration);
 
 				if (_parentSpan != null)
 					_parentSpan?._childDurationTimer.OnChildEnd((long)(Timestamp + Duration.Value * 1000));
@@ -448,10 +451,9 @@ public void End()
 
 				_childDurationTimer.OnSpanEnd(endTimestamp);
 
-				_logger.Trace()
-					?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
+				_logger?.Trace()?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
 						" End time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
-						this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp,
+						this, formattedTimestamp, Timestamp,
 						TimeUtils.FormatTimestampForLog(endTimestamp), endTimestamp, Duration);
 			}
 
@@ -473,7 +475,7 @@ public void End()
 			}
 			catch (Exception e)
 			{
-				_logger.Warning()?.LogException(e, "Failed deducing destination fields for span.");
+				_logger?.Warning()?.LogException(e, "Failed deducing destination fields for span.");
 			}
 
 			if (_isDropped && _context.IsValueCreated)
@@ -570,7 +572,7 @@ void QueueSpan(Span span)
 									DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, Duration!.Value);
 								break;
 						}
-						_logger.Trace()?.Log("Dropping fast exit span on composite span. Composite duration: {duration}", Composite.Sum);
+						_logger?.Trace()?.Log("Dropping fast exit span on composite span. Composite duration: {duration}", Composite.Sum);
 						return;
 					}
 					if (span.Duration < span.Configuration.ExitSpanMinDuration)
@@ -587,7 +589,7 @@ void QueueSpan(Span span)
 									DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, Duration!.Value);
 								break;
 						}
-						_logger.Trace()?.Log("Dropping fast exit span. Duration: {duration}", Duration);
+						_logger?.Trace()?.Log("Dropping fast exit span. Duration: {duration}", Duration);
 						return;
 					}
 				}
@@ -869,8 +871,7 @@ private Destination DeduceHttpDestination()
 			}
 			catch (Exception ex)
 			{
-				_logger.Trace()
-					?.LogException(ex, "Failed to deduce destination info from Context.Http."
+				_logger?.Trace()?.LogException(ex, "Failed to deduce destination info from Context.Http."
 						+ " Original URL: {OriginalUrl}. Context.Http.Url: {Context.Http.Url}."
 						, Context.Http.OriginalUrl, Context.Http.Url);
 				return null;

src/Elastic.Apm/Model/SpanTimerKey.cs

@@ -8,12 +8,14 @@ namespace Elastic.Apm.Model
 	/// <summary>
 	/// Encapsulates type and subtype
 	/// </summary>
-	internal struct SpanTimerKey
+	internal readonly record struct SpanTimerKey
 	{
 		public SpanTimerKey(string type, string subType) => (Type, SubType) = (type, subType);
 		public SpanTimerKey(string type) => (Type, SubType) = (type, null);
-		public string Type { get; }
-		public string SubType { get; set; }
-		public static SpanTimerKey AppSpanType => new SpanTimerKey("app");
+
+		public readonly string Type { get; }
+		public readonly string SubType { get; }
+
+		public static SpanTimerKey AppSpanType => new("app");
 	}
 }