Skip to content

Commit

Permalink
Implements elastic#922: Add GC time to the .Net Agent
Browse files Browse the repository at this point in the history
  • Loading branch information
@jpenniman @gregkalapos
jpenniman authored and gregkalapos committed Mar 2, 2021
1 parent 9f74f82 commit 0c903cf
Show file tree
Hide file tree
Showing 3 changed files with 84 additions and 16 deletions.
4 changes: 3 additions & 1 deletion src/Elastic.Apm/Metrics/MetricsCollector.cs
View file
Expand Up @@ -93,10 +93,12 @@ public MetricsCollector(IApmLogger logger, IPayloadSender payloadSender, IConfig
GcMetricsProvider.GcGen2SizeName);
var collectGen3Size = !WildcardMatcher.IsAnyMatch(currentConfigSnapshot.DisableMetrics,
GcMetricsProvider.GcGen3SizeName);
var collectGcTime = !WildcardMatcher.IsAnyMatch(currentConfigSnapshot.DisableMetrics,
GcMetricsProvider.GcTimeName);
if (collectGcCount || collectGen0Size || collectGen1Size || collectGen2Size || collectGen3Size)
{
MetricsProviders.Add(new GcMetricsProvider(_logger, collectGcCount, collectGen0Size, collectGen1Size, collectGen2Size,
collectGen3Size));
collectGen3Size, collectGcTime));
}

var collectCgroupMemLimitBytes = !WildcardMatcher.IsAnyMatch(currentConfigSnapshot.DisableMetrics,
Expand Down
77 changes: 68 additions & 9 deletions src/Elastic.Apm/Metrics/MetricsProvider/GcMetricsProvider.cs
View file
Expand Up @@ -11,6 +11,7 @@
using Elastic.Apm.Helpers;
using Elastic.Apm.Logging;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Analysis;
using Microsoft.Diagnostics.Tracing.Parsers;
using Microsoft.Diagnostics.Tracing.Parsers.Clr;
using Microsoft.Diagnostics.Tracing.Session;
Expand All @@ -29,12 +30,14 @@ internal class GcMetricsProvider : IMetricsProvider, IDisposable
private const string SessionNamePrefix = "EtwSessionForCLRElasticApm_";

internal const string GcCountName = "clr.gc.count";
internal const string GcTimeName = "clr.gc.time";
internal const string GcGen0SizeName = "clr.gc.gen0size";
internal const string GcGen1SizeName = "clr.gc.gen1size";
internal const string GcGen2SizeName = "clr.gc.gen2size";
internal const string GcGen3SizeName = "clr.gc.gen3size";

private readonly bool _collectGcCount;
private readonly bool _collectGcTime;
private readonly bool _collectGcGen0Size;
private readonly bool _collectGcGen1Size;
private readonly bool _collectGcGen2Size;
Expand All @@ -53,12 +56,14 @@ internal class GcMetricsProvider : IMetricsProvider, IDisposable
private ulong _gen1Size;
private ulong _gen2Size;
private ulong _gen3Size;
private double _gcTime;

public GcMetricsProvider(IApmLogger logger, bool collectGcCount = true, bool collectGcGen0Size = true, bool collectGcGen1Size = true,
bool collectGcGen2Size = true, bool collectGcGen3Size = true
bool collectGcGen2Size = true, bool collectGcGen3Size = true, bool collectGcTime = true
)
{
_collectGcCount = collectGcCount;
_collectGcTime = collectGcTime;
_collectGcGen0Size = collectGcGen0Size;
_collectGcGen1Size = collectGcGen1Size;
_collectGcGen2Size = collectGcGen2Size;
Expand All @@ -74,6 +79,7 @@ internal class GcMetricsProvider : IMetricsProvider, IDisposable
{
try
{
_traceEventSession.Source.NeedLoadedDotNetRuntimes();
_traceEventSession.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
Expand All @@ -89,9 +95,49 @@ internal class GcMetricsProvider : IMetricsProvider, IDisposable
_traceEventSession.Source.Clr.GCStop += ClrOnGCStop;
_traceEventSession.Source.Clr.GCHeapStats += ClrOnGCHeapStats;
_traceEventSession.Source.Process();
_traceEventSession.Source.AddCallbackOnProcessStart(process =>
{
process.AddCallbackOnDotNetRuntimeLoad(runtime =>
{
runtime.GCEnd += (traceProcess, gc) =>
{
if (traceProcess.ProcessID == Process.GetCurrentProcess().Id)
{
if (!_isMetricAlreadyCaptured)
{
lock (_lock)
_isMetricAlreadyCaptured = true;
}
_gcTime = gc.DurationMSec;
_gcCount = (uint)gc.Number;
}
};
});
});
_traceEventSession.Source.Clr.GCHeapStats += (a) =>
{
if (a.ProcessID == Process.GetCurrentProcess().Id)
{
if (!_isMetricAlreadyCaptured)
{
lock (_lock)
_isMetricAlreadyCaptured = true;
}
_gen0Size = (ulong)a.GenerationSize0;
_gen1Size = (ulong)a.GenerationSize1;
_gen2Size = (ulong)a.GenerationSize2;
_gen3Size = (ulong)a.GenerationSize3;
}
};
_traceEventSession.Source.Process();
});
}


if (PlatformDetection.IsDotNetCore || PlatformDetection.IsDotNet5)
_eventListener = new GcEventListener(this, logger);
}
Expand All @@ -103,7 +149,8 @@ public bool IsMetricAlreadyCaptured
{
get
{
lock (_lock) return _isMetricAlreadyCaptured;
lock (_lock)
return _isMetricAlreadyCaptured;
}
}

