Skip to content

Add debug logging for parallel diagnosis #3329

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
Oct 7, 2025
Merged

Add debug logging for parallel diagnosis #3329

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: 1 addition & 1 deletion TUnit.Engine/Framework/TUnitServiceProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -211,7 +211,7 @@ public TUnitServiceProvider(IExtension extension,
testStateManager));

// Create scheduler configuration from command line options
var testGroupingService = Register<ITestGroupingService>(new TestGroupingService());
var testGroupingService = Register<ITestGroupingService>(new TestGroupingService(Logger));
var circularDependencyDetector = Register(new CircularDependencyDetector());

var constraintKeyScheduler = Register<IConstraintKeyScheduler>(new ConstraintKeyScheduler(
Expand Down
29 changes: 28 additions & 1 deletion TUnit.Engine/Scheduling/TestScheduler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -230,19 +230,28 @@ private async Task ExecuteTestWithParallelLimitAsync(
// Check if test has parallel limit constraint
if (test.Context.ParallelLimiter != null)
{
var limiterType = test.Context.ParallelLimiter.GetType().Name;
var semaphore = _parallelLimitLockProvider.GetLock(test.Context.ParallelLimiter);

await _logger.LogDebugAsync($"Test '{test.TestId}': Waiting for ParallelLimiter '{limiterType}' (available: {semaphore.CurrentCount}/{test.Context.ParallelLimiter.Limit})").ConfigureAwait(false);

await semaphore.WaitAsync(cancellationToken).ConfigureAwait(false);

await _logger.LogDebugAsync($"Test '{test.TestId}': Acquired ParallelLimiter '{limiterType}' (remaining: {semaphore.CurrentCount}/{test.Context.ParallelLimiter.Limit})").ConfigureAwait(false);

try
{
await _testRunner.ExecuteTestAsync(test, cancellationToken).ConfigureAwait(false);
}
finally
{
semaphore.Release();
await _logger.LogDebugAsync($"Test '{test.TestId}': Released ParallelLimiter '{limiterType}' (available: {semaphore.CurrentCount}/{test.Context.ParallelLimiter.Limit})").ConfigureAwait(false);
}
}
else
{
await _logger.LogDebugAsync($"Test '{test.TestId}': No ParallelLimiter, executing directly").ConfigureAwait(false);
await _testRunner.ExecuteTestAsync(test, cancellationToken).ConfigureAwait(false);
}
}
Expand Down Expand Up @@ -361,6 +370,8 @@ private async Task ExecuteParallelTestsWithLimitAsync(
int maxParallelism,
CancellationToken cancellationToken)
{
await _logger.LogDebugAsync($"Starting {tests.Length} tests with global max parallelism: {maxParallelism}").ConfigureAwait(false);

// Global semaphore limits total concurrent test execution
var globalSemaphore = new SemaphoreSlim(maxParallelism, maxParallelism);

Expand All @@ -383,16 +394,27 @@ private async Task ExecuteParallelTestsWithLimitAsync(
// Phase 1: Acquire ParallelLimiter first (if test has one)
if (test.Context.ParallelLimiter != null)
{
var limiterName = test.Context.ParallelLimiter.GetType().Name;
await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 1] Acquiring ParallelLimiter '{limiterName}' (limit: {test.Context.ParallelLimiter.Limit})").ConfigureAwait(false);

parallelLimiterSemaphore = _parallelLimitLockProvider.GetLock(test.Context.ParallelLimiter);
await parallelLimiterSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false);

await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 1] Acquired ParallelLimiter '{limiterName}'").ConfigureAwait(false);
}

try
{
// Phase 2: Acquire global semaphore
// At this point, we have the constrained resource (if needed),
// so we can immediately use the global slot for execution
await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 2] Acquiring global semaphore (available: {globalSemaphore.CurrentCount}/{maxParallelism})").ConfigureAwait(false);

await globalSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false);

var slotsUsed = maxParallelism - globalSemaphore.CurrentCount;
await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 2] Acquired global semaphore - executing (global slots used: {slotsUsed}/{maxParallelism})").ConfigureAwait(false);

try
{
// Execute the test
Expand All @@ -404,12 +426,17 @@ private async Task ExecuteParallelTestsWithLimitAsync(
{
// Always release global semaphore after execution
globalSemaphore.Release();
await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 2] Released global semaphore (available: {globalSemaphore.CurrentCount}/{maxParallelism})").ConfigureAwait(false);
}
}
finally
{
// Always release ParallelLimiter semaphore (if we acquired one)
parallelLimiterSemaphore?.Release();
if (parallelLimiterSemaphore != null)
{
parallelLimiterSemaphore.Release();
await _logger.LogDebugAsync($"Test '{test.TestId}': [Phase 1] Released ParallelLimiter").ConfigureAwait(false);
}
}
}).ToArray();

