void DispatchCommit(ICommit commit, string slotName, LongCheckpoint startCheckpoint) { if (Logger.IsDebugEnabled) { Logger.ThreadProperties["commit"] = commit.CommitId; } if (Logger.IsDebugEnabled) { Logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", commit.CheckpointToken, _config.TenantId); } TenantContext.Enter(_config.TenantId); var chkpoint = LongCheckpoint.Parse(commit.CheckpointToken); if (chkpoint.LongValue <= startCheckpoint.LongValue) { // già fatta return; } var projections = _projectionsBySlot[slotName]; bool dispatchCommit = false; var eventMessages = commit.Events.ToArray(); var projectionToUpdate = new List <string>(); for (int index = 0; index < eventMessages.Length; index++) { var eventMessage = eventMessages[index]; try { var evt = (DomainEvent)eventMessage.Body; if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evType"] = evt.GetType().Name; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evMsId"] = evt.MessageId; } string eventName = evt.GetType().Name; foreach (var projection in projections) { var cname = projection.GetCommonName(); if (Logger.IsDebugEnabled) { Logger.ThreadProperties["prj"] = cname; } var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, commit.CheckpointToken); bool handled; long ticks = 0; try { var sw = new Stopwatch(); sw.Start(); //if (Logger.IsDebugEnabled)Logger.DebugFormat("Handling {0} with {1}", commit.CheckpointToken, projection.GetType().Name); handled = projection.Handle(evt, checkpointStatus.IsRebuilding); //if (Logger.IsDebugEnabled)Logger.DebugFormat("Handled {0} with {1}", commit.CheckpointToken, projection.GetType().Name); sw.Stop(); ticks = sw.ElapsedTicks; } catch (Exception ex) { Logger.FatalFormat(ex, "[{3}] Failed checkpoint {0}: {1} > {2}", commit.CheckpointToken, commit.StreamId, eventName, slotName ); throw; } if (handled) { _metrics.Inc(cname, eventName, ticks); Logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}", commit.CheckpointToken, commit.StreamId, eventName, slotName, cname ); } if (!checkpointStatus.IsRebuilding) { if (handled) { dispatchCommit = true; } projectionToUpdate.Add(cname); } else { if (checkpointStatus.IsLast && (index == eventMessages.Length - 1)) { projection.StopRebuild(); var meter = _metrics.GetMeter(cname); _checkpointTracker.RebuildEnded(projection, meter); Logger.InfoFormat("Rebuild done {0} @ {1}", projection.GetType().FullName, commit.CheckpointToken ); } } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["prj"] = null; } } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evType"] = null; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evMsId"] = null; } } catch (Exception ex) { if (Logger.IsDebugEnabled) { Logger.ErrorFormat(ex, "{0} -> {1}", eventMessage.Body, ex.Message); } throw; } } _checkpointTracker.UpdateSlot(slotName, commit.CheckpointToken); MetricsHelper.MarkCommitDispatchedCount(slotName, 1); foreach (var cname in projectionToUpdate) { _checkpointTracker.SetCheckpoint(cname, commit.CheckpointToken); } if (dispatchCommit) { _notifyCommitHandled.SetDispatched(commit); } // ok in multithread wihout locks! if (_maxDispatchedCheckpoint < chkpoint.LongValue) { if (Logger.IsDebugEnabled) { Logger.DebugFormat("Updating last dispatched checkpoint from {0} to {1}", _maxDispatchedCheckpoint, chkpoint.LongValue ); } _maxDispatchedCheckpoint = chkpoint.LongValue; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["commit"] = null; } }
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); }
void DispatchCommit(ICommit commit, string slotName, Int64 startCheckpoint) { Interlocked.Increment(ref _countOfConcurrentDispatchingCommit); if (Logger.IsDebugEnabled) { Logger.ThreadProperties["commit"] = commit.CommitId; } if (Logger.IsDebugEnabled) { Logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", commit.CheckpointToken, _config.TenantId); } TenantContext.Enter(_config.TenantId); var chkpoint = commit.CheckpointToken; 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 ApplicationException(error); } if (lastCheckpointDispatched[slotName] + 1 != chkpoint) { if (lastCheckpointDispatched[slotName] > 0) { Logger.DebugFormat("Sequence of commit non consecutive, 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]; bool dispatchCommit = false; var eventCount = commit.Events.Count; var projectionToUpdate = new List <string>(); for (int index = 0; index < eventCount; index++) { var eventMessage = commit.Events.ElementAt(index); try { var evt = (DomainEvent)eventMessage.Body; if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evType"] = evt.GetType().Name; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evMsId"] = evt.MessageId; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["evCheckpointToken"] = commit.CheckpointToken; } string eventName = evt.GetType().Name; foreach (var projection in projections) { var cname = projection.GetCommonName(); if (Logger.IsDebugEnabled) { Logger.ThreadProperties["prj"] = cname; } var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, commit.CheckpointToken); bool handled; long ticks = 0; try { //pay attention, stopwatch consumes time. var sw = new Stopwatch(); sw.Start(); handled = projection.Handle(evt, checkpointStatus.IsRebuilding); sw.Stop(); ticks = sw.ElapsedTicks; MetricsHelper.IncrementProjectionCounter(cname, slotName, eventName, ticks); } catch (Exception ex) { var error = String.Format("[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}", commit.CheckpointToken, commit.StreamId, eventName, slotName, cname); Logger.Fatal(error, ex); _engineFatalErrors.Add(error); throw; } if (handled) { _metrics.Inc(cname, eventName, ticks); if (Logger.IsDebugEnabled) { Logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}", commit.CheckpointToken, commit.StreamId, eventName, slotName, cname ); } } if (!checkpointStatus.IsRebuilding) { if (handled) { dispatchCommit = true; } projectionToUpdate.Add(cname); } else { if (checkpointStatus.IsLast && (index == eventCount - 1)) { projection.StopRebuild(); var meter = _metrics.GetMeter(cname); _checkpointTracker.RebuildEnded(projection, meter); Logger.InfoFormat("Rebuild done {0} @ {1}", projection.GetType().FullName, commit.CheckpointToken ); } } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["prj"] = null; } } ClearLoggerThreadPropertiesForEventDispatchLoop(); } catch (Exception ex) { Logger.ErrorFormat(ex, "Error dispathing commit id: {0}\nMessage: {1}\nError: {2}", commit.CheckpointToken, eventMessage.Body, ex.Message); ClearLoggerThreadPropertiesForEventDispatchLoop(); throw; } } if (projectionToUpdate.Count == 0) { //I'm in rebuilding or no projection had run any events, only update slot _checkpointTracker.UpdateSlot(slotName, commit.CheckpointToken); } else { //I'm not on rebuilding, we have projection to update, update everything with one call. _checkpointTracker.UpdateSlotAndSetCheckpoint(slotName, projectionToUpdate, commit.CheckpointToken); } MetricsHelper.MarkCommitDispatchedCount(slotName, 1); if (dispatchCommit) { _notifyCommitHandled.SetDispatched(commit); } // 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; } if (Logger.IsDebugEnabled) { Logger.ThreadProperties["commit"] = null; } Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit); }