Skip to content

Avoid eager trace payload construction when diagnostics are disabled #1381

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.

Sign up for GitHub

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

Merged
berndverst merged 1 commit into from
Jul 27, 2026
Merged

Avoid eager trace payload construction when diagnostics are disabled #1381

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
267 changes: 267 additions & 0 deletions Test/DurableTask.Core.Tests/TraceHelperTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,15 +14,18 @@
#nullable enable
namespace DurableTask.Core.Tests
{
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using DurableTask.Core.Entities.OperationFormat;
using DurableTask.Core.Tracing;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using DiagnosticsActivityStatusCode = System.Diagnostics.ActivityStatusCode;
using TraceActivityStatusCode = DurableTask.Core.Tracing.ActivityStatusCode;

[TestClass]
[DoNotParallelize]
public class TraceHelperTests
{
Comment thread
berndverst marked this conversation as resolved.
[TestMethod]
Expand Down Expand Up @@ -64,6 +67,270 @@ public void EndActivitiesForEntityInvocationMarksFailures()

Assert.AreEqual(DiagnosticsActivityStatusCode.Error, activities[0].Status);
}

[TestMethod]
public void TraceFactoriesRunOnlyWhenRequestedLevelIsEnabled()
{
using var listener = new CapturingEventListener();
listener.Enable(EventLevel.Warning);

var instance = new OrchestrationInstance
{
InstanceId = "instance",
ExecutionId = "execution",
};
int traceFactoryCalls = 0;
int sessionFactoryCalls = 0;
int instanceFactoryCalls = 0;

TraceHelper.Trace(
TraceEventType.Information,
"TraceFactory",
() =>
{
traceFactoryCalls++;
return "trace payload";
});
TraceHelper.TraceSession(
TraceEventType.Information,
"SessionFactory",
"session",
() =>
{
sessionFactoryCalls++;
return "session payload";
});
TraceHelper.TraceInstance(
TraceEventType.Information,
"InstanceFactory",
instance,
() =>
{
instanceFactoryCalls++;
return "instance payload";
});

Assert.AreEqual(0, traceFactoryCalls);
Assert.AreEqual(0, sessionFactoryCalls);
Assert.AreEqual(0, instanceFactoryCalls);
Assert.AreEqual(0, listener.Events.Count);

listener.Enable(EventLevel.Informational);

TraceHelper.Trace(
TraceEventType.Information,
"TraceFactory",
() =>
{
traceFactoryCalls++;
return "trace payload";
});
TraceHelper.TraceSession(
TraceEventType.Information,
"SessionFactory",
"session",
() =>
{
sessionFactoryCalls++;
return "session payload";
});
TraceHelper.TraceInstance(
TraceEventType.Information,
"InstanceFactory",
instance,
() =>
{
instanceFactoryCalls++;
return "instance payload";
});

Assert.AreEqual(1, traceFactoryCalls);
Assert.AreEqual(1, sessionFactoryCalls);
Assert.AreEqual(1, instanceFactoryCalls);
Assert.AreEqual(3, listener.Events.Count);
AssertEvent(listener.Events[0], "trace payload", "TraceFactory");
AssertEvent(listener.Events[1], "session payload", "SessionFactory");
AssertEvent(listener.Events[2], "instance payload", "InstanceFactory");
}

[TestMethod]
public void TraceFormattingRunsOnlyWhenRequestedLevelIsEnabled()
{
using var listener = new CapturingEventListener();
listener.Enable(EventLevel.Warning);

var instance = new OrchestrationInstance
{
InstanceId = "instance",
ExecutionId = "execution",
};
var traceValue = new CountingValue("trace payload");
var sessionValue = new CountingValue("session payload");
var instanceValue = new CountingValue("instance payload");

TraceHelper.Trace(TraceEventType.Information, "TraceFormat", "{0}", traceValue);
TraceHelper.TraceSession(TraceEventType.Information, "SessionFormat", "session", "{0}", sessionValue);
TraceHelper.TraceInstance(TraceEventType.Information, "InstanceFormat", instance, "{0}", instanceValue);

Assert.AreEqual(0, traceValue.ToStringCalls);
Assert.AreEqual(0, sessionValue.ToStringCalls);
Assert.AreEqual(0, instanceValue.ToStringCalls);
Assert.AreEqual(0, listener.Events.Count);

listener.Enable(EventLevel.Informational);

TraceHelper.Trace(TraceEventType.Information, "TraceFormat", "{0}", traceValue);
TraceHelper.TraceSession(TraceEventType.Information, "SessionFormat", "session", "{0}", sessionValue);
TraceHelper.TraceInstance(TraceEventType.Information, "InstanceFormat", instance, "{0}", instanceValue);

Assert.AreEqual(1, traceValue.ToStringCalls);
Assert.AreEqual(1, sessionValue.ToStringCalls);
Assert.AreEqual(1, instanceValue.ToStringCalls);
Assert.AreEqual(3, listener.Events.Count);
AssertEvent(listener.Events[0], "trace payload", "TraceFormat");
AssertEvent(listener.Events[1], "session payload", "SessionFormat");
AssertEvent(listener.Events[2], "instance payload", "InstanceFormat");
}

[TestMethod]
public void TraceExceptionPayloadsRunOnlyWhenRequestedLevelIsEnabled()
{
using var listener = new CapturingEventListener();
listener.Enable(EventLevel.Warning);

var exception = new InvalidOperationException("failure");
int factoryCalls = 0;
var formatValue = new CountingValue("format payload");

Exception factoryResult = TraceHelper.TraceException(
TraceEventType.Information,
"ExceptionFactory",
exception,
() =>
{
factoryCalls++;
return "factory payload";
});
Exception formatResult = TraceHelper.TraceException(
TraceEventType.Information,
"ExceptionFormat",
exception,
"{0}",
formatValue);

Assert.AreSame(exception, factoryResult);
Assert.AreSame(exception, formatResult);
Assert.AreEqual(0, factoryCalls);
Assert.AreEqual(0, formatValue.ToStringCalls);
Assert.AreEqual(0, listener.Events.Count);

listener.Enable(EventLevel.Informational);

factoryResult = TraceHelper.TraceException(
TraceEventType.Information,
"ExceptionFactory",
exception,
() =>
{
factoryCalls++;
return "factory payload";
});
formatResult = TraceHelper.TraceException(
TraceEventType.Information,
"ExceptionFormat",
exception,
"{0}",
formatValue);

Assert.AreSame(exception, factoryResult);
Assert.AreSame(exception, formatResult);
Assert.AreEqual(1, factoryCalls);
Assert.AreEqual(1, formatValue.ToStringCalls);
Assert.AreEqual(2, listener.Events.Count);
AssertEvent(listener.Events[0], FormatExceptionMessage("factory payload", exception), "ExceptionFactory");
AssertEvent(listener.Events[1], FormatExceptionMessage("format payload", exception), "ExceptionFormat");
}

static void AssertEvent(CapturedEvent capturedEvent, string message, string eventType)
{
Assert.AreEqual(3, capturedEvent.EventId);
Assert.AreEqual(7, capturedEvent.PayloadCount);
Assert.AreEqual(message, capturedEvent.Message);
Assert.AreEqual(eventType, capturedEvent.EventType);
}

static string FormatExceptionMessage(string message, Exception exception)
{
return message + "\nException: " + exception.GetType() + " : " + exception.Message + "\n\t" +
exception.StackTrace + "\nInner Exception: " + exception.InnerException?.ToString();
Comment thread
berndverst marked this conversation as resolved.
Dismissed
}

sealed class CountingValue
{
readonly string value;

public CountingValue(string value)
{
this.value = value;
}

public int ToStringCalls { get; private set; }

public override string ToString()
{
this.ToStringCalls++;
return this.value;
}
}

sealed class CapturedEvent
{
public CapturedEvent(int eventId, int payloadCount, string message, string eventType)
{
this.EventId = eventId;
this.PayloadCount = payloadCount;
this.Message = message;
this.EventType = eventType;
}

public int EventId { get; }

public int PayloadCount { get; }

public string Message { get; }

public string EventType { get; }
}

sealed class CapturingEventListener : EventListener
{
readonly List<CapturedEvent> events = new List<CapturedEvent>();

public IReadOnlyList<CapturedEvent> Events => this.events;

public void Enable(EventLevel eventLevel)
{
this.EnableEvents(DefaultEventSource.Log, eventLevel, DefaultEventSource.Keywords.Diagnostics);
}

public override void Dispose()
{
this.DisableEvents(DefaultEventSource.Log);
base.Dispose();
}

protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
if (eventData.EventSource == DefaultEventSource.Log &&
eventData.Payload != null &&
eventData.Payload.Count == 7 &&
eventData.Payload[4] is string message &&
eventData.Payload[6] is string eventType)
{
this.events.Add(new CapturedEvent(eventData.EventId, eventData.Payload.Count, message, eventType));
}
}
}
}
}
#endif
15 changes: 10 additions & 5 deletions src/DurableTask.Core/TaskOrchestrationDispatcher.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ namespace DurableTask.Core
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Globalization;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
Expand Down Expand Up @@ -438,8 +439,10 @@ protected async Task<bool> OnProcessWorkItemAsync(TaskOrchestrationWorkItem work
TraceEventType.Verbose,
"TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin",
runtimeState.OrchestrationInstance!,
"Executing user orchestration: {0}",
JsonDataConverter.Default.Serialize(runtimeState.GetOrchestrationRuntimeStateDump(), true));
() => string.Format(
CultureInfo.InvariantCulture,
"Executing user orchestration: {0}",
JsonDataConverter.Default.Serialize(runtimeState.GetOrchestrationRuntimeStateDump(), true)));

