Add logging to Resource Monitoring (#5355)

* Initial commit

* update

* update

* Fix tests

* PR Comments

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/Linux/LinuxUtilizationProvider.cs

@@ -3,6 +3,8 @@
 
 using System;
 using System.Diagnostics.Metrics;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring.Linux;
@@ -14,6 +16,7 @@ internal sealed class LinuxUtilizationProvider : ISnapshotProvider
 
     private readonly object _cpuLocker = new();
     private readonly object _memoryLocker = new();
+    private readonly ILogger<LinuxUtilizationProvider> _logger;
     private readonly ILinuxUtilizationParser _parser;
     private readonly ulong _memoryLimit;
     private readonly TimeSpan _cpuRefreshInterval;
@@ -28,15 +31,16 @@ internal sealed class LinuxUtilizationProvider : ISnapshotProvider
 
     private double _cpuPercentage = double.NaN;
     private double _memoryPercentage;
-    private double _previousCgroupCpuTime;
-    private double _previousHostCpuTime;
+    private long _previousCgroupCpuTime;
+    private long _previousHostCpuTime;
 
     public SystemResources Resources { get; }
 
     public LinuxUtilizationProvider(IOptions<ResourceMonitoringOptions> options, ILinuxUtilizationParser parser,
-        IMeterFactory meterFactory, TimeProvider? timeProvider = null)
+        IMeterFactory meterFactory, ILogger<LinuxUtilizationProvider>? logger = null, TimeProvider? timeProvider = null)
     {
         _parser = parser;
+        _logger = logger ?? NullLogger<LinuxUtilizationProvider>.Instance;
         _timeProvider = timeProvider ?? TimeProvider.System;
         DateTimeOffset now = _timeProvider.GetUtcNow();
         _cpuRefreshInterval = options.Value.CpuConsumptionRefreshInterval;
@@ -73,6 +77,7 @@ public LinuxUtilizationProvider(IOptions<ResourceMonitoringOptions> options, ILi
         // _memoryLimit - Resource Memory Limit (in k8s terms)
         // _memoryLimit - To keep the contract, this parameter will get the Host available memory
         Resources = new SystemResources(cpuRequest, cpuLimit, _memoryLimit, _memoryLimit);
+        Log.SystemResourcesInfo(_logger, cpuLimit, cpuRequest, _memoryLimit, _memoryLimit);
     }
 
     public double CpuUtilization()
@@ -94,12 +99,14 @@ public double CpuUtilization()
         {
             if (now >= _refreshAfterCpu)
             {
-                double deltaHost = hostCpuTime - _previousHostCpuTime;
-                double deltaCgroup = cgroupCpuTime - _previousCgroupCpuTime;
+                long deltaHost = hostCpuTime - _previousHostCpuTime;
+                long deltaCgroup = cgroupCpuTime - _previousCgroupCpuTime;
 
                 if (deltaHost > 0 && deltaCgroup > 0)
                 {
-                    double percentage = Math.Min(One, deltaCgroup / deltaHost);
+                    double percentage = Math.Min(One, (double)deltaCgroup / deltaHost);
+
+                    Log.CpuUsageData(_logger, cgroupCpuTime, hostCpuTime, _previousCgroupCpuTime, _previousHostCpuTime, percentage);
 
                     _cpuPercentage = percentage;
                     _refreshAfterCpu = now.Add(_cpuRefreshInterval);
@@ -137,6 +144,8 @@ public double MemoryUtilization()
             }
         }
 
+        Log.MemoryUsageData(_logger, memoryUsed, _memoryLimit, _memoryPercentage);
+
         return _memoryPercentage;
     }
 

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/Linux/Log.cs

@@ -0,0 +1,36 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System.Diagnostics.CodeAnalysis;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring;
+
+[SuppressMessage("Usage", "CA1801:Review unused parameters", Justification = "Generators.")]
+[SuppressMessage("Major Code Smell", "S109:Magic numbers should not be used", Justification = "Generators.")]
+internal static partial class Log
+{
+    [LoggerMessage(1, LogLevel.Debug,
+#pragma warning disable S103 // Lines should not be too long
+        "Computed CPU usage with CgroupCpuTime = {cgroupCpuTime}, HostCpuTime = {hostCpuTime}, PreviousCgroupCpuTime = {previousCgroupCpuTime}, PreviousHostCpuTime = {previousHostCpuTime}, CpuPercentage = {cpuPercentage}.")]
+#pragma warning restore S103 // Lines should not be too long
+    public static partial void CpuUsageData(
+        ILogger logger,
+        long cgroupCpuTime,
+        long hostCpuTime,
+        long previousCgroupCpuTime,
+        long previousHostCpuTime,
+        double cpuPercentage);
+
+    [LoggerMessage(2, LogLevel.Debug,
+        "Computed memory usage with MemoryUsedInBytes = {memoryUsed}, MemoryLimit = {memoryLimit}, MemoryPercentage = {memoryPercentage}.")]
+    public static partial void MemoryUsageData(
+        ILogger logger,
+        ulong memoryUsed,
+        double memoryLimit,
+        double memoryPercentage);
+
+    [LoggerMessage(3, LogLevel.Debug,
+        "System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}.")]
+    public static partial void SystemResourcesInfo(ILogger logger, double cpuLimit, double cpuRequest, ulong memoryLimit, ulong memoryRequest);
+}

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/Windows/Log.cs

@@ -15,4 +15,35 @@ internal static partial class Log
 
     [LoggerMessage(2, LogLevel.Information, "Resource Monitoring is running outside of Job Object. For more information about Job Objects see https://aka.ms/job-objects")]
     public static partial void RunningOutsideJobObject(ILogger logger);
+
+    [LoggerMessage(3, LogLevel.Debug,
+        "Computed CPU usage with CpuUsageTicks = {cpuUsageTicks}, OldCpuUsageTicks = {oldCpuUsageTicks}, TimeTickDelta = {timeTickDelta}, CpuUnits = {cpuUnits}, CpuPercentage = {cpuPercentage}.")]
+    public static partial void CpuUsageData(ILogger logger,
+        long cpuUsageTicks,
+        long oldCpuUsageTicks,
+        double timeTickDelta,
+        double cpuUnits,
+        double cpuPercentage);
+
+    [LoggerMessage(4, LogLevel.Debug,
+        "Computed memory usage with CurrentMemoryUsage = {currentMemoryUsage}, TotalMemory = {totalMemory}, MemoryPercentage = {memoryPercentage}.")]
+    public static partial void MemoryUsageData(ILogger logger,
+        ulong currentMemoryUsage,
+        double totalMemory,
+        double memoryPercentage);
+
+#pragma warning disable S103 // Lines should not be too long
+    [LoggerMessage(5, LogLevel.Debug, "Computed CPU usage with CpuUsageKernelTicks = {cpuUsageKernelTicks}, CpuUsageUserTicks = {cpuUsageUserTicks}, OldCpuUsageTicks = {oldCpuUsageTicks}, TimeTickDelta = {timeTickDelta}, CpuUnits = {cpuUnits}, CpuPercentage = {cpuPercentage}.")]
+#pragma warning restore S103 // Lines should not be too long
+    public static partial void CpuContainerUsageData(ILogger logger,
+        long cpuUsageKernelTicks,
+        long cpuUsageUserTicks,
+        long oldCpuUsageTicks,
+        double timeTickDelta,
+        double cpuUnits,
+        double cpuPercentage);
+
+    [LoggerMessage(6, LogLevel.Debug,
+        "System resources information: CpuLimit = {cpuLimit}, CpuRequest = {cpuRequest}, MemoryLimit = {memoryLimit}, MemoryRequest = {memoryRequest}.")]
+    public static partial void SystemResourcesInfo(ILogger logger, double cpuLimit, double cpuRequest, ulong memoryLimit, ulong memoryRequest);
 }

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/Windows/WindowsContainerSnapshotProvider.cs

