diff --git a/src/Foundatio/Caching/InMemoryCacheClient.cs b/src/Foundatio/Caching/InMemoryCacheClient.cs index 2d2b0fa2..d6c00336 100644 --- a/src/Foundatio/Caching/InMemoryCacheClient.cs +++ b/src/Foundatio/Caching/InMemoryCacheClient.cs @@ -622,13 +622,14 @@ private async Task 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; diff --git a/src/Foundatio/Lock/ILockProvider.cs b/src/Foundatio/Lock/ILockProvider.cs index bacfd1f6..ff2928a3 100644 --- a/src/Foundatio/Lock/ILockProvider.cs +++ b/src/Foundatio/Lock/ILockProvider.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -144,15 +144,16 @@ public static async Task 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); @@ -165,12 +166,18 @@ public static async Task 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)); diff --git a/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs b/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs index db3cd774..f5535f44 100644 --- a/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs +++ b/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Threading.Tasks; using Foundatio.Caching; using Foundatio.Lock;