Add logging of snapshot information in ResourceMonitorService (#5362)

* Add logging of snapshot information in ResourceMonitorService

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

@@ -16,4 +16,13 @@ internal static partial class Log
 
     [LoggerMessage(2, LogLevel.Error, "Publisher `{Publisher}` was unable to publish utilization statistics.")]
     public static partial void HandlePublishUtilizationException(ILogger logger, Exception e, string publisher);
+
+    [LoggerMessage(3, LogLevel.Debug,
+        "Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}.")]
+    public static partial void SnapshotReceived(
+        ILogger logger,
+        TimeSpan totalTimeSinceStart,
+        TimeSpan kernelTimeSinceStart,
+        TimeSpan userTimeSinceStart,
+        ulong memoryUsageInBytes);
 }

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/ResourceMonitorService.cs

@@ -130,7 +130,10 @@ protected override async Task ExecuteAsync(CancellationToken cancellationToken)
 
             try
             {
-                _snapshotsStore.Add(_provider.GetSnapshot());
+                var snapshot = _provider.GetSnapshot();
+                _snapshotsStore.Add(snapshot);
+
+                Log.SnapshotReceived(_logger, snapshot.TotalTimeSinceStart, snapshot.KernelTimeSinceStart, snapshot.UserTimeSinceStart, snapshot.MemoryUsageInBytes);
             }
             catch (Exception e)
             {

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/ResourceMonitoringLinuxCgroupVersion.cs

@@ -1,4 +1,7 @@
-using System.Diagnostics.CodeAnalysis;
+// 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 System.IO;
 
 // Licensed to the .NET Foundation under one or more agreements.

src/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring/SystemResources.cs

@@ -1,4 +1,7 @@
-using Microsoft.Shared.Diagnostics;
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using Microsoft.Shared.Diagnostics;
 
 namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring;
 

test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/ResourceMonitoringServiceTests.cs

@@ -13,6 +13,7 @@
 using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Time.Testing;
 using Moq;
+using VerifyXunit;
 using Xunit;
 using static Microsoft.Extensions.Options.Options;
 
@@ -21,6 +22,7 @@ namespace Microsoft.Extensions.Diagnostics.ResourceMonitoring.Test;
 /// <summary>
 /// Tests for the DataTracker class.
 /// </summary>
+[UsesVerify]
 public sealed class ResourceMonitoringServiceTests
 {
     private const string ProviderUnableToGatherData = "Unable to gather utilization statistics.";
@@ -344,6 +346,35 @@ public async Task ResourceUtilizationTracker_InitializedProperly_InvokesPublishe
         Assert.True(publisherCalled);
     }
 
+    [Fact]
+    public async Task ResourceUtilizationTracker_LogsSnapshotInformation()
+    {
+        const int TimerPeriod = 100;
+        var logger = new FakeLogger<ResourceMonitorService>();
+        var clock = new FakeTimeProvider();
+
+        using var tracker = new ResourceMonitorService(
+            new FakeProvider(),
+            logger,
+            Create(new ResourceMonitoringOptions
+            {
+                CollectionWindow = TimeSpan.FromMilliseconds(TimerPeriod),
+                PublishingWindow = TimeSpan.FromMilliseconds(TimerPeriod),
+                SamplingInterval = TimeSpan.FromMilliseconds(TimerPeriod)
+            }),
+            Array.Empty<IResourceUtilizationPublisher>(),
+            clock);
+
+        // Start running the tracker.
+        await tracker.StartAsync(CancellationToken.None);
+
+        clock.Advance(TimeSpan.FromMilliseconds(TimerPeriod));
+
+        await tracker.StopAsync(CancellationToken.None);
+
+        await Verifier.Verify(logger.Collector.LatestRecord).UseDirectory("Verified");
+    }
+
     [Fact(Skip = "Broken test, see https://github.com/dotnet/extensions/issues/4529")]
     public async Task ResourceUtilizationTracker_WhenInitializedWithZeroSnapshots_ReportsHighCpuSpikesThenConvergeInFewCycles()
     {
@@ -636,7 +667,7 @@ public void GetUtilization_BasicTest()
     }
 
     [Fact]
-    public void GetUtilization_ProvidedByWindowGreaterThanSamplingWindowButLesserThanCollectionWindow_Successes()
+    public void GetUtilization_ProvidedByWindowGreaterThanSamplingWindowButLesserThanCollectionWindow_Succeeds()
     {
         var providerMock = new Mock<ISnapshotProvider>(MockBehavior.Loose);
 

test/Libraries/Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests/Verified/ResourceMonitoringServiceTests.ResourceUtilizationTracker_LogsSnapshotInformation.verified.txt

@@ -0,0 +1,45 @@
+{
+  Level: Debug,
+  Id: {
+    Id: 3,
+    Name: SnapshotReceived
+  },
+  State: [
+    {
+      {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}.
+    },
+    {
+      memoryUsageInBytes: 500
+    },
+    {
+      userTimeSinceStart: 00:00:01
+    },
+    {
+      kernelTimeSinceStart: 00:00:01
+    },
+    {
+      totalTimeSinceStart: 730119.00:00:00
+    }
+  ],
+  StructuredState: [
+    {
+      {OriginalFormat}: Snapshot received: TotalTimeSinceStart={totalTimeSinceStart}, KernelTimeSinceStart={kernelTimeSinceStart}, UserTimeSinceStart={userTimeSinceStart}, MemoryUsageInBytes={memoryUsageInBytes}.
+    },
+    {
+      memoryUsageInBytes: 500
+    },
+    {
+      userTimeSinceStart: 00:00:01
+    },
+    {
+      kernelTimeSinceStart: 00:00:01
+    },
+    {
+      totalTimeSinceStart: 730119.00:00:00
+    }
+  ],
+  Message: Snapshot received: TotalTimeSinceStart=730119.00:00:00, KernelTimeSinceStart=00:00:01, UserTimeSinceStart=00:00:01, MemoryUsageInBytes=500.,
+  Category: Microsoft.Extensions.Diagnostics.ResourceMonitoring.ResourceMonitorService,
+  LevelEnabled: true,
+  Timestamp: DateTimeOffset_1
+}