Skip to content
Permalink

Comparing changes

Choose two branches to see what’s changed or to start a new pull request. If you need to, you can also or learn more about diff comparisons.

Open a pull request

Create a new pull request by comparing changes across two branches. If you need to, you can also . Learn more about diff comparisons here.
base repository: elastic/apm-agent-dotnet
Failed to load repositories. Confirm that selected base ref is valid, then try again.
Loading
base: main
Choose a base ref
...
head repository: elastic/apm-agent-dotnet
Failed to load repositories. Confirm that selected head ref is valid, then try again.
Loading
compare: phase-two-logger-optimisations
Choose a head ref
Can’t automatically merge. Don’t worry, you can still create the pull request.
  • 4 commits
  • 11 files changed
  • 1 contributor

Commits on Nov 27, 2024

  1. Copy the full SHA
    2e63867 View commit details
  2. Reduce allocations from logging infrastructure

    - Cache scoped loggers to avoid allocations per span, transaction and error
    stevejgordon committed Nov 27, 2024
    Copy the full SHA
    02c433f View commit details
  3. Copy the full SHA
    3386ba6 View commit details

Commits on Nov 28, 2024

  1. Copy the full SHA
    0aa4e8a View commit details
4 changes: 2 additions & 2 deletions src/Elastic.Apm/Api/Tracer.cs
Original file line number Diff line number Diff line change
@@ -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("{Scope} Starting {TransactionValue}", nameof(Tracer), retVal);
return retVal;
}

Original file line number Diff line number Diff line change
@@ -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
62 changes: 50 additions & 12 deletions src/Elastic.Apm/Logging/IApmLoggingExtensions.cs
Original file line number Diff line number Diff line change
@@ -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,49 @@

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.
private static readonly ConcurrentDictionary<string, 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;

if (!ScopedLoggers.TryGetValue(scope, out var scopedLogger))
{
// Ensure we don't allow creations of scoped loggers 'wrapping' other scoped loggers
var potentialScopedLogger = new ScopedLogger(logger is ScopedLogger s ? s.Logger : logger, scope);

if (ScopedLoggers.TryAdd(scope, potentialScopedLogger))
{
scopedLogger = potentialScopedLogger;
}
else
{
scopedLogger = ScopedLoggers[scope];
}
}

return scopedLogger;
}

private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception? exception, params object?[]? args)
{
try
{
@@ -28,9 +65,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 +81,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 +99,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 +199,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 +216,4 @@ public void LogExceptionWithCaller(Exception exception,
}
}
}
#nullable restore
2 changes: 1 addition & 1 deletion src/Elastic.Apm/Logging/ScopedLogger.cs
Original file line number Diff line number Diff line change
@@ -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

Original file line number Diff line number Diff line change
@@ -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; }
14 changes: 5 additions & 9 deletions src/Elastic.Apm/Model/Error.cs
Original file line number Diff line number Diff line change
@@ -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);
}

51 changes: 26 additions & 25 deletions src/Elastic.Apm/Model/Span.cs
Original file line number Diff line number Diff line change
@@ -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;
10 changes: 6 additions & 4 deletions src/Elastic.Apm/Model/SpanTimerKey.cs
Original file line number Diff line number Diff line change
@@ -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");
}
}
Loading