Skip to content

perf: guard debug logging to avoid string allocations #4682

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
thomhurst merged 1 commit into from
Feb 6, 2026
Merged

perf: guard debug logging to avoid string allocations #4682

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
2 changes: 2 additions & 0 deletions TUnit.Engine/Logging/TUnitFrameworkLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,6 +93,8 @@ public bool IsEnabled(LogLevel logLevel)
return logLevel >= _minimumLogLevel;
}

public bool IsDebugEnabled => _minimumLogLevel <= LogLevel.Debug;

public async Task LogErrorAsync(string message)
{
await LogAsync(LogLevel.Error, message, null, (s, _) => s);
Expand Down
15 changes: 10 additions & 5 deletions TUnit.Engine/Scheduling/ConstraintKeyScheduler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -80,7 +80,8 @@ public async ValueTask ExecuteTestsWithConstraintsAsync(
if (canStart)
{
// Start the test immediately
await _logger.LogDebugAsync($"Starting test {test.TestId} with constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting test {test.TestId} with constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
startSignal.SetResult(true);

var testTask = ExecuteTestAndReleaseKeysAsync(test, constraintKeys, lockedKeys, lockObject, waitingTests, cancellationToken);
Expand All @@ -90,7 +91,8 @@ public async ValueTask ExecuteTestsWithConstraintsAsync(
else
{
// Queue the test to wait for its keys
await _logger.LogDebugAsync($"Queueing test {test.TestId} waiting for constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Queueing test {test.TestId} waiting for constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
waitingTests.Enqueue((test, constraintKeys, startSignal));

var testTask = WaitAndExecuteTestAsync(test, constraintKeys, startSignal, lockedKeys, lockObject, waitingTests, cancellationToken);
Expand Down Expand Up @@ -118,7 +120,8 @@ private async Task WaitAndExecuteTestAsync(
// Wait for signal to start
await startSignal.Task.ConfigureAwait(false);

await _logger.LogDebugAsync($"Starting previously queued test {test.TestId} with constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting previously queued test {test.TestId} with constraint keys: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);

await ExecuteTestAndReleaseKeysAsync(test, constraintKeys, lockedKeys, lockObject, waitingTests, cancellationToken).ConfigureAwait(false);
}
Expand Down Expand Up @@ -209,11 +212,13 @@ private async Task ExecuteTestAndReleaseKeysAsync(
}

// Log and signal tests to start outside the lock
await _logger.LogDebugAsync($"Released constraint keys for test {test.TestId}: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Released constraint keys for test {test.TestId}: {string.Join(", ", constraintKeys)}").ConfigureAwait(false);

foreach (var testToStart in testsToStart)
{
await _logger.LogDebugAsync($"Unblocking waiting test {testToStart.Test.TestId} with constraint keys: {string.Join(", ", testToStart.ConstraintKeys)}").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Unblocking waiting test {testToStart.Test.TestId} with constraint keys: {string.Join(", ", testToStart.ConstraintKeys)}").ConfigureAwait(false);
testToStart.StartSignal.SetResult(true);
}
}
Expand Down
24 changes: 16 additions & 8 deletions TUnit.Engine/Scheduling/TestScheduler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,7 +79,8 @@ public async Task<bool> ScheduleAndExecuteAsync(
return true;
}

await _logger.LogDebugAsync($"Scheduling execution of {testList.Count} tests").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Scheduling execution of {testList.Count} tests").ConfigureAwait(false);

var circularDependencies = _circularDependencyDetector.DetectCircularDependencies(testList);

Expand Down Expand Up @@ -163,7 +164,8 @@ private async Task ExecuteGroupedTestsAsync(

if (groupedTests.Parallel.Length > 0)
{
await _logger.LogDebugAsync($"Starting {groupedTests.Parallel.Length} parallel tests").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting {groupedTests.Parallel.Length} parallel tests").ConfigureAwait(false);
await ExecuteTestsAsync(groupedTests.Parallel, cancellationToken).ConfigureAwait(false);
}

Expand All @@ -176,14 +178,16 @@ private async Task ExecuteGroupedTestsAsync(
}
var orderedTestsArray = orderedTests.ToArray();

await _logger.LogDebugAsync($"Starting parallel group '{group.Key}' with {orderedTestsArray.Length} orders").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting parallel group '{group.Key}' with {orderedTestsArray.Length} orders").ConfigureAwait(false);
await ExecuteTestsAsync(orderedTestsArray, cancellationToken).ConfigureAwait(false);
}

foreach (var kvp in groupedTests.ConstrainedParallelGroups)
{
var constrainedTests = kvp.Value;
await _logger.LogDebugAsync($"Starting constrained parallel group '{kvp.Key}' with {constrainedTests.UnconstrainedTests.Length} unconstrained and {constrainedTests.KeyedTests.Length} keyed tests").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting constrained parallel group '{kvp.Key}' with {constrainedTests.UnconstrainedTests.Length} unconstrained and {constrainedTests.KeyedTests.Length} keyed tests").ConfigureAwait(false);

var tasks = new List<Task>();
if (constrainedTests.UnconstrainedTests.Length > 0)
Expand All @@ -202,13 +206,15 @@ private async Task ExecuteGroupedTestsAsync(

if (groupedTests.KeyedNotInParallel.Length > 0)
{
await _logger.LogDebugAsync($"Starting {groupedTests.KeyedNotInParallel.Length} keyed NotInParallel tests").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting {groupedTests.KeyedNotInParallel.Length} keyed NotInParallel tests").ConfigureAwait(false);
await _constraintKeyScheduler.ExecuteTestsWithConstraintsAsync(groupedTests.KeyedNotInParallel, cancellationToken).ConfigureAwait(false);
}

if (groupedTests.NotInParallel.Length > 0)
{
await _logger.LogDebugAsync($"Starting {groupedTests.NotInParallel.Length} global NotInParallel tests").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Starting {groupedTests.NotInParallel.Length} global NotInParallel tests").ConfigureAwait(false);
await ExecuteSequentiallyAsync(groupedTests.NotInParallel, cancellationToken).ConfigureAwait(false);
}

Expand Down Expand Up @@ -239,7 +245,8 @@ private async Task ProcessDynamicTestQueueAsync(CancellationToken cancellationTo
// Execute the batch of dynamic tests if any were found
if (dynamicTests.Count > 0)
{
await _logger.LogDebugAsync($"Executing {dynamicTests.Count} dynamic test(s)").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Executing {dynamicTests.Count} dynamic test(s)").ConfigureAwait(false);

// Group and execute just like regular tests
var dynamicTestsArray = dynamicTests.ToArray();
Expand Down Expand Up @@ -271,7 +278,8 @@ private async Task ProcessDynamicTestQueueAsync(CancellationToken cancellationTo

if (dynamicTests.Count > 0)
{
await _logger.LogDebugAsync($"Executing {dynamicTests.Count} remaining dynamic test(s)").ConfigureAwait(false);
if (_logger.IsDebugEnabled)
await _logger.LogDebugAsync($"Executing {dynamicTests.Count} remaining dynamic test(s)").ConfigureAwait(false);

var dynamicTestsArray = dynamicTests.ToArray();
var groupedDynamicTests = await _groupingService.GroupTestsByConstraintsAsync(dynamicTestsArray).ConfigureAwait(false);
Expand Down
Loading