@@ -7,6 +7,7 @@
 using System.Threading;
 using Microsoft.Extensions.Diagnostics.ResourceMonitoring.Windows.Interop;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring.Windows;
@@ -26,6 +27,7 @@ internal sealed class WindowsContainerSnapshotProvider : ISnapshotProvider
     private readonly object _memoryLocker = new();
     private readonly TimeProvider _timeProvider;
     private readonly IProcessInfo _processInfo;
+    private readonly ILogger<WindowsContainerSnapshotProvider> _logger;
     private readonly double _memoryLimit;
     private readonly double _cpuLimit;
     private readonly TimeSpan _cpuRefreshInterval;
@@ -44,7 +46,7 @@ internal sealed class WindowsContainerSnapshotProvider : ISnapshotProvider
     /// Initializes a new instance of the <see cref="WindowsContainerSnapshotProvider"/> class.
     /// </summary>
     public WindowsContainerSnapshotProvider(
-        ILogger<WindowsContainerSnapshotProvider> logger,
+        ILogger<WindowsContainerSnapshotProvider>? logger,
         IMeterFactory meterFactory,
         IOptions<ResourceMonitoringOptions> options)
         : this(new MemoryInfo(), new SystemInfo(), new ProcessInfo(), logger, meterFactory,
@@ -61,13 +63,14 @@ internal WindowsContainerSnapshotProvider(
         IMemoryInfo memoryInfo,
         ISystemInfo systemInfo,
         IProcessInfo processInfo,
-        ILogger<WindowsContainerSnapshotProvider> logger,
+        ILogger<WindowsContainerSnapshotProvider>? logger,
         IMeterFactory meterFactory,
         Func<IJobHandle> createJobHandleObject,
         TimeProvider timeProvider,
         ResourceMonitoringOptions options)
     {
-        Log.RunningInsideJobObject(logger);
+        _logger = logger ?? NullLogger<WindowsContainerSnapshotProvider>.Instance;
+        Log.RunningInsideJobObject(_logger);
 
         _memoryStatus = new Lazy<MEMORYSTATUSEX>(
             memoryInfo.GetMemoryStatus,
@@ -88,6 +91,7 @@ internal WindowsContainerSnapshotProvider(
         var cpuRequest = _cpuLimit;
         var memoryRequest = memoryLimitLong;
         Resources = new SystemResources(cpuRequest, _cpuLimit, memoryRequest, memoryLimitLong);
+        Log.SystemResourcesInfo(_logger, _cpuLimit, cpuRequest, memoryLimitLong, memoryRequest);
 
         var basicAccountingInfo = jobHandle.GetBasicAccountingInfo();
         _oldCpuUsageTicks = basicAccountingInfo.TotalKernelTime + basicAccountingInfo.TotalUserTime;
@@ -195,6 +199,8 @@ private double MemoryPercentage(Func<ulong> getMemoryUsage)
                 _refreshAfterMemory = now.Add(_memoryRefreshInterval);
             }
 
+            Log.MemoryUsageData(_logger, memoryUsage, _memoryLimit, _memoryPercentage);
+
             return _memoryPercentage;
         }
     }
@@ -223,9 +229,13 @@ private double CpuPercentage()
                 var timeTickDelta = (now.Ticks - _oldCpuTimeTicks) * _cpuLimit;
                 if (usageTickDelta > 0 && timeTickDelta > 0)
                 {
+                    _cpuPercentage = Math.Min(Hundred, usageTickDelta / timeTickDelta * Hundred); // Don't change calculation order, otherwise precision is lost.
+
+                    Log.CpuContainerUsageData(
+                        _logger, basicAccountingInfo.TotalKernelTime, basicAccountingInfo.TotalUserTime, _oldCpuUsageTicks, timeTickDelta, _cpuLimit, _cpuPercentage);
+
                     _oldCpuUsageTicks = currentCpuTicks;
                     _oldCpuTimeTicks = now.Ticks;
-                    _cpuPercentage = Math.Min(Hundred, usageTickDelta / timeTickDelta * Hundred); // Don't change calculation order, otherwise we loose some precision
                     _refreshAfterCpu = now.Add(_cpuRefreshInterval);
                 }
             }

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/Windows/WindowsSnapshotProvider.cs

