Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add logging of snapshot information in ResourceMonitorService #5362

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
Expand Down
Original file line number Diff line number Diff line change
@@ -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;

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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.";
Expand Down Expand Up @@ -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()
{
Expand Down Expand Up @@ -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);

Expand Down
Original file line number Diff line number Diff line change
@@ -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
}