From 93d72906b336ff09f3f6c9f8a9215824b0ae5b7c Mon Sep 17 00:00:00 2001 From: Yash Agarwal Date: Tue, 26 Dec 2023 14:11:25 +0530 Subject: [PATCH 1/4] Actor reminders related tracing imporvements --- .../Runtime/ActorManager.cs | 16 ++++++++++++++-- .../Runtime/ActorReminder.cs | 8 ++++++++ .../Runtime/ActorReminderData.cs | 2 +- .../Runtime/ActorReminderState.cs | 19 +++++++++++++++++++ .../Runtime/KvsActorStateProviderBase.cs | 18 ++++++++++++++---- .../Runtime/NullActorStateProvider.cs | 6 ++++++ .../ReliableCollectionsActorStateProvider.cs | 12 ++++++++++++ .../Runtime/VolatileActorStateProvider.cs | 18 +++++++++++++++--- 8 files changed, 89 insertions(+), 10 deletions(-) diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs index f31a64ec..99a09431 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs @@ -436,6 +436,13 @@ public async Task FireReminderAsync(ActorReminder reminder) try { + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Firing reminder ({0}) for actor ({1})", + reminder.Name, + reminder.OwnerActorId.GetStorageKey()); + using (var actorScope = this.GetActor(reminder.OwnerActorId, true, false)) { var actorBase = actorScope.Actor; @@ -1233,12 +1240,17 @@ private async Task CleanupRemindersAsync() private async Task LoadRemindersAsync(CancellationToken cancellationToken) { + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + $"Loading reminders."); + var reminders = await this.StateProvider.LoadRemindersAsync(cancellationToken); ActorTrace.Source.WriteInfoWithId( TraceType, this.traceId, - $"Loading {reminders.Count} reminders."); + $"Found {reminders.Count} reminders."); if (reminders.Count > 0 && !this.actorService.ActorTypeInformation.IsRemindable) { @@ -1306,7 +1318,7 @@ private async Task RegisterOrUpdateReminderAsync( TraceType, this.traceId, "Registering reminder for actor: ({0}), reminderName: ({1}), remainingDueTime: ({2}), saveState {3}", - actorReminder.OwnerActorId, + actorReminder.OwnerActorId.GetStorageKey(), actorReminder.Name, remainingDueTime, saveState); diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminder.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminder.cs index 160787b7..11f9077b 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminder.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminder.cs @@ -124,6 +124,14 @@ internal void ArmTimer(TimeSpan newDueTime) { try { + this.actorManager.TraceSource.WriteInfoWithId( + TraceType, + this.actorManager.GetActorTraceId(this.OwnerActorId), + "Arming timer for reminder ({0}), actor: ({1}), newDueTime: ({2})", + this.Name, + this.OwnerActorId.GetStorageKey(), + newDueTime); + snap.Change(newDueTime, Timeout.InfiniteTimeSpan); } catch (Exception e) diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderData.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderData.cs index 08f8dc56..2758479b 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderData.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderData.cs @@ -65,7 +65,7 @@ public long EstimateDataLength() public override string ToString() { - return $"ActorId: {this.ActorId} Name: {this.Name} DueTime: {this.DueTime} Period: {this.Period} State: {this.State} LogicalCreationTime: {this.LogicalCreationTime}"; + return $"ActorId: ({this.ActorId.GetStorageKey()}), Name: ({this.Name}), DueTime: ({this.DueTime}), Period: ({this.Period}), State: ({this.State}), LogicalCreationTime: ({this.LogicalCreationTime})"; } } } diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs index 2fe068e8..e5a450da 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs @@ -6,6 +6,7 @@ namespace Microsoft.ServiceFabric.Actors.Runtime { using System; + using System.Diagnostics; using System.Runtime.Serialization; using System.Threading; @@ -15,6 +16,8 @@ namespace Microsoft.ServiceFabric.Actors.Runtime [DataContract(Name = "ActorReminderState")] public class ActorReminderState : IActorReminderState { + private const string TraceType = "ActorReminderState"; + [DataMember(Name = "Reminder", Order = 0, IsRequired = true)] private readonly ActorReminderData reminder; @@ -34,10 +37,26 @@ internal ActorReminderState(ActorReminderData reminder, TimeSpan currentLogicalT if (reminderCompletedData != null) { this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminderCompletedData.LogicalTime, reminder.Period); + ActorTrace.Source.WriteInfo( + TraceType, + "Next Due Time for Reminder: ({0}), Actor: ({1}), Reminder Completed Time: ({2}), Period: ({3}) is ({4})", + reminder.Name, + reminder.ActorId.GetStorageKey(), + reminderCompletedData.LogicalTime, + reminder.Period, + this.nextDueTime); } else { this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminder.LogicalCreationTime, reminder.DueTime); + ActorTrace.Source.WriteInfo( + TraceType, + "Next Due Time for Reminder: ({0}), Actor: ({1}), Reminder Creation Time: ({2}), Due Time: ({3}) is ({4})", + reminder.Name, + reminder.ActorId.GetStorageKey(), + reminder.LogicalCreationTime, + reminder.DueTime, + this.nextDueTime); } } diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/KvsActorStateProviderBase.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/KvsActorStateProviderBase.cs index 0fed223a..2f4eec77 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/KvsActorStateProviderBase.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/KvsActorStateProviderBase.cs @@ -564,8 +564,14 @@ async Task IActorStateProvider.SaveReminderAsync(ActorId actorId, IActorReminder await this.EnsureLogicalTimeManagerInitializedAsync(cancellationToken); var reminderKey = CreateReminderStorageKey(actorId, reminder.Name); - var data = new ActorReminderData(actorId, reminder, this.logicalTimeManager.CurrentLogicalTime); - var buffer = this.SerializeReminder(data); + var reminderData = new ActorReminderData(actorId, reminder, this.logicalTimeManager.CurrentLogicalTime); + var buffer = this.SerializeReminder(reminderData); + + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Saving Reminder - {0}", + reminderData); var reminderCompletedKey = ActorStateProviderHelper.CreateReminderCompletedStorageKey(actorId, reminder.Name); @@ -1140,8 +1146,6 @@ private async Task EnsureLogicalTimeManagerInitializedAsync(CancellationToken ca await Task.Delay(retryCount * StateProviderInitRetryDelayMilliseconds, cancellationToken); } - ActorTrace.Source.WriteInfoWithId(TraceType, this.traceId, "Logical Time Manager is initialized"); - if (this.replicaRole != ReplicaRole.Primary) { throw new FabricNotPrimaryException(FabricErrorCode.NotPrimary); @@ -1532,6 +1536,12 @@ private Task> GetReminderCompletedData private async Task EnumerateReminderAsync(CancellationToken cancellationToken) { + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Enumerating all reminders. Current Logical Time - {0}", + this.logicalTimeManager.CurrentLogicalTime); + var reminderCollection = new ActorReminderCollection(); using (var tx = this.storeReplica.CreateTransaction()) diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/NullActorStateProvider.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/NullActorStateProvider.cs index 7dda284e..997758ad 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/NullActorStateProvider.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/NullActorStateProvider.cs @@ -260,6 +260,12 @@ Task IActorStateProvider.SaveReminderAsync(ActorId actorId, IActorReminder state var key = CreateReminderStorageKey(actorId, state.Name); var reminderData = new ActorReminderData(actorId, state, TimeSpan.Zero); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Saving Reminder - {0}", + reminderData); + this.stateDictionary.AddOrUpdate(key, reminderData, (s, o) => reminderData); return Task.FromResult(true); diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ReliableCollectionsActorStateProvider.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ReliableCollectionsActorStateProvider.cs index a97cb4e4..c690b37e 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ReliableCollectionsActorStateProvider.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ReliableCollectionsActorStateProvider.cs @@ -445,6 +445,12 @@ async Task IActorStateProvider.SaveReminderAsync(ActorId actorId, IActorReminder var reminderData = new ActorReminderData(actorId, reminder, this.logicalTimeManager.CurrentLogicalTime); var data = ActorReminderDataSerializer.Serialize(reminderData); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Saving Reminder - {0}", + reminderData); + await this.stateProviderHelper.ExecuteWithRetriesAsync( async () => { @@ -1131,6 +1137,12 @@ private async Task EnumerateRemindersAsync( private async Task EnumerateRemindersAsync(CancellationToken cancellationToken) { + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Enumerating all reminders. Current Logical Time - {0}", + this.logicalTimeManager.CurrentLogicalTime); + var reminderCollection = new ActorReminderCollection(); var reminderCompletedDataDict = await this.GetReminderCompletedDataMapAsync(null, cancellationToken); diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/VolatileActorStateProvider.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/VolatileActorStateProvider.cs index e565425e..dcbf9cab 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/VolatileActorStateProvider.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/VolatileActorStateProvider.cs @@ -570,12 +570,20 @@ async Task IActorStateProvider.SaveReminderAsync(ActorId actorId, IActorReminder { await this.EnsureLogicalTimeManagerInitializedAsync(cancellationToken); + var reminderData = new ActorStateData(new ActorReminderData(actorId, reminder, this.logicalTimeManager.CurrentLogicalTime)); + + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Saving Reminder - {0}", + reminderData); + var actorStateDataWrapperList = new List { ActorStateDataWrapper.CreateForUpdate( ActorStateType.Reminder, CreateReminderStorageKey(actorId, reminder.Name), - new ActorStateData(new ActorReminderData(actorId, reminder, this.logicalTimeManager.CurrentLogicalTime))), + reminderData), ActorStateDataWrapper.CreateForDelete( ActorStateType.Actor, @@ -664,6 +672,12 @@ async Task IActorStateProvider.LoadRemindersAsync(Canc { await this.EnsureLogicalTimeManagerInitializedAsync(cancellationToken); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Enumerating all reminders. Current Logical Time - {0}", + this.logicalTimeManager.CurrentLogicalTime); + var reminderCollection = new ActorReminderCollection(); var stateDictionary = this.stateTable.GetActorStateDictionary(ActorStateType.Reminder); @@ -1288,8 +1302,6 @@ private async Task EnsureLogicalTimeManagerInitializedAsync(CancellationToken ca await Task.Delay(retryCount * StateProviderInitRetryDelayMilliseconds, cancellationToken); } - ActorTrace.Source.WriteInfoWithId(TraceType, this.traceId, "Logical Time Manager is initialized"); - if (this.replicaRole != ReplicaRole.Primary) { throw new FabricNotPrimaryException(FabricErrorCode.NotPrimary); From 7982b700b3c1a5db32a714964556ff4c37ca29e8 Mon Sep 17 00:00:00 2001 From: Yash Agarwal Date: Tue, 27 Feb 2024 15:18:31 +0530 Subject: [PATCH 2/4] retrigger checks From a26d892508be42ee5dcd6c15a58baaaeca8f84b4 Mon Sep 17 00:00:00 2001 From: Yash Agarwal Date: Thu, 29 Feb 2024 15:29:06 +0530 Subject: [PATCH 3/4] Address comments --- .../Runtime/ActorManager.cs | 25 +++++++++++++++++++ .../Runtime/ActorReminderState.cs | 6 +++-- 2 files changed, 29 insertions(+), 2 deletions(-) diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs index 99a09431..73f4367e 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs @@ -214,6 +214,13 @@ public async Task DispatchToActorAsync( // Emit diagnostic info - before acquiring actor lock var lockAcquireStartTime = this.DiagnosticsEventManager.AcquireActorLockStart(actor); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Acquiring lock for actor: {0}, actor method: {1}", + actorId, + actorMethodContext.MethodName); + DateTime? lockAcquireFinishTime = null; try { @@ -227,6 +234,12 @@ public async Task DispatchToActorAsync( { // Emit diagnostic info - failed to acquire actor lock this.DiagnosticsEventManager.AcquireActorLockFailed(actor); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Acquiring lock for actor: {0}, actor method: {1} failed", + actorId, + actorMethodContext.MethodName); throw; } @@ -239,6 +252,13 @@ public async Task DispatchToActorAsync( actor, lockAcquireStartTime); + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + "Acquired lock for actor: {0}, actor method: {1}", + actorId, + actorMethodContext.MethodName); + retval = await this.DispatchToActorConcurrencyLockHeldAsync( @@ -1296,6 +1316,11 @@ private async Task LoadRemindersAsync(CancellationToken cancellationToken) ex.ToString()); } } + + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + $"Load reminders complete."); } private Task RegisterOrUpdateReminderAsync( diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs index e5a450da..0bc1bdc5 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorReminderState.cs @@ -39,9 +39,10 @@ internal ActorReminderState(ActorReminderData reminder, TimeSpan currentLogicalT this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminderCompletedData.LogicalTime, reminder.Period); ActorTrace.Source.WriteInfo( TraceType, - "Next Due Time for Reminder: ({0}), Actor: ({1}), Reminder Completed Time: ({2}), Period: ({3}) is ({4})", + "ComputeRemainingTime - Reminder: ({0}), Actor: ({1}), Current Logical Time: ({2}), Reminder Completed Time: ({3}), Period ({4}), Next Due Time: ({5})", reminder.Name, reminder.ActorId.GetStorageKey(), + currentLogicalTime, reminderCompletedData.LogicalTime, reminder.Period, this.nextDueTime); @@ -51,9 +52,10 @@ internal ActorReminderState(ActorReminderData reminder, TimeSpan currentLogicalT this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminder.LogicalCreationTime, reminder.DueTime); ActorTrace.Source.WriteInfo( TraceType, - "Next Due Time for Reminder: ({0}), Actor: ({1}), Reminder Creation Time: ({2}), Due Time: ({3}) is ({4})", + "ComputeRemainingTime - Reminder: ({0}), Actor: ({1}), Current Logical Time: ({2}), Reminder Creation Time: ({3}), Due Time: ({4}), Next Due Time: ({5})", reminder.Name, reminder.ActorId.GetStorageKey(), + currentLogicalTime, reminder.LogicalCreationTime, reminder.DueTime, this.nextDueTime); From 84805ee3f08abce8e46068112fb2ec5620784687 Mon Sep 17 00:00:00 2001 From: Yash Agarwal Date: Fri, 1 Mar 2024 10:46:51 +0530 Subject: [PATCH 4/4] Catch exception when failed to acquire actor lock --- .../Runtime/ActorManager.cs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs index 73f4367e..80a474ab 100644 --- a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs +++ b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs @@ -230,16 +230,17 @@ public async Task DispatchToActorAsync( async innerActor => await this.HandleDirtyStateAsync(innerActor), cancellationToken); } - catch + catch (Exception ex) { // Emit diagnostic info - failed to acquire actor lock this.DiagnosticsEventManager.AcquireActorLockFailed(actor); - ActorTrace.Source.WriteInfoWithId( + ActorTrace.Source.WriteWarningWithId( TraceType, this.traceId, - "Acquiring lock for actor: {0}, actor method: {1} failed", + "Failed to acquire lock for actor: {0}, actor method: {1}, exception - {2}", actorId, - actorMethodContext.MethodName); + actorMethodContext.MethodName, + ex.ToString()); throw; }