diff --git a/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs b/src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs index f31a64ec..80a474ab 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 { @@ -223,10 +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.WriteWarningWithId( + TraceType, + this.traceId, + "Failed to acquire lock for actor: {0}, actor method: {1}, exception - {2}", + actorId, + actorMethodContext.MethodName, + ex.ToString()); throw; } @@ -239,6 +253,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( @@ -436,6 +457,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 +1261,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) { @@ -1284,6 +1317,11 @@ private async Task LoadRemindersAsync(CancellationToken cancellationToken) ex.ToString()); } } + + ActorTrace.Source.WriteInfoWithId( + TraceType, + this.traceId, + $"Load reminders complete."); } private Task RegisterOrUpdateReminderAsync( @@ -1306,7 +1344,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..0bc1bdc5 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,28 @@ internal ActorReminderState(ActorReminderData reminder, TimeSpan currentLogicalT if (reminderCompletedData != null) { this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminderCompletedData.LogicalTime, reminder.Period); + ActorTrace.Source.WriteInfo( + TraceType, + "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); } else { this.nextDueTime = ComputeRemainingTime(currentLogicalTime, reminder.LogicalCreationTime, reminder.DueTime); + ActorTrace.Source.WriteInfo( + TraceType, + "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); } } 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);