diff --git a/src/CommonLib/AdaptiveTimeout.cs b/src/CommonLib/AdaptiveTimeout.cs index 409266c7..8e4a1f78 100644 --- a/src/CommonLib/AdaptiveTimeout.cs +++ b/src/CommonLib/AdaptiveTimeout.cs @@ -14,10 +14,12 @@ public sealed class AdaptiveTimeout : IDisposable { private readonly ConcurrentQueue _latestSuccessTimestamps; private readonly ILogger _log; private readonly TimeSpan _maxTimeout; + private readonly TimeSpan _minTimeout; private readonly bool _useAdaptiveTimeout; private readonly int _minSamplesForAdaptiveTimeout; private readonly bool _throwIfExcessiveTimeouts; private int _timeSpikeDecay; + private readonly TimeSpan _defaultMinTimeout = TimeSpan.FromSeconds(1); private const int TimeSpikePenalty = 2; private const int TimeSpikeForgiveness = 1; private const int TimeSpikeThreshold = 3; @@ -37,6 +39,7 @@ public AdaptiveTimeout(TimeSpan maxTimeout, ILogger log, int sampleCount = 100, if (log == null) throw new ArgumentNullException(nameof(log)); + _minTimeout = _defaultMinTimeout; _sampler = new ExecutionTimeSampler(log, sampleCount, logFrequency); _latestSuccessTimestamps = new ConcurrentQueue(); _log = log; @@ -46,6 +49,16 @@ public AdaptiveTimeout(TimeSpan maxTimeout, ILogger log, int sampleCount = 100, _throwIfExcessiveTimeouts = throwIfExcessiveTimeouts; } + public AdaptiveTimeout(TimeSpan maxTimeout, TimeSpan minTimeout, ILogger log, int sampleCount = 100, int logFrequency = 1000, int minSamplesForAdaptiveTimeout = 30, bool useAdaptiveTimeout = true, bool throwIfExcessiveTimeouts = false) + : this(maxTimeout, log, sampleCount, logFrequency, minSamplesForAdaptiveTimeout, useAdaptiveTimeout, throwIfExcessiveTimeouts) { + if (minTimeout < TimeSpan.Zero) + throw new ArgumentException("minTimeout must be non-negative", nameof(minTimeout)); + if (minTimeout >= maxTimeout) + throw new ArgumentException("minTimeout must be less than maxTimeout", nameof(minTimeout)); + + _minTimeout = minTimeout; + } + public void ClearSamples() { Interlocked.Exchange(ref _timeSpikeDecay, 0); _sampler.ClearSamples(); @@ -214,11 +227,11 @@ public void Dispose() { _sampler.Dispose(); } - // Within 5 standard deviations will have a conservative lower bound of catching 96% of executions (1 - 1/5^2), + // Within 7 standard deviations will have a conservative lower bound of catching 98% of executions (1 - 1/7^2), // regardless of sample shape // so long as those samples are independent and identically distributed // (and if they're not, our TimeSpikeSafetyValve should provide us with some adaptability) - // But the effective collection rate is probably closer to 98+% + // But the effective collection rate is probably closer to 99+% // (in part because we don't need to filter out "too fast" outliers) // But we'll cap at configured maximum timeout // https://modelassist.epixanalytics.com/space/EA/26574957/Tchebysheffs+Rule @@ -231,6 +244,7 @@ public TimeSpan GetAdaptiveTimeout() { var stdDev = _sampler.StandardDeviation(); var adaptiveTimeoutMs = _sampler.Average() + (stdDev * StdDevMultiplier); var cappedTimeoutMS = Math.Min(adaptiveTimeoutMs, _maxTimeout.TotalMilliseconds); + cappedTimeoutMS = Math.Max(cappedTimeoutMS, _minTimeout.TotalMilliseconds); return TimeSpan.FromMilliseconds(cappedTimeoutMS); } catch (Exception ex) { diff --git a/src/CommonLib/Processors/LocalGroupProcessor.cs b/src/CommonLib/Processors/LocalGroupProcessor.cs index c2048b04..c76239b5 100644 --- a/src/CommonLib/Processors/LocalGroupProcessor.cs +++ b/src/CommonLib/Processors/LocalGroupProcessor.cs @@ -36,7 +36,8 @@ public LocalGroupProcessor(ILdapUtils utils, ILogger log = null) { _openDomainAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMServer.OpenDomain))); _getAliasesAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMDomain.GetAliases))); _openAliasAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMDomain.OpenAlias))); - _getMembersAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMAlias.GetMembers))); + // Disabling adaptive timeout for GetMembers as it can be very chatty and we don't want timeouts to cause us to miss groups entirely. We can re-enable adaptive timeouts here in the future if we find a good way to handle timeouts without losing entire groups + _getMembersAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMAlias.GetMembers)), useAdaptiveTimeout: false); _lookupPrincipalBySidAdaptiveTimeout = new AdaptiveTimeout(maxTimeout: TimeSpan.FromMinutes(2), Logging.LogProvider.CreateLogger(nameof(ISAMServer.LookupPrincipalBySid))); } diff --git a/test/unit/AdaptiveTimeoutTest.cs b/test/unit/AdaptiveTimeoutTest.cs index c105c23d..29a97815 100644 --- a/test/unit/AdaptiveTimeoutTest.cs +++ b/test/unit/AdaptiveTimeoutTest.cs @@ -18,7 +18,8 @@ public AdaptiveTimeoutTest(ITestOutputHelper testOutputHelper) { [Fact] public async Task AdaptiveTimeout_GetAdaptiveTimeout_NotEnoughSamplesAsync() { var maxTimeout = TimeSpan.FromSeconds(1); - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3); + var minTimeout = TimeSpan.Zero; + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3); await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(50)); @@ -29,7 +30,8 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_NotEnoughSamplesAsync() { [Fact] public async Task AdaptiveTimeout_GetAdaptiveTimeout_AdaptiveDisabled() { var maxTimeout = TimeSpan.FromSeconds(1); - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3, false); + var minTimeout = TimeSpan.Zero; + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3, false); await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(50)); await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(50)); @@ -42,7 +44,8 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_AdaptiveDisabled() { [Fact] public async Task AdaptiveTimeout_GetAdaptiveTimeout() { var maxTimeout = TimeSpan.FromSeconds(1); - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3); + var minTimeout = TimeSpan.Zero; + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 10, 1000, 3); await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(40)); await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(50)); @@ -56,8 +59,9 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout() { public async Task AdaptiveTimeout_GetAdaptiveTimeout_TimeSpikeSafetyValve() { var tasks = new List(); var maxTimeout = TimeSpan.FromSeconds(1); + var minTimeout = TimeSpan.Zero; var numSamples = 30; - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 10); + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 10); for (int i = 0; i < numSamples; i++) tasks.Add(adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(10))); @@ -75,8 +79,9 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_TimeSpikeSafetyValve() { public async Task AdaptiveTimeout_GetAdaptiveTimeout_TimeSpikeSafetyValve_IgnoreHiccup() { var tasks = new List(); var maxTimeout = TimeSpan.FromSeconds(1); + var minTimeout = TimeSpan.Zero; var numSamples = 5; - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2); + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2); // Prepare our successful samples for (int i = 0; i < numSamples; i++) @@ -103,8 +108,9 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_TimeSpikeSafetyValve_Ignore public async Task AdaptiveTimeout_GetAdaptiveTimeout_ThrowWhenExcessiveTimeouts() { var tasks = new List(); var maxTimeout = TimeSpan.FromMilliseconds(500); + var minTimeout = TimeSpan.Zero; var numSamples = 5; - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2, throwIfExcessiveTimeouts: true); + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2, throwIfExcessiveTimeouts: true); for (int i = 0; i < numSamples; i++) tasks.Add(adaptiveTimeout.ExecuteWithTimeout((_) => Task.CompletedTask)); @@ -121,8 +127,9 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_ThrowWhenExcessiveTimeouts( public async Task AdaptiveTimeout_GetAdaptiveTimeout_DoNotThrowWhenExcessiveTimeouts() { var tasks = new List(); var maxTimeout = TimeSpan.FromMilliseconds(500); + var minTimeout = TimeSpan.Zero; var numSamples = 5; - var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2, throwIfExcessiveTimeouts: false); + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), numSamples, 1000, 2, throwIfExcessiveTimeouts: false); for (int i = 0; i < numSamples; i++) tasks.Add(adaptiveTimeout.ExecuteWithTimeout((_) => Task.CompletedTask)); @@ -135,6 +142,19 @@ public async Task AdaptiveTimeout_GetAdaptiveTimeout_DoNotThrowWhenExcessiveTime await Task.WhenAll(tasks); } + [Fact] + public async Task AdaptiveTimeout_GetAdaptiveTimeout_MinTimeout() { + var maxTimeout = TimeSpan.FromSeconds(1); + var minTimeout = TimeSpan.FromSeconds(0.5); + var adaptiveTimeout = new AdaptiveTimeout(maxTimeout, minTimeout, new TestLogger(_testOutputHelper, Microsoft.Extensions.Logging.LogLevel.Trace), 1, 1000, 1); + + await adaptiveTimeout.ExecuteWithTimeout(async (_) => await Task.Delay(50)); + + var adaptiveTimeoutResult = adaptiveTimeout.GetAdaptiveTimeout(); + Assert.Equal(minTimeout, adaptiveTimeoutResult); + Assert.True(adaptiveTimeoutResult < maxTimeout); + } + [Fact] public void AdaptiveTimeout_AtomicDecrementWithFloor_IsThreadSafe() { int value = 1000;