Add Compaction logging (#510)

* Add logging for compaction test

* Fix AddAndReplaceEntries_AreThreadSafe

Author: JunTaoLuo

src/Caching/Memory/src/MemoryCache.cs

@@ -8,6 +8,8 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Internal;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.Extensions.Caching.Memory
@@ -21,6 +23,7 @@ public class MemoryCache : IMemoryCache
         private readonly ConcurrentDictionary<object, CacheEntry> _entries;
         private long _cacheSize = 0;
         private bool _disposed;
+        private ILogger _logger;
 
         // We store the delegates locally to prevent allocations
         // every time a new CacheEntry is created.
@@ -35,13 +38,27 @@ public class MemoryCache : IMemoryCache
         /// </summary>
         /// <param name="optionsAccessor">The options of the cache.</param>
         public MemoryCache(IOptions<MemoryCacheOptions> optionsAccessor)
+            : this(optionsAccessor, NullLoggerFactory.Instance) { }
+
+        /// <summary>
+        /// Creates a new <see cref="MemoryCache"/> instance.
+        /// </summary>
+        /// <param name="optionsAccessor">The options of the cache.</param>
+        /// <param name="loggerFactory"></param>
+        public MemoryCache(IOptions<MemoryCacheOptions> optionsAccessor, ILoggerFactory loggerFactory)
         {
             if (optionsAccessor == null)
             {
                 throw new ArgumentNullException(nameof(optionsAccessor));
             }
 
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
             _options = optionsAccessor.Value;
+            _logger = loggerFactory.CreateLogger<MemoryCache>();
 
             _entries = new ConcurrentDictionary<object, CacheEntry>();
             _setEntry = SetEntry;
@@ -341,18 +358,25 @@ private bool UpdateCacheSizeExceedsCapacity(CacheEntry entry)
 
         private void TriggerOvercapacityCompaction()
         {
+            _logger.LogDebug("Overcapacity compaction triggered");
+
             // Spawn background thread for compaction
             ThreadPool.QueueUserWorkItem(s => OvercapacityCompaction((MemoryCache)s), this);
         }
 
         private static void OvercapacityCompaction(MemoryCache cache)
         {
             var currentSize = Interlocked.Read(ref cache._cacheSize);
+
+            cache._logger.LogDebug($"Overcapacity compaction executing. Current size {currentSize}");
+
             var lowWatermark = cache._options.SizeLimit * (1 - cache._options.CompactionPercentage);
             if (currentSize > lowWatermark)
             {
                 cache.Compact(currentSize - (long)lowWatermark, entry => entry.Size.Value);
             }
+
+            cache._logger.LogDebug($"Overcapacity compaction executed. New size {Interlocked.Read(ref cache._cacheSize)}");
         }
 
         /// Remove at least the given percentage (0.10 for 10%) of the total entries (or estimated memory?), according to the following policy:
@@ -481,4 +505,4 @@ private static void ValidateCacheKey(object key)
             }
         }
     }
-}
+}

src/Caching/Memory/src/MemoryDistributedCache.cs

@@ -5,6 +5,8 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Caching.Memory;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.Extensions.Caching.Distributed
@@ -16,13 +18,21 @@ public class MemoryDistributedCache : IDistributedCache
         private readonly IMemoryCache _memCache;
 
         public MemoryDistributedCache(IOptions<MemoryDistributedCacheOptions> optionsAccessor)
+            : this(optionsAccessor, NullLoggerFactory.Instance) { }
+
+        public MemoryDistributedCache(IOptions<MemoryDistributedCacheOptions> optionsAccessor, ILoggerFactory loggerFactory)
         {
             if (optionsAccessor == null)
             {
                 throw new ArgumentNullException(nameof(optionsAccessor));
             }
 
-            _memCache = new MemoryCache(optionsAccessor.Value);
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
+            _memCache = new MemoryCache(optionsAccessor.Value, loggerFactory);
         }
 
         public byte[] Get(string key)
