From 1adae59b1878ae6a6e0ef061a7070c0822a5c755 Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Thu, 28 Nov 2024 12:05:52 +0000 Subject: [PATCH] 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 | 4 +- ...ppSettingsConfigurationKeyValueProvider.cs | 8 +-- .../Logging/IApmLoggingExtensions.cs | 66 +++++++++++++++---- src/Elastic.Apm/Logging/ScopedLogger.cs | 2 +- .../BreakdownMetricsProvider.cs | 2 +- src/Elastic.Apm/Model/Error.cs | 14 ++-- src/Elastic.Apm/Model/Span.cs | 51 +++++++------- src/Elastic.Apm/Model/SpanTimerKey.cs | 10 +-- src/Elastic.Apm/Model/Transaction.cs | 52 ++++++++------- .../OpenTelemetry/ElasticActivityListener.cs | 25 ++++--- .../AzureFunctionsContext.cs | 2 +- 11 files changed, 139 insertions(+), 97 deletions(-) diff --git a/src/Elastic.Apm/Api/Tracer.cs b/src/Elastic.Apm/Api/Tracer.cs index 5c810dbf9..d91fc97ee 100644 --- a/src/Elastic.Apm/Api/Tracer.cs +++ b/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; } diff --git a/src/Elastic.Apm/Config/Net4FullFramework/AppSettingsConfigurationKeyValueProvider.cs b/src/Elastic.Apm/Config/Net4FullFramework/AppSettingsConfigurationKeyValueProvider.cs index 4f7d18c21..84503d367 100644 --- a/src/Elastic.Apm/Config/Net4FullFramework/AppSettingsConfigurationKeyValueProvider.cs +++ b/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 diff --git a/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs b/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs index 4b9b4521c..9aa11559a 100644 --- a/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs +++ b/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 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 Formatters = new(); - private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception e, params object[] args) + /// + /// Returns a ScopedLogger, potentially from the cache. + /// + /// An existing . + /// The name of the scope. + /// A new scoped logger or null of the is null. + /// Requires to be non-null and non-empty. + 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 args) + private static LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection? 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 diff --git a/src/Elastic.Apm/Logging/ScopedLogger.cs b/src/Elastic.Apm/Logging/ScopedLogger.cs index ed49289f1..1ad8d35ed 100644 --- a/src/Elastic.Apm/Logging/ScopedLogger.cs +++ b/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 diff --git a/src/Elastic.Apm/Metrics/MetricsProvider/BreakdownMetricsProvider.cs b/src/Elastic.Apm/Metrics/MetricsProvider/BreakdownMetricsProvider.cs index 576edc21b..c2214fc38 100644 --- a/src/Elastic.Apm/Metrics/MetricsProvider/BreakdownMetricsProvider.cs +++ b/src/Elastic.Apm/Metrics/MetricsProvider/BreakdownMetricsProvider.cs @@ -17,7 +17,7 @@ internal class BreakdownMetricsProvider : IMetricsProvider /// /// Encapsulates types which are used as key to group MetricSets. /// - private struct GroupKey + private readonly record struct GroupKey { public TransactionInfo Transaction { get; } public SpanInfo Span { get; } diff --git a/src/Elastic.Apm/Model/Error.cs b/src/Elastic.Apm/Model/Error.cs index f2c15f8db..6aa8fe7ae 100644 --- a/src/Elastic.Apm/Model/Error.cs +++ b/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 labels = null - ) - : this(transaction, parentId, loggerArg, labels) => Exception = capturedException; + public Error(CapturedException capturedException, Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary labels = null) : + this(transaction, parentId, loggerArg, labels) => Exception = capturedException; public Error(ErrorLog errorLog, Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary labels = null) : this(transaction, parentId, loggerArg, labels) - => Log = errorLog; - + => Log = errorLog; - private Error(Transaction transaction, string parentId, IApmLogger loggerArg, Dictionary labels = null) + private Error(Transaction transaction, string parentId, IApmLogger logger, Dictionary 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); } diff --git a/src/Elastic.Apm/Model/Span.cs b/src/Elastic.Apm/Model/Span.cs index 9aff679cb..707c9f45d 100644 --- a/src/Elastic.Apm/Model/Span.cs +++ b/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() }; + 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 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; } /// @@ -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; diff --git a/src/Elastic.Apm/Model/SpanTimerKey.cs b/src/Elastic.Apm/Model/SpanTimerKey.cs index a881ceecf..2301fdc3b 100644 --- a/src/Elastic.Apm/Model/SpanTimerKey.cs +++ b/src/Elastic.Apm/Model/SpanTimerKey.cs @@ -8,12 +8,14 @@ namespace Elastic.Apm.Model /// /// Encapsulates type and subtype /// - 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"); } } diff --git a/src/Elastic.Apm/Model/Transaction.cs b/src/Elastic.Apm/Model/Transaction.cs index 9280a7809..3558d7a56 100644 --- a/src/Elastic.Apm/Model/Transaction.cs +++ b/src/Elastic.Apm/Model/Transaction.cs @@ -280,7 +280,7 @@ internal Transaction( } catch (Exception e) { - _logger.Error()?.LogException(e, "Error setting trace context on created activity"); + _logger?.Error()?.LogException(e, "Error setting trace context on created activity"); } } else @@ -327,22 +327,22 @@ internal Transaction( SpanCount = new SpanCount(); _currentExecutionSegmentsContainer.CurrentTransaction = this; + var formattedTimestamp = _logger.IsEnabled(LogLevel.Trace) ? TimeUtils.FormatTimestampForLog(Timestamp) : string.Empty; + if (isSamplingFromDistributedTracingData) { - _logger.Trace() - ?.Log("New Transaction instance created: {Transaction}. " + + _logger?.Trace()?.Log("New Transaction instance created: {Transaction}. " + "IsSampled ({IsSampled}) and SampleRate ({SampleRate}) is based on incoming distributed tracing data ({DistributedTracingData})." + " Start time: {Time} (as timestamp: {Timestamp})", - this, IsSampled, SampleRate, distributedTracingData, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp); + this, IsSampled, SampleRate, distributedTracingData, formattedTimestamp, Timestamp); } else { - _logger.Trace() - ?.Log("New Transaction instance created: {Transaction}. " + + _logger?.Trace()?.Log("New Transaction instance created: {Transaction}. " + "IsSampled ({IsSampled}) is based on the given sampler ({Sampler})." + " Start time: {Time} (as timestamp: {Timestamp})", - this, IsSampled, sampler, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp); + this, IsSampled, sampler, formattedTimestamp, Timestamp); } } @@ -646,34 +646,38 @@ public string EnsureParentId() public void End() { + var endTimestamp = TimeUtils.TimestampNow(); + // If the outcome is still unknown and it was not specifically set to unknown, then it's success 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 {Transaction} (with Duration already set)." + + _logger?.Trace()?.Log("Ended {Transaction} (with Duration already set)." + " Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms", - this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, Duration); + this, formattedTimestamp, Timestamp, Duration); ChildDurationTimer.OnSpanEnd((long)(Timestamp + Duration.Value * 1000)); } else { - Assertion.IfEnabled?.That(!_isEnded, - $"Transaction's Duration doesn't have value even though {nameof(End)} method was already called." + - $" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" + - $" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." + - $" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}"); + if (Assertion.IsEnabled && _isEnded) + { + throw new AssertionFailedException($"Transaction's Duration doesn't have value even though {nameof(End)} method was already called." + + $" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" + + $" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." + + $" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}"); + } - var endTimestamp = TimeUtils.TimestampNow(); ChildDurationTimer.OnSpanEnd(endTimestamp); Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, endTimestamp); - _logger.Trace() - ?.Log("Ended {Transaction}. Start time: {Time} (as timestamp: {Timestamp})," + + + _logger?.Trace()?.Log("Ended {Transaction}. 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); } @@ -699,8 +703,7 @@ public void End() { if (!CompressionBuffer.IsSampled && _apmServerInfo?.Version >= new ElasticVersion(8, 0, 0, string.Empty)) { - _logger?.Debug() - ?.Log("Dropping unsampled compressed span - unsampled span won't be sent on APM Server v8+. SpanId: {id}", + _logger?.Debug()?.Log("Dropping unsampled compressed span - unsampled span won't be sent on APM Server v8+. SpanId: {id}", CompressionBuffer.Id); } else @@ -734,8 +737,7 @@ public void End() } else { - _logger?.Debug() - ?.Log("Dropping unsampled transaction - unsampled transactions won't be sent on APM Server v8+. TransactionId: {id}", Id); + _logger?.Debug()?.Log("Dropping unsampled transaction - unsampled transactions won't be sent on APM Server v8+. TransactionId: {id}", Id); } _currentExecutionSegmentsContainer.CurrentTransaction = null; @@ -773,7 +775,7 @@ internal Span StartSpanInternal(string name, string type, string subType = null, { var retVal = new Span(name, type, Id, TraceId, this, _sender, _logger, _currentExecutionSegmentsContainer, _apmServerInfo, instrumentationFlag: instrumentationFlag, captureStackTraceOnStart: captureStackTraceOnStart, timestamp: timestamp, - isExitSpan: isExitSpan, id: id, links: links, current: current); + isExitSpan: isExitSpan, id: id, links: links); ChildDurationTimer.OnChildStart(retVal.Timestamp); if (!string.IsNullOrEmpty(subType)) @@ -782,7 +784,7 @@ internal Span StartSpanInternal(string name, string type, string subType = null, if (!string.IsNullOrEmpty(action)) retVal.Action = action; - _logger.Trace()?.Log("Starting {SpanDetails}", retVal.ToString()); + _logger?.Trace()?.Log("Starting {SpanDetails}", retVal.ToString()); return retVal; } diff --git a/src/Elastic.Apm/OpenTelemetry/ElasticActivityListener.cs b/src/Elastic.Apm/OpenTelemetry/ElasticActivityListener.cs index dca9db9c7..a7678f7e7 100644 --- a/src/Elastic.Apm/OpenTelemetry/ElasticActivityListener.cs +++ b/src/Elastic.Apm/OpenTelemetry/ElasticActivityListener.cs @@ -3,10 +3,9 @@ // 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 NET5_0_OR_GREATER +#if NET8_0_OR_GREATER using System; -using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -22,15 +21,15 @@ namespace Elastic.Apm.OpenTelemetry { public class ElasticActivityListener : IDisposable { - private static readonly string[] ServerPortAttributeKeys = new[] { SemanticConventions.ServerPort, SemanticConventions.NetPeerPort }; + private static readonly string[] ServerPortAttributeKeys = [SemanticConventions.ServerPort, SemanticConventions.NetPeerPort]; private static readonly string[] ServerAddressAttributeKeys = - new[] { SemanticConventions.ServerAddress, SemanticConventions.NetPeerName, SemanticConventions.NetPeerIp }; + [SemanticConventions.ServerAddress, SemanticConventions.NetPeerName, SemanticConventions.NetPeerIp]; private static readonly string[] HttpAttributeKeys = - new[] { SemanticConventions.UrlFull, SemanticConventions.HttpUrl, SemanticConventions.HttpScheme }; + [SemanticConventions.UrlFull, SemanticConventions.HttpUrl, SemanticConventions.HttpScheme]; - private static readonly string[] HttpUrlAttributeKeys = new[] { SemanticConventions.UrlFull, SemanticConventions.HttpUrl }; + private static readonly string[] HttpUrlAttributeKeys = [SemanticConventions.UrlFull, SemanticConventions.HttpUrl]; private readonly ConditionalWeakTable _activeSpans = new(); private readonly ConditionalWeakTable _activeTransactions = new(); @@ -77,7 +76,7 @@ internal void Start(Tracer tracerInternal) if (HasServiceBusInstrumentation && activity.Tags.Any(kvp => kvp.Key.Equals("az.namespace", StringComparison.Ordinal) && kvp.Value.Equals("Microsoft.ServiceBus", StringComparison.Ordinal))) { - _logger.Debug()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped 'Microsoft.ServiceBus' " + + _logger?.Debug()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped 'Microsoft.ServiceBus' " + "activity because 'Elastic.Apm.Azure.ServiceBus' is present in the application.", activity.DisplayName, activity.Id, activity.TraceId); @@ -87,7 +86,7 @@ internal void Start(Tracer tracerInternal) if (HasStorageInstrumentation && activity.Tags.Any(kvp => kvp.Key.Equals("az.namespace", StringComparison.Ordinal) && kvp.Value.Equals("Microsoft.Storage", StringComparison.Ordinal))) { - _logger.Debug()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped 'Microsoft.Storage' " + + _logger?.Debug()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped 'Microsoft.Storage' " + "activity because 'Elastic.Apm.Azure.Storage' is present in the application.", activity.DisplayName, activity.Id, activity.TraceId); @@ -96,12 +95,12 @@ internal void Start(Tracer tracerInternal) if (KnownListeners.SkippedActivityNamesSet.Contains(activity.DisplayName)) { - _logger.Trace()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped because it matched " + - "a skipped activity name defined in KnownListeners."); + _logger?.Trace()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId} skipped because it matched " + + "a skipped activity name defined in KnownListeners.", activity.DisplayName, activity.Id, activity.TraceId); return; } - _logger.Trace()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId}", + _logger?.Trace()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId}", activity.DisplayName, activity.Id, activity.TraceId); var spanLinks = new List(activity.Links.Count()); @@ -176,12 +175,12 @@ private void CreateSpanForActivity(Activity activity, long timestamp, List