Actor reminders related tracing improvements (#360)

* Actor reminders related tracing imporvements

* retrigger checks

* Address comments

* Catch exception when failed to acquire actor lock

src/Microsoft.ServiceFabric.Actors/Runtime/ActorManager.cs

@@ -214,6 +214,13 @@ public async Task<T> DispatchToActorAsync<T>(
 
  // 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<T> DispatchToActorAsync<T>(
  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<T> DispatchToActorAsync<T>(
  actor,
  lockAcquireStartTime);
 
+ ActorTrace.Source.WriteInfoWithId(
+ TraceType,
+ this.traceId,
+ "Acquired lock for actor: {0}, actor method: {1}",
+ actorId,
+ actorMethodContext.MethodName);
+
  retval =
  await
  this.DispatchToActorConcurrencyLockHeldAsync<T>(
@@ -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);

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)

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})";
  }
  }
 }

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);
  }
  }
 

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<Dictionary<string, ReminderCompletedData>> GetReminderCompletedData
 
  private async Task<IActorReminderCollection> 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())

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);

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<IActorReminderCollection> 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);
 

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>
  {
  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<IActorReminderCollection> 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);