Reduce logging frequency in ConcurrencyManager.GetStatus (Azure#2758)

Havunen · Aug 31, 2021 · 1f7f383 · 1f7f383
1 parent 11b9965
commit 1f7f383
Show file tree

Hide file tree

Showing 4 changed files with 96 additions and 1 deletion.
diff --git a/src/Microsoft.Azure.WebJobs.Host/Scale/ConcurrencyManager.cs b/src/Microsoft.Azure.WebJobs.Host/Scale/ConcurrencyManager.cs
@@ -121,7 +121,7 @@ public ConcurrencyStatus GetStatus(string functionId)
                 functionConcurrencyStatus.DecreaseConcurrency();
             }
 
-            _logger.HostConcurrencyStatus(functionId, functionConcurrencyStatus.CurrentConcurrency, functionConcurrencyStatus.OutstandingInvocations);
+            functionConcurrencyStatus.LogUpdates(_logger);
 
             return functionConcurrencyStatus;
         }

diff --git a/src/Microsoft.Azure.WebJobs.Host/Scale/ConcurrencyStatus.cs b/src/Microsoft.Azure.WebJobs.Host/Scale/ConcurrencyStatus.cs
@@ -4,6 +4,7 @@
 using System;
 using System.Diagnostics;
 using System.Threading;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Azure.WebJobs.Host.Scale
 {
@@ -22,6 +23,7 @@ public class ConcurrencyStatus
 
         private int _adjustmentRunDirection;
         private int _adjustmentRunCount;
+        private int _lastLoggedConcurrency;
 
         /// <summary>
         /// Constructs a new instance.
@@ -239,6 +241,19 @@ internal void DecreaseConcurrency()
             AdjustConcurrency(delta);
         }
 
+        /// <summary>
+        /// Log if concurrency status has changed since the last call.
+        /// </summary>
+        /// <param name="logger">The logger to use.</param>
+        internal void LogUpdates(ILogger logger)
+        {
+            if (CurrentConcurrency != _lastLoggedConcurrency)
+            {
+                logger.HostConcurrencyStatus(FunctionId, CurrentConcurrency, OutstandingInvocations);
+                _lastLoggedConcurrency = CurrentConcurrency;
+            }
+        }
+
         internal void FunctionStarted()
         {
             lock (_syncLock)

diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Scale/ConcurrencyManagerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Scale/ConcurrencyManagerTests.cs
@@ -171,6 +171,46 @@ public void GetStatus_FunctionRecentlyAdjusted_ReturnsCurrentStatus()
             _mockThrottleManager.Verify(p => p.GetStatus(), Times.Never);
         }
 
+        [Fact]
+        public void GetStatus_OnlyLogsOnStatusChange()
+        {
+            TestHelpers.SetupStopwatch(_testFunctionConcurrencyStatus.LastConcurrencyAdjustmentStopwatch, TimeSpan.FromSeconds(ConcurrencyStatus.DefaultMinAdjustmentFrequencySeconds));
+            _throttleStatus = new ConcurrencyThrottleAggregateStatus { State = ThrottleState.Disabled };
+
+            // make a bunch of back to back GetStatus calls
+            // only expect a log entry for the first one
+            ConcurrencyStatus status = null;
+            for (int i = 0; i < 10; i++)
+            {
+                status = _concurrencyManager.GetStatus(TestFunctionId);
+            }
+            Assert.Equal(1, status.CurrentConcurrency);
+            var logs = _loggerProvider.GetAllLogMessages().Where(p => p.Category == LogCategories.Concurrency).ToArray();
+            Assert.Single(logs);
+            Assert.Equal("testfunction Concurrency: 1, OutstandingInvocations: 0", logs[0].FormattedMessage);
+
+            // now increase concurrency - expect a single log
+            _loggerProvider.ClearAllLogMessages();
+            status.IncreaseConcurrency();
+            TestHelpers.SetupStopwatch(_testFunctionConcurrencyStatus.LastConcurrencyAdjustmentStopwatch, TimeSpan.FromSeconds(ConcurrencyStatus.DefaultMinAdjustmentFrequencySeconds));
+            status = _concurrencyManager.GetStatus(TestFunctionId);
+            Assert.Equal(2, status.CurrentConcurrency);
+            logs = _loggerProvider.GetAllLogMessages().Where(p => p.Category == LogCategories.Concurrency).ToArray();
+            Assert.Single(logs);
+            Assert.Equal("testfunction Concurrency: 2, OutstandingInvocations: 0", logs[0].FormattedMessage);
+
+            // make a bunch more back to back GetStatus calls without
+            // changing anything - don't expect any logs
+            _loggerProvider.ClearAllLogMessages();
+            for (int i = 0; i < 10; i++)
+            {
+                status = _concurrencyManager.GetStatus(TestFunctionId);
+            }
+            Assert.Equal(2, status.CurrentConcurrency);
+            logs = _loggerProvider.GetAllLogMessages().Where(p => p.Category == LogCategories.Concurrency).ToArray();
+            Assert.Empty(logs);
+        }
+
         [Theory]
         [InlineData(50, true)]
         [InlineData(1, false)]

diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Scale/ConcurrencyStatusTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Scale/ConcurrencyStatusTests.cs
@@ -8,6 +8,7 @@
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host.Scale;
 using Microsoft.Azure.WebJobs.Host.TestCommon;
+using Microsoft.Extensions.Logging;
 using Moq;
 using Xunit;
 
@@ -22,6 +23,9 @@ public class ConcurrencyStatusTests
         private readonly Random _rand = new Random();
         private readonly Mock<ConcurrencyManager> _concurrencyManagerMock;
         private readonly ConcurrencyStatus _testConcurrencyStatus;
+        private readonly LoggerFactory _loggerFactory;
+        private readonly TestLoggerProvider _loggerProvider;
+        private readonly ILogger _testLogger;
 
         private ConcurrencyThrottleAggregateStatus _throttleStatus;
 
@@ -33,6 +37,11 @@ public ConcurrencyStatusTests()
             _concurrencyManagerMock.SetupGet(p => p.ThrottleStatus).Returns(() => _throttleStatus);
 
             _testConcurrencyStatus = new ConcurrencyStatus(TestFunctionId, _concurrencyManagerMock.Object);
+
+            _loggerFactory = new LoggerFactory();
+            _loggerProvider = new TestLoggerProvider();
+            _loggerFactory.AddProvider(_loggerProvider);
+            _testLogger = _loggerFactory.CreateLogger("Test");
         }
 
         [Fact]
@@ -414,5 +423,36 @@ public async Task FunctionExecutionEvents_Synchronization()
             Assert.Equal(latencies.Sum(), _testConcurrencyStatus.TotalInvocationTimeSinceLastAdjustmentMs);
             Assert.Equal(numThreads, _testConcurrencyStatus.MaxConcurrentExecutionsSinceLastAdjustment);
         }
+
+        [Fact]
+        public void LogStatus_OnlyLogsWhenStatusChanges()
+        {
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            var logs = _loggerProvider.GetAllLogMessages().ToArray();
+            Assert.Single(logs);
+            Assert.Equal("testfunction Concurrency: 1, OutstandingInvocations: 0", logs[0].FormattedMessage);
+
+            _loggerProvider.ClearAllLogMessages();
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            logs = _loggerProvider.GetAllLogMessages().ToArray();
+            Assert.Empty(logs);
+
+            _loggerProvider.ClearAllLogMessages();
+            _testConcurrencyStatus.IncreaseConcurrency();
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            logs = _loggerProvider.GetAllLogMessages().ToArray();
+            Assert.Single(logs);
+            Assert.Equal("testfunction Concurrency: 2, OutstandingInvocations: 0", logs[0].FormattedMessage);
+
+            _loggerProvider.ClearAllLogMessages();
+            _testConcurrencyStatus.ApplySnapshot(new FunctionConcurrencySnapshot { Concurrency = 3 });
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            _testConcurrencyStatus.LogUpdates(_testLogger);
+            logs = _loggerProvider.GetAllLogMessages().ToArray();
+            Assert.Single(logs);
+            Assert.Equal("testfunction Concurrency: 3, OutstandingInvocations: 0", logs[0].FormattedMessage);
+        }
     }
 }