Expand All @@ -115,12 +162,14 @@ public bool IsMetricAlreadyCaptured

public IEnumerable<MetricSample> GetSamples()
{
if (_gcCount != 0 || _gen0Size != 0 || _gen2Size != 0 || _gen3Size != 0)
if (_gcCount != 0 || _gen0Size != 0 || _gen2Size != 0 || _gen3Size != 0 || _gcTime > 0)
{
var retVal = new List<MetricSample>(5);

if (_collectGcCount)
retVal.Add(new MetricSample(GcCountName, _gcCount));
if (_collectGcTime)
retVal.Add(new MetricSample(GcTimeName, _gcTime));
if (_collectGcGen0Size)
retVal.Add(new MetricSample(GcGen0SizeName, _gen0Size));
if (_collectGcGen1Size)
Expand All @@ -134,8 +183,8 @@ public IEnumerable<MetricSample> GetSamples()
}
_logger.Trace()
?.Log(
"Collected gc metrics values: gcCount: {gcCount}, gen0Size: {gen0Size}, gen1Size: {gen1Size}, gen2Size: {gen2Size}, gen1Size: {gen3Size}",
_gcCount, _gen0Size, _gen1Size, _gen2Size, _gen3Size);
"Collected gc metrics values: gcCount: {gcCount}, gen0Size: {gen0Size}, gen1Size: {gen1Size}, gen2Size: {gen2Size}, gen1Size: {gen3Size}, gcTime: {gcTime}",
_gcCount, _gen0Size, _gen1Size, _gen2Size, _gen3Size, _gcTime);
return null;
}

Expand Down Expand Up @@ -190,6 +239,7 @@ private class GcEventListener : EventListener
private static readonly int keywordGC = 1;
private readonly GcMetricsProvider _gcMetricsProvider;
private readonly IApmLogger _logger;
private long _gcStartTime;

public GcEventListener(GcMetricsProvider gcMetricsProvider, IApmLogger logger)
{
Expand All @@ -205,7 +255,8 @@ protected override void OnEventSourceCreated(EventSource eventSource)
{
try
{
if (!eventSource.Name.Equals("Microsoft-Windows-DotNETRuntime")) return;
if (!eventSource.Name.Equals("Microsoft-Windows-DotNETRuntime"))
return;

EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)keywordGC);
_eventSourceDotNet = eventSource;
Expand Down Expand Up @@ -252,6 +303,9 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData)
}
}

if (eventData.EventName.Contains("GCStart"))
_gcStartTime = DateTime.UtcNow.Ticks;

// Collect GC count
if (eventData.EventName.Contains("GCEnd"))
{
Expand All @@ -263,20 +317,25 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData)

_logger?.Trace()?.Log("OnEventWritten with GCEnd");

_gcMetricsProvider._gcTime = (DateTime.UtcNow.Ticks - _gcStartTime) / 10_000.0;