if (!versioningFailed)
{
Expand Down Expand Up @@ -472,9 +475,11 @@ protected async Task<bool> OnProcessWorkItemAsync(TaskOrchestrationWorkItem work
TraceEventType.Information,
"TaskOrchestrationDispatcher-ExecuteUserOrchestration-End",
runtimeState.OrchestrationInstance!,
"Executed user orchestration. Received {0} orchestrator actions: {1}",
decisions.Count,
string.Join(", ", decisions.Select(d => d.Id + ":" + d.OrchestratorActionType)));
() => string.Format(
CultureInfo.InvariantCulture,
"Executed user orchestration. Received {0} orchestrator actions: {1}",
decisions.Count,
string.Join(", ", decisions.Select(d => d.Id + ":" + d.OrchestratorActionType))));

// TODO: Exception handling for invalid decisions, which is increasingly likely
// when custom middleware is involved (e.g. out-of-process scenarios).
Expand Down
18 changes: 18 additions & 0 deletions src/DurableTask.Core/Tracing/DefaultEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,24 @@ public static class Keywords
/// </summary>
public bool IsCriticalEnabled => IsEnabled(EventLevel.Critical, Keywords.Diagnostics);

[NonEvent]
internal bool IsEventEnabled(TraceEventType eventLevel)
{
switch (eventLevel)
{
case TraceEventType.Critical:
return IsCriticalEnabled;
case TraceEventType.Error:
return IsErrorEnabled;
case TraceEventType.Warning:
return IsWarningEnabled;
case TraceEventType.Information:
return IsInfoEnabled;
default:
return IsTraceEnabled;
}
}

/// <summary>
/// Trace an event for the supplied event type and parameters
/// </summary>
Expand Down
Loading
Loading