internal async Task DispatchEventAsync(UnwindedDomainEvent unwindedEvent) { if (unwindedEvent == UnwindedDomainEvent.LastEvent) { Finished = true; _lastCheckpointRebuilded = LastCheckpointDispatched; //Set to zero metrics, we dispatched everything. return; } var chkpoint = unwindedEvent.CheckpointToken; if (chkpoint > LastCheckpointDispatched) { if (_logger.IsDebugEnabled) { _logger.DebugFormat("Discharded event {0} commit {1} because last checkpoint dispatched for slot {2} is {3}.", unwindedEvent.CommitId, unwindedEvent.CheckpointToken, SlotName, _maxCheckpointDispatched); } return; } Interlocked.Increment(ref RebuildProjectionMetrics.CountOfConcurrentDispatchingCommit); TenantContext.Enter(_config.TenantId); try { string eventName = unwindedEvent.EventType; foreach (var projection in _projections) { var cname = projection.Info.CommonName; long elapsedticks; try { QueryPerformanceCounter(out long ticks1); await projection.HandleAsync(unwindedEvent.GetEvent(), true).ConfigureAwait(false); QueryPerformanceCounter(out long ticks2); elapsedticks = ticks2 - ticks1; KernelMetricsHelper.IncrementProjectionCounterRebuild(cname, SlotName, eventName, elapsedticks); } catch (Exception ex) { _logger.FatalFormat(ex, "[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}", unwindedEvent.CheckpointToken, unwindedEvent.PartitionId, eventName, SlotName, cname ); HealthChecks.RegisterHealthCheck($"RebuildDispatcher, slot {SlotName} - FailedCheckpoint {unwindedEvent.CheckpointToken}", () => HealthCheckResult.Unhealthy(ex) ); throw; } _metrics.Inc(cname, eventName, elapsedticks); if (_logger.IsDebugEnabled) { _logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}", unwindedEvent.CheckpointToken, unwindedEvent.PartitionId, eventName, SlotName, cname ); } } } catch (Exception ex) { _logger.ErrorFormat(ex, "Error dispathing commit id: {0}\nMessage: {1}\nError: {2}", unwindedEvent.CheckpointToken, unwindedEvent.Event, ex.Message); HealthChecks.RegisterHealthCheck($"RebuildDispatcher, slot {SlotName} - GeneralError", () => HealthCheckResult.Unhealthy(ex) ); throw; } _lastCheckpointRebuilded = chkpoint; KernelMetricsHelper.MarkEventInRebuildDispatchedCount(SlotName, 1); Interlocked.Decrement(ref RebuildProjectionMetrics.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); }
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; } }
internal void DispatchEvent(DomainEvent evt) { var chkpoint = evt.CheckpointToken; if (chkpoint > LastCheckpointDispatched) { if (_logger.IsDebugEnabled) { _logger.DebugFormat("Discharded event {0} commit {1} because last checkpoint dispatched for slot {2} is {3}.", evt.CommitId, evt.CheckpointToken, SlotName, _maxCheckpointDispatched); } return; } Interlocked.Increment(ref RebuildProjectionMetrics.CountOfConcurrentDispatchingCommit); //Console.WriteLine("[{0:00}] - Slot {1}", Thread.CurrentThread.ManagedThreadId, slotName); if (_logger.IsDebugEnabled) { _logger.ThreadProperties["commit"] = evt.CommitId; _logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", evt.CheckpointToken, _config.TenantId); } TenantContext.Enter(_config.TenantId); try { if (_logger.IsDebugEnabled) { _logger.ThreadProperties["evType"] = evt.GetType().Name; _logger.ThreadProperties["evMsId"] = evt.MessageId; _logger.ThreadProperties["evCheckpointToken"] = evt.CheckpointToken; } string eventName = evt.GetType().Name; foreach (var projection in _projections) { var cname = projection.GetCommonName(); if (_logger.IsDebugEnabled) { _logger.ThreadProperties["prj"] = cname; } bool handled; long ticks = 0; try { //pay attention, stopwatch consumes time. var sw = new Stopwatch(); sw.Start(); handled = projection.Handle(evt, true); sw.Stop(); ticks = sw.ElapsedTicks; MetricsHelper.IncrementProjectionCounterRebuild(cname, SlotName, eventName, ticks); } catch (Exception ex) { _logger.FatalFormat(ex, "[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}", evt.CheckpointToken, evt.AggregateId, eventName, SlotName, cname ); throw; } _metrics.Inc(cname, eventName, ticks); if (_logger.IsDebugEnabled) { _logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}", evt.CheckpointToken, evt.AggregateId, eventName, SlotName, cname ); } if (_logger.IsDebugEnabled) { _logger.ThreadProperties["prj"] = null; } } ClearLoggerThreadPropertiesForEventDispatchLoop(); } catch (Exception ex) { _logger.ErrorFormat(ex, "Error dispathing commit id: {0}\nMessage: {1}\nError: {2}", evt.CheckpointToken, evt, ex.Message); ClearLoggerThreadPropertiesForEventDispatchLoop(); throw; } _lastCheckpointRebuilded = chkpoint; if (_logger.IsDebugEnabled) { _logger.ThreadProperties["commit"] = null; } Interlocked.Decrement(ref RebuildProjectionMetrics.CountOfConcurrentDispatchingCommit); }