var indexOfCount = IndexOf("Count");
if (indexOfCount < 0) return;
if (indexOfCount < 0)
return;

var gcCount = eventData.Payload[indexOfCount];

if (!(gcCount is uint gcCountInt)) return;
if (!(gcCount is uint gcCountInt))
return;

_gcMetricsProvider._gcCount = gcCountInt;
}

void SetValue(string name, ref ulong value)
{
var gen0SizeIndex = IndexOf(name);
if (gen0SizeIndex < 0) return;
if (gen0SizeIndex < 0)
return;

var gen0Size = eventData.Payload[gen0SizeIndex];
if (gen0Size is ulong gen0SizeLong)
Expand Down
19 changes: 13 additions & 6 deletions test/Elastic.Apm.Tests/MetricsTests.cs
View file
Expand Up @@ -64,7 +64,8 @@ public void CollectAllMetrics()
[Fact]
public void SystemCpu()
{
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Linux) && !RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) return;
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Linux) && !RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
return;

using var systemTotalCpuProvider = new SystemTotalCpuProvider(new NoopLogger());
Thread.Sleep(1000); //See https://github.com/elastic/apm-agent-dotnet/pull/264#issuecomment-499778288
Expand Down Expand Up @@ -106,7 +107,8 @@ public void ProviderWithException()
var providerWithException = new MetricsProviderWithException();
mc.MetricsProviders.Add(providerWithException);

for (var i = 0; i < MetricsCollector.MaxTryWithoutSuccess; i++) mc.CollectAllMetrics();
for (var i = 0; i < MetricsCollector.MaxTryWithoutSuccess; i++)
mc.CollectAllMetrics();

providerWithException.NumberOfGetValueCalls.Should().Be(MetricsCollector.MaxTryWithoutSuccess);

Expand All @@ -121,7 +123,8 @@ public void ProviderWithException()
$"Failed reading {providerWithException.DbgName} {MetricsCollector.MaxTryWithoutSuccess} consecutively - the agent won't try reading {providerWithException.DbgName} anymore");

//make sure GetValue() in MetricsProviderWithException is not called anymore:
for (var i = 0; i < 10; i++) mc.CollectAllMetrics();
for (var i = 0; i < 10; i++)
mc.CollectAllMetrics();

var logLineBeforeStage2 = testLogger.Lines.Count;
//no more logs, no more calls to GetValue():
Expand Down Expand Up @@ -234,7 +237,8 @@ public void CollectAllMetrics_ShouldDisableProvider_WhenSamplesAreInvalid(List<M
metricsCollector.MetricsProviders.Add(metricsProviderMock.Object);

// Act
foreach (var _ in Enumerable.Range(0, iterations)) metricsCollector.CollectAllMetrics();
foreach (var _ in Enumerable.Range(0, iterations))
metricsCollector.CollectAllMetrics();

// Assert
mockPayloadSender.Metrics.Should().BeEmpty();
Expand Down Expand Up @@ -265,7 +269,8 @@ public void CollectAllMetrics_ShouldNotDisableProvider_WhenAnyValueIsSamplesIsVa
metricsCollector.MetricsProviders.Add(metricsProviderMock.Object);

// Act
foreach (var _ in Enumerable.Range(0, iterations)) metricsCollector.CollectAllMetrics();
foreach (var _ in Enumerable.Range(0, iterations))
metricsCollector.CollectAllMetrics();

// Assert
mockPayloadSender.Metrics.Count.Should().Be(iterations);
Expand All @@ -292,6 +297,7 @@ public void CollectGcMetrics()
var containsValue = false;
var hasGenSize = false;


for (var j = 0; j < 1000; j++)
{
for (var i = 0; i < 300_000; i++)
Expand All @@ -308,7 +314,7 @@ public void CollectGcMetrics()

GC.Collect();

var samples = gcMetricsProvider.GetSamples();
var samples = gcMetricsProvider.GetSamples()?.ToArray();

containsValue = samples != null && samples.Any();
hasGenSize = samples != null && samples
Expand All @@ -318,6 +324,7 @@ public void CollectGcMetrics()

if (containsValue && hasGenSize)
break;

}

if (PlatformDetection.IsDotNetFullFramework)
Expand Down

0 comments on commit 0c903cf

Please sign in to comment.