private async Task StartPoll( BufferBlock <UnwindedDomainEvent> buffer, ActionBlock <UnwindedDomainEvent> broadcaster, String bucketInfo, List <RebuildProjectionSlotDispatcher> dispatchers, List <String> allEventTypesHandledByAllSlots, List <SlotGuaranteedDeliveryBroadcastBlock.SlotInfo <UnwindedDomainEvent> > consumers) { if (buffer == null) { throw new ArgumentNullException(nameof(buffer)); } if (broadcaster == null) { throw new ArgumentNullException(nameof(broadcaster)); } if (dispatchers == null) { throw new ArgumentNullException(nameof(dispatchers)); } if (consumers == null) { throw new ArgumentNullException(nameof(consumers)); } if (allEventTypesHandledByAllSlots == null) { throw new ArgumentNullException(nameof(allEventTypesHandledByAllSlots)); } Stopwatch sw = Stopwatch.StartNew(); var eventCollection = _eventUnwinder.UnwindedCollection; Int64 lastCheckpointTokenDispatched = 0; Int32 lastSequenceDispatched = 0; Int64 maxEventDispatched = dispatchers.Max(d => d.LastCheckpointDispatched); Int64 totalEventToDispatch = eventCollection.Count(Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched)); Int64 dispatchedEvents = 0; //this is the main cycle that continue to poll events and send to the tpl buffer Boolean done = false; while (!done) { try { IFindFluent <UnwindedDomainEvent, UnwindedDomainEvent> filter = eventCollection .Find( //Greater than last dispatched, less than maximum dispatched and one of the events that are elaborated by at least one of the projection Builders <UnwindedDomainEvent> .Filter.And( Builders <UnwindedDomainEvent> .Filter.Or( //this is the condition on last dispatched Builders <UnwindedDomainEvent> .Filter.Gt(e => e.CheckpointToken, lastCheckpointTokenDispatched), //or checkpoint token is greater than last dispatched. Builders <UnwindedDomainEvent> .Filter.And( //or is equal to the last dispatched, but the EventSequence is greater. Builders <UnwindedDomainEvent> .Filter.Gt(e => e.EventSequence, lastSequenceDispatched), Builders <UnwindedDomainEvent> .Filter.Eq(e => e.CheckpointToken, lastCheckpointTokenDispatched) ) ), Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched) //less than or equal max event dispatched. , Builders <UnwindedDomainEvent> .Filter.In(e => e.EventType, allEventTypesHandledByAllSlots) ) ); Logger.InfoFormat($"polled rebuild query {filter}"); var query = filter .Sort(Builders <UnwindedDomainEvent> .Sort.Ascending(e => e.CheckpointToken).Ascending(e => e.EventSequence)); await query.ForEachAsync(Dispatch).ConfigureAwait(false); async Task Dispatch(UnwindedDomainEvent eventUnwinded) { _pollError = null; if (Logger.IsDebugEnabled) { Logger.DebugFormat("TPL queued event {0}/{1} for bucket {2}", eventUnwinded.CheckpointToken, eventUnwinded.EventSequence, bucketInfo); } //rehydrate the event before dispatching eventUnwinded.EnhanceEvent(); await buffer.SendAsync(eventUnwinded).ConfigureAwait(false); dispatchedEvents++; lastSequenceDispatched = eventUnwinded.EventSequence; lastCheckpointTokenDispatched = eventUnwinded.CheckpointToken; } //Send marker unwindws domain event to signal that rebuild is finished await buffer.SendAsync(UnwindedDomainEvent.LastEvent).ConfigureAwait(false); done = true; } catch (MongoException ex) { _pollError = $"Unable to poll event from UnwindedCollection: {ex.Message} - Last good checkpoint dispatched { lastCheckpointTokenDispatched }"; Logger.WarnFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched); } catch (Exception ex) { _pollError = $"Unable to poll event from UnwindedCollection: {ex.Message} - Last good checkpoint dispatched { lastCheckpointTokenDispatched }"; Logger.FatalFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched); throw; } } try { Logger.InfoFormat("Finished loading events for bucket {0} wait for tpl to finish flush", bucketInfo); buffer.Complete(); broadcaster.Completion.Wait(); //wait for all event to be broadcasted. Task.WaitAll(consumers.Select(c => c.Target.Completion).ToArray()); //wait for all consumers to complete. Thread.Sleep(1000); //wait for another secondo before finishing. //create a list of dispatcher to wait for finish, then start waiting. List <RebuildProjectionSlotDispatcher> dispatcherWaitingToFinish = dispatchers.ToList(); while (dispatcherWaitingToFinish.Count > 0) { if (Logger.IsDebugEnabled) { Logger.DebugFormat("Waiting for {0} slot to finish events", dispatcherWaitingToFinish.Count); } Int32 i = dispatcherWaitingToFinish.Count - 1; while (i >= 0) { var dispatcher = dispatcherWaitingToFinish[i]; if (dispatcher.Finished) { foreach (var projection in dispatcher.Projections) { try { await projection.StopRebuildAsync().ConfigureAwait(false); } catch (Exception ex) { Logger.ErrorFormat(ex, "Error in StopRebuild for projection {0}", projection.Info.CommonName); throw; } var meter = _metrics.GetMeter(projection.Info.CommonName); _checkpointTracker.RebuildEnded(projection, meter); Logger.InfoFormat("Rebuild done for projection {0} @ {1}", projection.GetType().FullName, dispatcher.LastCheckpointDispatched ); } await _checkpointTracker.UpdateSlotAndSetCheckpointAsync( dispatcher.SlotName, dispatcher.Projections.Select(p => p.Info.CommonName), dispatcher.LastCheckpointDispatched).ConfigureAwait(false); dispatcherWaitingToFinish.Remove(dispatcher); Logger.InfoFormat("Rebuild ended for slot {0}", dispatcher.SlotName); } i--; } if (dispatcherWaitingToFinish.Count > 0) { Thread.Sleep(2000); } } sw.Stop(); Logger.InfoFormat("Bucket {0} finished dispathing all events for slots: {1}", bucketInfo, dispatchers.Select(d => d.SlotName).Aggregate((s1, s2) => s1 + ", " + s2)); _status.BucketDone(bucketInfo, dispatchedEvents, sw.ElapsedMilliseconds, totalEventToDispatch); } catch (Exception ex) { Logger.FatalFormat(ex, "Error during rebuild finish {0}", ex.Message); throw; } }
private async Task DispatchCommitAsync(IChunk chunk, string slotName, Int64 startCheckpoint) { Interlocked.Increment(ref _countOfConcurrentDispatchingCommit); _loggerThreadContextManager.SetContextProperty("commit", $"{chunk.OperationId}/{chunk.Position}"); if (_logger.IsDebugEnabled) { _logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", chunk.Position, _config.TenantId); } TenantContext.Enter(_config.TenantId); var chkpoint = chunk.Position; if (!lastCheckpointDispatched.ContainsKey(slotName)) { lastCheckpointDispatched[slotName] = 0; } if (lastCheckpointDispatched[slotName] >= chkpoint) { var error = String.Format("Sequence broken, last checkpoint for slot {0} was {1} and now we dispatched {2}", slotName, lastCheckpointDispatched[slotName], chkpoint); _logger.Error(error); throw new JarvisFrameworkEngineException(error); } if (lastCheckpointDispatched[slotName] + 1 != chkpoint && lastCheckpointDispatched[slotName] > 0) { _logger.DebugFormat("Sequence of commit not consecutive (probably holes), last dispatched {0} receiving {1}", lastCheckpointDispatched[slotName], chkpoint); } lastCheckpointDispatched[slotName] = chkpoint; if (chkpoint <= startCheckpoint) { //Already dispatched, skip it. Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit); return; } var projections = _projectionsBySlot[slotName]; object[] events = GetArrayOfObjectFromChunk(chunk); var eventCount = events.Length; //now it is time to dispatch the commit, we will dispatch each projection //and for each projection we dispatch all the events present in changeset bool someProjectionProcessedTheEvent = false; foreach (var projection in projections) { var cname = projection.Info.CommonName; Object eventMessage = null; try { //Foreach projection we need to dispach every event for (int index = 0; index < eventCount; index++) { eventMessage = events[index]; var message = eventMessage as IMessage; string eventName = eventMessage.GetType().Name; _loggerThreadContextManager.SetContextProperty("evType", eventName); _loggerThreadContextManager.SetContextProperty("evMsId", message?.MessageId); _loggerThreadContextManager.SetContextProperty("evCheckpointToken", chunk.Position); _loggerThreadContextManager.SetContextProperty("prj", cname); var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, chunk.Position); long ticks = 0; try { //pay attention, stopwatch consumes time. var sw = new Stopwatch(); sw.Start(); var eventProcessed = await projection .HandleAsync(eventMessage, checkpointStatus.IsRebuilding) .ConfigureAwait(false); someProjectionProcessedTheEvent |= eventProcessed; sw.Stop(); ticks = sw.ElapsedTicks; KernelMetricsHelper.IncrementProjectionCounter(cname, slotName, eventName, ticks, sw.ElapsedMilliseconds); if (_logger.IsDebugEnabled) { _logger.DebugFormat("[Slot:{3}] [Projection {4}] Handled checkpoint {0}: {1} > {2}", chunk.Position, chunk.PartitionId, $"eventName: {eventName} [event N°{index}]", slotName, cname ); } } catch (Exception ex) { var error = String.Format("[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}", chunk.Position, chunk.PartitionId, eventName, slotName, cname); _logger.Fatal(error, ex); _engineFatalErrors.Add(String.Format("{0}\n{1}", error, ex)); throw; } } //End of event cycle } catch (Exception ex) { _loggerThreadContextManager.ClearContextProperty("commit"); _logger.ErrorFormat(ex, "Error dispathing Chunk [{0}]\n Message: {1}\n Error: {2}\n", chunk.Position, eventMessage?.GetType()?.Name, ex.Message); throw; } finally { _loggerThreadContextManager.ClearContextProperty("evType"); _loggerThreadContextManager.ClearContextProperty("evMsId"); _loggerThreadContextManager.ClearContextProperty("evCheckpointToken"); _loggerThreadContextManager.ClearContextProperty("prj"); } projection.CheckpointProjected(chunk.Position); //TODO: Evaluate if it is needed to update single projection checkpoint //Update this projection, set all events of this checkpoint as dispatched. //await _checkpointTracker.UpdateProjectionCheckpointAsync(cname, chunk.Position).ConfigureAwait(false); } //End of projection cycle. await _checkpointTracker.UpdateSlotAndSetCheckpointAsync( slotName, projections.Select(_ => _.Info.CommonName), chunk.Position, someEventDispatched : someProjectionProcessedTheEvent).ConfigureAwait(false); KernelMetricsHelper.MarkCommitDispatchedCount(slotName, 1); await _notifyCommitHandled.SetDispatched(slotName, chunk).ConfigureAwait(false); // ok in multithread wihout locks! if (_maxDispatchedCheckpoint < chkpoint) { if (_logger.IsDebugEnabled) { _logger.DebugFormat("Updating last dispatched checkpoint from {0} to {1}", _maxDispatchedCheckpoint, chkpoint ); } _maxDispatchedCheckpoint = chkpoint; } _loggerThreadContextManager.ClearContextProperty("commit"); Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit); }