async Task ExceptionTraceWrapperAsync( WorkItemDispatcherContext context, string workItemId, string operation, Func <Task> asyncAction) { try { await asyncAction(); } catch (Exception exception) when(!Utils.IsFatal(exception)) { // eat and move on this.LogHelper.ProcessWorkItemFailed(context, workItemId, operation, exception); TraceHelper.TraceException(TraceEventType.Error, "WorkItemDispatcher-ExceptionTraceError", exception); } }
/// <summary> /// Starts the work item dispatcher /// </summary> /// <exception cref="InvalidOperationException">Exception if dispatcher has already been started</exception> public async Task StartAsync() { if (!this.isStarted) { await this.initializationLock.WaitAsync(); try { if (this.isStarted) { throw TraceHelper.TraceException(TraceEventType.Error, "WorkItemDispatcherStart-AlreadyStarted", new InvalidOperationException($"WorkItemDispatcher '{this.name}' has already started")); } this.concurrencyLock?.Dispose(); this.concurrencyLock = new SemaphoreSlim(this.MaxConcurrentWorkItems); this.shutdownCancellationTokenSource?.Dispose(); this.shutdownCancellationTokenSource = new CancellationTokenSource(); this.isStarted = true; TraceHelper.Trace(TraceEventType.Information, "WorkItemDispatcherStart", $"WorkItemDispatcher('{this.name}') starting. Id {this.id}."); for (var i = 0; i < this.DispatcherCount; i++) { string dispatcherId = i.ToString(); var context = new WorkItemDispatcherContext(this.name, this.id, dispatcherId); this.LogHelper.DispatcherStarting(context); // We just want this to Run we intentionally don't wait #pragma warning disable 4014 Task.Run(() => this.DispatchAsync(context)); #pragma warning restore 4014 } } finally { this.initializationLock.Release(); } } }
async Task ProcessWorkItemAsync(WorkItemDispatcherContext context, object workItemObj) { var workItem = (T)workItemObj; var abortWorkItem = true; string workItemId = string.Empty; try { workItemId = this.workItemIdentifier(workItem); TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherProcess-Begin", GetFormattedLog(context.DispatcherId, $"Starting to process workItem {workItemId}")); await ProcessWorkItem(workItem); AdjustDelayModifierOnSuccess(); TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherProcess-End", GetFormattedLog(context.DispatcherId, $"Finished processing workItem {workItemId}")); abortWorkItem = false; } catch (TypeMissingException exception) { TraceHelper.TraceException( TraceEventType.Error, "WorkItemDispatcherProcess-TypeMissingException", exception, GetFormattedLog(context.DispatcherId, $"Exception while processing workItem {workItemId}")); TraceHelper.Trace( TraceEventType.Error, "WorkItemDispatcherProcess-TypeMissingBackingOff", "Backing off after invalid operation by " + BackOffIntervalOnInvalidOperationSecs); // every time we hit invalid operation exception we back off the dispatcher AdjustDelayModifierOnFailure(BackOffIntervalOnInvalidOperationSecs); } catch (Exception exception) when(!Utils.IsFatal(exception)) { TraceHelper.TraceException( TraceEventType.Error, "WorkItemDispatcherProcess-Exception", exception, GetFormattedLog(context.DispatcherId, $"Exception while processing workItem {workItemId}")); int delayInSecs = this.GetDelayInSecondsAfterOnProcessException(exception); if (delayInSecs > 0) { TraceHelper.Trace( TraceEventType.Error, "WorkItemDispatcherProcess-BackingOff", "Backing off after exception by at least " + delayInSecs + " until " + CountDownToZeroDelay + " successful operations"); AdjustDelayModifierOnFailure(delayInSecs); } else { // if the derived dispatcher doesn't think this exception worthy of back-off then // count it as a 'successful' operation AdjustDelayModifierOnSuccess(); } } finally { Interlocked.Decrement(ref this.concurrentWorkItemCount); this.concurrencyLock.Release(); } if (abortWorkItem && this.AbortWorkItem != null) { await ExceptionTraceWrapperAsync(() => this.AbortWorkItem(workItem)); } if (this.SafeReleaseWorkItem != null) { await ExceptionTraceWrapperAsync(() => this.SafeReleaseWorkItem(workItem)); } }
async Task DispatchAsync(string dispatcherId) { var context = new WorkItemDispatcherContext(this.name, this.id, dispatcherId); while (this.isStarted) { if (!await this.concurrencyLock.WaitAsync(TimeSpan.FromSeconds(5))) { TraceHelper.Trace( TraceEventType.Warning, "WorkItemDispatcherDispatch-MaxOperations", GetFormattedLog(dispatcherId, $"Max concurrent operations ({this.concurrentWorkItemCount}) are already in progress. Still waiting for next accept.")); continue; } var delaySecs = 0; T workItem = default(T); try { Interlocked.Increment(ref this.activeFetchers); TraceHelper.Trace( TraceEventType.Verbose, "WorkItemDispatcherDispatch-StartFetch", GetFormattedLog(dispatcherId, $"Starting fetch with timeout of {DefaultReceiveTimeout} ({this.concurrentWorkItemCount}/{MaxConcurrentWorkItems} max)")); Stopwatch timer = Stopwatch.StartNew(); workItem = await FetchWorkItem(DefaultReceiveTimeout, this.shutdownCancellationTokenSource.Token); TraceHelper.Trace( TraceEventType.Verbose, "WorkItemDispatcherDispatch-EndFetch", GetFormattedLog(dispatcherId, $"After fetch ({timer.ElapsedMilliseconds} ms) ({this.concurrentWorkItemCount}/{MaxConcurrentWorkItems} max)")); } catch (TimeoutException) { delaySecs = 0; } catch (TaskCanceledException exception) { TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherDispatch-TaskCanceledException", GetFormattedLog(dispatcherId, $"TaskCanceledException while fetching workItem, should be harmless: {exception.Message}")); delaySecs = this.GetDelayInSecondsAfterOnFetchException(exception); } catch (Exception exception) { if (!this.isStarted) { TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherDispatch-HarmlessException", GetFormattedLog(dispatcherId, $"Harmless exception while fetching workItem after Stop(): {exception.Message}")); } else { // TODO : dump full node context here TraceHelper.TraceException( TraceEventType.Warning, "WorkItemDispatcherDispatch-Exception", exception, GetFormattedLog(dispatcherId, $"Exception while fetching workItem: {exception.Message}")); delaySecs = this.GetDelayInSecondsAfterOnFetchException(exception); } } finally { Interlocked.Decrement(ref this.activeFetchers); } var scheduledWorkItem = false; if (!(Equals(workItem, default(T)))) { if (!this.isStarted) { if (this.SafeReleaseWorkItem != null) { await this.SafeReleaseWorkItem(workItem); } } else { Interlocked.Increment(ref this.concurrentWorkItemCount); // We just want this to Run we intentionally don't wait #pragma warning disable 4014 Task.Run(() => ProcessWorkItemAsync(context, workItem)); #pragma warning restore 4014 scheduledWorkItem = true; } } delaySecs = Math.Max(this.delayOverrideSecs, delaySecs); if (delaySecs > 0) { await Task.Delay(TimeSpan.FromSeconds(delaySecs)); } if (!scheduledWorkItem) { this.concurrencyLock.Release(); } } }
async Task DispatchAsync(WorkItemDispatcherContext context) { string dispatcherId = context.DispatcherId; bool logThrottle = true; while (this.isStarted) { if (!await this.concurrencyLock.WaitAsync(TimeSpan.FromSeconds(5))) { if (logThrottle) { // This can happen frequently under heavy load. // To avoid log spam, we log just once until we can proceed. this.LogHelper.FetchingThrottled( context, this.concurrentWorkItemCount, this.MaxConcurrentWorkItems); TraceHelper.Trace( TraceEventType.Warning, "WorkItemDispatcherDispatch-MaxOperations", this.GetFormattedLog(dispatcherId, $"Max concurrent operations ({this.concurrentWorkItemCount}) are already in progress. Still waiting for next accept.")); logThrottle = false; } continue; } logThrottle = true; var delaySecs = 0; T workItem = default(T); try { Interlocked.Increment(ref this.activeFetchers); this.LogHelper.FetchWorkItemStarting(context, DefaultReceiveTimeout, this.concurrentWorkItemCount, this.MaxConcurrentWorkItems); TraceHelper.Trace( TraceEventType.Verbose, "WorkItemDispatcherDispatch-StartFetch", this.GetFormattedLog(dispatcherId, $"Starting fetch with timeout of {DefaultReceiveTimeout} ({this.concurrentWorkItemCount}/{this.MaxConcurrentWorkItems} max)")); Stopwatch timer = Stopwatch.StartNew(); workItem = await this.FetchWorkItem(DefaultReceiveTimeout, this.shutdownCancellationTokenSource.Token); if (!IsNull(workItem)) { string workItemId = this.workItemIdentifier(workItem); this.LogHelper.FetchWorkItemCompleted( context, workItemId, timer.Elapsed, this.concurrentWorkItemCount, this.MaxConcurrentWorkItems); } TraceHelper.Trace( TraceEventType.Verbose, "WorkItemDispatcherDispatch-EndFetch", this.GetFormattedLog(dispatcherId, $"After fetch ({timer.ElapsedMilliseconds} ms) ({this.concurrentWorkItemCount}/{this.MaxConcurrentWorkItems} max)")); } catch (TimeoutException) { delaySecs = 0; } catch (TaskCanceledException exception) { TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherDispatch-TaskCanceledException", this.GetFormattedLog(dispatcherId, $"TaskCanceledException while fetching workItem, should be harmless: {exception.Message}")); delaySecs = this.GetDelayInSecondsAfterOnFetchException(exception); } catch (Exception exception) { if (!this.isStarted) { TraceHelper.Trace( TraceEventType.Information, "WorkItemDispatcherDispatch-HarmlessException", this.GetFormattedLog(dispatcherId, $"Harmless exception while fetching workItem after Stop(): {exception.Message}")); } else { this.LogHelper.FetchWorkItemFailure(context, exception); // TODO : dump full node context here TraceHelper.TraceException( TraceEventType.Warning, "WorkItemDispatcherDispatch-Exception", exception, this.GetFormattedLog(dispatcherId, $"Exception while fetching workItem: {exception.Message}")); delaySecs = this.GetDelayInSecondsAfterOnFetchException(exception); } } finally { Interlocked.Decrement(ref this.activeFetchers); } var scheduledWorkItem = false; if (!IsNull(workItem)) { if (!this.isStarted) { if (this.SafeReleaseWorkItem != null) { await this.SafeReleaseWorkItem(workItem); } } else { Interlocked.Increment(ref this.concurrentWorkItemCount); // We just want this to Run we intentionally don't wait #pragma warning disable 4014 Task.Run(() => this.ProcessWorkItemAsync(context, workItem)); #pragma warning restore 4014 scheduledWorkItem = true; } } delaySecs = Math.Max(this.delayOverrideSecs, delaySecs); if (delaySecs > 0) { await Task.Delay(TimeSpan.FromSeconds(delaySecs)); } if (!scheduledWorkItem) { this.concurrencyLock.Release(); } } this.LogHelper.DispatcherStopped(context); }