Expand Down
32 changes: 30 additions & 2 deletions TUnit.Engine/Services/TestGroupingService.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
using TUnit.Core;
using TUnit.Core.Logging;
using TUnit.Engine.Logging;
using TUnit.Engine.Models;
using TUnit.Engine.Scheduling;

Expand All @@ -14,6 +16,13 @@ internal interface ITestGroupingService

internal sealed class TestGroupingService : ITestGroupingService
{
private readonly TUnitFrameworkLogger _logger;

public TestGroupingService(TUnitFrameworkLogger logger)
{
_logger = logger;
}

private struct TestSortKey
{
public int ExecutionPriority { get; init; }
Expand All @@ -22,7 +31,7 @@ private struct TestSortKey
public NotInParallelConstraint? NotInParallelConstraint { get; init; }
}

public ValueTask<GroupedTests> GroupTestsByConstraintsAsync(IEnumerable<AbstractExecutableTest> tests)
public async ValueTask<GroupedTests> GroupTestsByConstraintsAsync(IEnumerable<AbstractExecutableTest> tests)
{
var testsWithKeys = new List<(AbstractExecutableTest Test, TestSortKey Key)>();
foreach (var test in tests)
Expand Down Expand Up @@ -78,24 +87,34 @@ public ValueTask<GroupedTests> GroupTestsByConstraintsAsync(IEnumerable<Abstract
}
var notInParallel = sortKey.NotInParallelConstraint;

// Log parallel limiter if present
var parallelLimiterInfo = test.Context.ParallelLimiter != null
? $" [ParallelLimiter: {test.Context.ParallelLimiter.GetType().Name} (limit: {test.Context.ParallelLimiter.Limit})]"
: "";

if (parallelGroup != null && notInParallel != null)
{
// Test has both ParallelGroup and NotInParallel constraints
await _logger.LogDebugAsync($"Test '{test.TestId}': → ConstrainedParallelGroup '{parallelGroup.Group}' + NotInParallel{parallelLimiterInfo}").ConfigureAwait(false);
ProcessCombinedConstraints(test, sortKey.ClassFullName, parallelGroup, notInParallel, constrainedParallelGroups);
}
else if (parallelGroup != null)
{
// Only ParallelGroup constraint
await _logger.LogDebugAsync($"Test '{test.TestId}': → ParallelGroup '{parallelGroup.Group}'{parallelLimiterInfo}").ConfigureAwait(false);
ProcessParallelGroupConstraint(test, parallelGroup, parallelGroups);
}
else if (notInParallel != null)
{
// Only NotInParallel constraint
var keys = notInParallel.NotInParallelConstraintKeys.Count > 0 ? $" (keys: {string.Join(", ", notInParallel.NotInParallelConstraintKeys)})" : "";
await _logger.LogDebugAsync($"Test '{test.TestId}': → NotInParallel{keys}{parallelLimiterInfo}").ConfigureAwait(false);
ProcessNotInParallelConstraint(test, sortKey.ClassFullName, notInParallel, notInParallelList, keyedNotInParallelList);
}
else
{
// No constraints - can run in parallel
await _logger.LogDebugAsync($"Test '{test.TestId}': → Parallel (no constraints){parallelLimiterInfo}").ConfigureAwait(false);
parallelTests.Add(test);
}
}
Expand Down Expand Up @@ -177,7 +196,16 @@ public ValueTask<GroupedTests> GroupTestsByConstraintsAsync(IEnumerable<Abstract
ConstrainedParallelGroups = finalConstrainedGroups
};

return new ValueTask<GroupedTests>(result);
// Log summary of test categorization
await _logger.LogDebugAsync("═══ Test Grouping Summary ═══").ConfigureAwait(false);
await _logger.LogDebugAsync($" Parallel (no constraints): {parallelTests.Count} tests").ConfigureAwait(false);
await _logger.LogDebugAsync($" ParallelGroups: {parallelGroups.Count} groups").ConfigureAwait(false);
await _logger.LogDebugAsync($" ConstrainedParallelGroups: {finalConstrainedGroups.Count} groups").ConfigureAwait(false);
await _logger.LogDebugAsync($" NotInParallel (global): {sortedNotInParallel.Length} tests").ConfigureAwait(false);
await _logger.LogDebugAsync($" KeyedNotInParallel: {keyedArrays.Length} tests").ConfigureAwait(false);
await _logger.LogDebugAsync("════════════════════════════").ConfigureAwait(false);

return result;
}

private static void ProcessNotInParallelConstraint(
Expand Down
Loading