@@ -7,6 +7,7 @@
 using System.Diagnostics.Metrics;
 using Microsoft.Extensions.Diagnostics.ResourceMonitoring.Windows.Interop;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring.Windows;
@@ -20,6 +21,7 @@ internal sealed class WindowsSnapshotProvider : ISnapshotProvider
     private readonly int _cpuUnits;
     private readonly object _cpuLocker = new();
     private readonly object _memoryLocker = new();
+    private readonly ILogger<WindowsSnapshotProvider> _logger;
     private readonly TimeProvider _timeProvider;
     private readonly Func<long> _getCpuTicksFunc;
     private readonly Func<long> _getMemoryUsageFunc;
@@ -34,14 +36,14 @@ internal sealed class WindowsSnapshotProvider : ISnapshotProvider
     private double _cpuPercentage = double.NaN;
     private double _memoryPercentage;
 
-    public WindowsSnapshotProvider(ILogger<WindowsSnapshotProvider> logger, IMeterFactory meterFactory, IOptions<ResourceMonitoringOptions> options)
+    public WindowsSnapshotProvider(ILogger<WindowsSnapshotProvider>? logger, IMeterFactory meterFactory, IOptions<ResourceMonitoringOptions> options)
     : this(logger, meterFactory, options.Value, TimeProvider.System, GetCpuUnits, GetCpuTicks, GetMemoryUsageInBytes, GetTotalMemoryInBytes)
     {
     }
 
     [SuppressMessage("Major Code Smell", "S107:Methods should not have too many parameters", Justification = "Dependencies for testing")]
     internal WindowsSnapshotProvider(
-        ILogger<WindowsSnapshotProvider> logger,
+        ILogger<WindowsSnapshotProvider>? logger,
         IMeterFactory meterFactory,
         ResourceMonitoringOptions options,
         TimeProvider timeProvider,
@@ -50,7 +52,9 @@ internal WindowsSnapshotProvider(
         Func<long> getMemoryUsageFunc,
         Func<ulong> getTotalMemoryInBytesFunc)
     {
-        Log.RunningOutsideJobObject(logger);
+        _logger = logger ?? NullLogger<WindowsSnapshotProvider>.Instance;
+
+        Log.RunningOutsideJobObject(_logger);
 
         _cpuUnits = getCpuUnitsFunc();
         var totalMemory = getTotalMemoryInBytesFunc();
@@ -59,6 +63,7 @@ internal WindowsSnapshotProvider(
         // any resource requests or resource limits, therefore using physical values
         // such as number of CPUs and physical memory and using it for both requests and limits (aka 'guaranteed' and 'max'):
         Resources = new SystemResources(_cpuUnits, _cpuUnits, totalMemory, totalMemory);
+        Log.SystemResourcesInfo(_logger, _cpuUnits, _cpuUnits, totalMemory, totalMemory);
 
         _timeProvider = timeProvider;
         _getCpuTicksFunc = getCpuTicksFunc;
@@ -135,6 +140,8 @@ private double MemoryPercentage()
                 _refreshAfterMemory = now.Add(_memoryRefreshInterval);
             }
 
+            Log.MemoryUsageData(_logger, (ulong)currentMemoryUsage, _totalMemory, _memoryPercentage);
+
             return _memoryPercentage;
         }
     }
@@ -161,9 +168,12 @@ private double CpuPercentage()
                 var timeTickDelta = (now.Ticks - _oldCpuTimeTicks) * _cpuUnits;
                 if (usageTickDelta > 0 && timeTickDelta > 0)
                 {
+                    _cpuPercentage = Math.Min(Hundred, usageTickDelta / (double)timeTickDelta * Hundred); // Don't change calculation order, otherwise we loose some precision
+
+                    Log.CpuUsageData(_logger, currentCpuTicks, _oldCpuUsageTicks, timeTickDelta, _cpuUnits, _cpuPercentage);
+
                     _oldCpuUsageTicks = currentCpuTicks;
                     _oldCpuTimeTicks = now.Ticks;
-                    _cpuPercentage = Math.Min(Hundred, usageTickDelta / (double)timeTickDelta * Hundred); // Don't change calculation order, otherwise we loose some precision
                     _refreshAfterCpu = now.Add(_cpuRefreshInterval);
                 }
             }