Skip to content

Commit

Permalink
Improved log messages and added renew time checks
Browse files Browse the repository at this point in the history
  • Loading branch information
niemyjski committed Mar 27, 2024
1 parent ee69b38 commit c4a1910
Show file tree
Hide file tree
Showing 3 changed files with 18 additions and 10 deletions.
3 changes: 2 additions & 1 deletion src/Foundatio/Caching/InMemoryCacheClient.cs
Original file line number Diff line number Diff line change
Expand Up @@ -622,13 +622,14 @@ private async Task<bool> SetInternalAsync(string key, CacheEntry entry, bool add
{
_memory.AddOrUpdate(key, entry, (existingKey, existingEntry) =>
{
// NOTE: This update factory method will run multiple times if the key is already in the cache, especially during lock contention.
wasUpdated = false;
// check to see if existing entry is expired
if (existingEntry.ExpiresAt < SystemClock.UtcNow)
{
if (isTraceLogLevelEnabled)
_logger.LogTrace("Replacing expired cache key: {Key}", existingKey);
_logger.LogTrace("Attempting to replacing expired cache key: {Key}", existingKey);
wasUpdated = true;
return entry;
Expand Down
23 changes: 15 additions & 8 deletions src/Foundatio/Lock/ILockProvider.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
using System;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
Expand Down Expand Up @@ -144,15 +144,16 @@ public static async Task<ILock> AcquireAsync(this ILockProvider provider, IEnume
return new EmptyLock();

var logger = provider.GetLogger();
bool isTraceLogLevelEnabled = logger.IsEnabled(LogLevel.Trace);
if (isTraceLogLevelEnabled)
logger.LogTrace("Acquiring {LockCount} locks {Resource}", resourceList.Length, resourceList);

// If renew time is greater than 0, then cut the time in half with max time of 1 minute.
var renewTime = timeUntilExpires.GetValueOrDefault(TimeSpan.FromMinutes(1));
if (renewTime > TimeSpan.Zero)
renewTime = TimeSpan.FromTicks(renewTime.Ticks / 2) > TimeSpan.FromMinutes(1) ? TimeSpan.FromMinutes(1) : TimeSpan.FromTicks(renewTime.Ticks / 2);

bool isTraceLogLevelEnabled = logger.IsEnabled(LogLevel.Trace);
if (isTraceLogLevelEnabled)
logger.LogTrace("Acquiring {LockCount} locks {Resource} RenewTime={RenewTime:g}", resourceList.Length, resourceList, renewTime);

var sw = Stopwatch.StartNew();

var acquiredLocks = new List<(ILock Lock, DateTime LastRenewed)>(resourceList.Length);
Expand All @@ -165,12 +166,18 @@ public static async Task<ILock> AcquireAsync(this ILockProvider provider, IEnume
}

// Renew any acquired locks so they stay alive until we have all locks
if (acquiredLocks.Count > 0)
if (acquiredLocks.Count > 0 && renewTime > TimeSpan.Zero)
{
var utcNow = SystemClock.UtcNow;
var locksToRenew = acquiredLocks.Where(al => al.LastRenewed < utcNow.Subtract(renewTime)).ToList();
await Task.WhenAll(locksToRenew.Select(al => al.Lock.RenewAsync(timeUntilExpires))).AnyContext();
locksToRenew.ForEach(al => al.LastRenewed = utcNow);
var locksToRenew = acquiredLocks.Where(al => al.LastRenewed < utcNow.Subtract(renewTime)).ToArray();
if (locksToRenew.Length > 0)
{
await Task.WhenAll(locksToRenew.Select(al => al.Lock.RenewAsync(timeUntilExpires))).AnyContext();
locksToRenew.ForEach(al => al.LastRenewed = utcNow);

if (isTraceLogLevelEnabled)
logger.LogTrace("Renewed {LockCount} locks {Resource} RenewTime={RenewTime:g}", locksToRenew.Length, locksToRenew.Select(al => al.Lock.Resource), renewTime);
}
}

acquiredLocks.Add((l, SystemClock.UtcNow));
Expand Down
2 changes: 1 addition & 1 deletion tests/Foundatio.Tests/Locks/InMemoryLockTests.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
using System;
using System;
using System.Threading.Tasks;
using Foundatio.Caching;
using Foundatio.Lock;
Expand Down

0 comments on commit c4a1910

Please sign in to comment.