@@ -134,4 +144,4 @@ public void Remove(string key)
             return CompletedTask;
         }
     }
-}
+}

src/Caching/Memory/src/Microsoft.Extensions.Caching.Memory.csproj

@@ -11,6 +11,7 @@
   <ItemGroup>
     <Reference Include="Microsoft.Extensions.Caching.Abstractions" />
     <Reference Include="Microsoft.Extensions.DependencyInjection.Abstractions" />
+    <Reference Include="Microsoft.Extensions.Logging.Abstractions" />
     <Reference Include="Microsoft.Extensions.Options" />
   </ItemGroup>
 

src/Caching/Memory/test/CapacityTests.cs

@@ -1,16 +1,17 @@
-// Copyright (c) .NET Foundation. All rights reserved.
+// Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Caching.Memory.Infrastructure;
 using Microsoft.Extensions.Internal;
+using Microsoft.Extensions.Logging.Testing;
 using Xunit;
 
 namespace Microsoft.Extensions.Caching.Memory
 {
-    public class CapacityTests
+    public class CapacityTests : LoggedTestBase
     {
         [Fact]
         public void MemoryDistributedCacheOptionsDefaultsTo200MBSizeLimit()
@@ -115,7 +116,7 @@ public async Task DoNotAddIfSizeOverflows()
             var cache = new MemoryCache(new MemoryCacheOptions
             {
                 SizeLimit = long.MaxValue
-            });
+            }, LoggerFactory);
 
             var entryOptions = new MemoryCacheEntryOptions { Size = long.MaxValue };
             var sem = new SemaphoreSlim(0, 1);
@@ -408,4 +409,4 @@ public void NoCompactionWhenNoMaximumEntriesCountSpecified()
             Assert.Equal(6, cache.Count);
         }
     }
-}
+}

src/Caching/Memory/test/MemoryCacheSetAndRemoveTests.cs

@@ -553,7 +553,7 @@ public void AddAndReplaceEntries_AreThreadSafe()
                     var entrySize = random.Next(0, 5);
                     cache.Set(random.Next(0, 10), entrySize, new MemoryCacheEntryOptions { Size = entrySize });
                 }
-            }, cts.Token);
+            });
 
             var task1 = Task.Run(() =>
             {
@@ -562,7 +562,7 @@ public void AddAndReplaceEntries_AreThreadSafe()
                     var entrySize = random.Next(0, 5);
                     cache.Set(random.Next(0, 10), entrySize, new MemoryCacheEntryOptions { Size = entrySize });
                 }
-            }, cts.Token);
+            });
 
             var task2 = Task.Run(() =>
             {
@@ -571,7 +571,7 @@ public void AddAndReplaceEntries_AreThreadSafe()
                     var entrySize = random.Next(0, 5);
                     cache.Set(random.Next(0, 10), entrySize, new MemoryCacheEntryOptions { Size = entrySize });
                 }
-            }, cts.Token);
+            });
 
             cts.CancelAfter(TimeSpan.FromSeconds(5));
             var task3 = Task.Delay(TimeSpan.FromSeconds(7));
@@ -643,4 +643,4 @@ private class TestKey
             public override int GetHashCode() => 0;
         }
     }
-}
+}

src/Caching/Memory/test/Microsoft.Extensions.Caching.Memory.Tests.csproj

@@ -1,12 +1,15 @@
 <Project Sdk="Microsoft.NET.Sdk">
 
+  <Import Project="$(MSBuildThisFileDirectory)..\..\..\Logging\Logging.Testing\src\build\Microsoft.Extensions.Logging.Testing.props" />
+
   <PropertyGroup>
     <TargetFrameworks>$(StandardTestTfms)</TargetFrameworks>
   </PropertyGroup>
 
   <ItemGroup>
     <Reference Include="Microsoft.Extensions.Caching.Memory" />
     <Reference Include="Microsoft.Extensions.DependencyInjection" />
+    <Reference Include="Microsoft.Extensions.Logging.Testing" />
   </ItemGroup>
 
 </Project>