From: Noah Falk Date: Thu, 19 Sep 2024 21:02:26 +0000 (-0700) Subject: Metric name disambiguation (#4938) X-Git-Tag: accepted/tizen/unified/20241231.014852~39^2^2 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=37b70e07df52a98d08093565c574d423eff9e795;p=platform%2Fcore%2Fdotnet%2Fdiagnostics.git Metric name disambiguation (#4938) In .NET 8.0 we added tags on Meters and Instruments but MetricsEventSource only included the names when emitting value publishing events. This made it ambiguous when there was more than one Meter or Instrument with the same name. In 9.0 MetricsEventSource started included InstrumentIDs in the BeginInstrumentReporting events and in the value publishing events that provides a stronger correlation identifier. This change consumes the IDs in those events within Microsoft.Diagnostics.Monitoring.EventPipe, allowing dotnet-counters (and presumably dotnet-monitor too) to track time series that differ only by the tags provided to the Meter/Instrument constructors. I also re-enabled a disabled test that got broken when .NET 9.0 added the System.Runtime Meter. Fixes #4843, #4564 --- diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs index 7bd7e3611..d6833da30 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs @@ -37,20 +37,64 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe internal static class TraceEventExtensions { private static Dictionary counterMetadataByName = new(); + private static Dictionary counterMetadataById = new(); private static HashSet inactiveSharedSessions = new(StringComparer.OrdinalIgnoreCase); - // This assumes uniqueness of provider/counter combinations; - // this is currently a limitation (see https://github.com/dotnet/runtime/issues/93097 and https://github.com/dotnet/runtime/issues/93767) - public static CounterMetadata GetCounterMetadata(string providerName, string counterName, string meterTags = null, string instrumentTags = null, string scopeHash = null) + private static CounterMetadata AddCounterMetadata(string providerName, string counterName, int? id, string meterTags, string instrumentTags, string scopeHash) { + CounterMetadata metadata; + if (id.HasValue && counterMetadataById.TryGetValue(id.Value, out metadata)) + { + return metadata; + } + + // Its possible that we previously indexed this counter by name but it didn't have an ID at that point because we weren't + // listening to it then. + // Its also possible that we previously indexed a counter with the same name as this one but with different tags or scope hash. ProviderAndCounter providerAndCounter = new(providerName, counterName); - if (counterMetadataByName.TryGetValue(providerAndCounter, out CounterMetadata provider)) + if (counterMetadataByName.TryGetValue(providerAndCounter, out metadata)) { - return provider; + // we found a counter that matches the name, but it might not match everything + if (metadata.MeterTags == meterTags && metadata.InstrumentTags == instrumentTags && metadata.ScopeHash == scopeHash) + { + // add the ID index if it didn't exist before + if (id.HasValue) + { + counterMetadataById.TryAdd(id.Value, metadata); + } + return metadata; + } } - counterMetadataByName.Add(providerAndCounter, new CounterMetadata(providerName, counterName, meterTags, instrumentTags, scopeHash)); - return counterMetadataByName[providerAndCounter]; + // no pre-existing counter metadata was found, create a new one + metadata = new CounterMetadata(providerName, counterName, meterTags, instrumentTags, scopeHash); + if (id.HasValue) + { + counterMetadataById.TryAdd(id.Value, metadata); + } + counterMetadataByName.TryAdd(providerAndCounter, metadata); + return metadata; + } + + private static CounterMetadata GetCounterMetadata(string providerName, string counterName, int? id) + { + // Lookup by ID is preferred because it eliminates ambiguity in the case of duplicate provider/counter names. + // IDs are present starting in MetricsEventSource 9.0. + // Duplicate named providers/counters might still have different tags or scope hashes + CounterMetadata metadata; + if (id.HasValue && counterMetadataById.TryGetValue(id.Value, out metadata)) + { + return metadata; + } + ProviderAndCounter providerAndCounter = new(providerName, counterName); + if (counterMetadataByName.TryGetValue(providerAndCounter, out metadata)) + { + return metadata; + } + + // For EventCounter based events we expect to fall through here the first time a new counter is observed + // For MetricsEventSource events we should never reach here unless the BeginInstrumentRecording event was dropped. + return AddCounterMetadata(providerName, counterName, id, null, null, null); } public static bool TryGetCounterPayload(this TraceEvent traceEvent, CounterConfiguration counterConfiguration, out ICounterPayload payload) @@ -185,22 +229,29 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe string unit = (string)obj.PayloadValue(4); string tags = (string)obj.PayloadValue(5); string lastValueText = (string)obj.PayloadValue(6); + int? id = null; + + if (obj.Version >= 2) + { + id = (int)obj.PayloadValue(7); + } if (!counterConfiguration.CounterFilter.IsIncluded(meterName, instrumentName)) { return; } + CounterMetadata metadata = GetCounterMetadata(meterName, instrumentName, id); // the value might be an empty string indicating no measurement was provided this collection interval if (double.TryParse(lastValueText, NumberStyles.Number | NumberStyles.Float, CultureInfo.InvariantCulture, out double lastValue)) { - payload = new GaugePayload(GetCounterMetadata(meterName, instrumentName), null, unit, tags, lastValue, obj.TimeStamp); + payload = new GaugePayload(metadata, null, unit, tags, lastValue, obj.TimeStamp); } else { // for observable instruments we assume the lack of data is meaningful and remove it from the UI // this happens when the Gauge callback function throws an exception. - payload = new CounterEndedPayload(GetCounterMetadata(meterName, instrumentName), obj.TimeStamp); + payload = new CounterEndedPayload(metadata, obj.TimeStamp); } } @@ -223,18 +274,25 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe return; } - if (traceEvent.Version < 1) + string instrumentTags = null; + string meterTags = null; + string meterScopeHash = null; + int? instrumentID = null; + + if (traceEvent.Version >= 1) { - payload = new BeginInstrumentReportingPayload(GetCounterMetadata(meterName, instrumentName), traceEvent.TimeStamp); + instrumentTags = (string)traceEvent.PayloadValue(7); + meterTags = (string)traceEvent.PayloadValue(8); + meterScopeHash = (string)traceEvent.PayloadValue(9); } - else + if (traceEvent.Version >= 2) { - string instrumentTags = (string)traceEvent.PayloadValue(7); - string meterTags = (string)traceEvent.PayloadValue(8); - string meterScopeHash = (string)traceEvent.PayloadValue(9); - - payload = new BeginInstrumentReportingPayload(GetCounterMetadata(meterName, instrumentName, meterTags, instrumentTags, meterScopeHash), traceEvent.TimeStamp); + int id = (int)traceEvent.PayloadValue(10); + // ID zero is a sentinel value for MetricsEventSource events indicating no ID was provided because the instrument was not being listened to. + // Many different instruments may all share ID zero we don't want to index them by that ID. + instrumentID = (id != 0) ? id : null; } + payload = new BeginInstrumentReportingPayload(AddCounterMetadata(meterName, instrumentName, instrumentID, meterTags, instrumentTags, meterScopeHash), traceEvent.TimeStamp); } private static void HandleCounterRate(TraceEvent traceEvent, CounterConfiguration counterConfiguration, out ICounterPayload payload) @@ -256,27 +314,32 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe string rateText = (string)traceEvent.PayloadValue(6); //Starting in .NET 8 we also publish the absolute value of these counters string absoluteValueText = null; + int? id = null; if (traceEvent.Version >= 1) { absoluteValueText = (string)traceEvent.PayloadValue(7); } + if (traceEvent.Version >= 2) + { + id = (int)traceEvent.PayloadValue(8); + } if (!counterConfiguration.CounterFilter.IsIncluded(meterName, instrumentName)) { return; } - + CounterMetadata metadata = GetCounterMetadata(meterName, instrumentName, id); if (double.TryParse(rateText, NumberStyles.Number | NumberStyles.Float, CultureInfo.InvariantCulture, out double rate)) { if (absoluteValueText != null && counterConfiguration.UseCounterRateAndValuePayload && double.TryParse(absoluteValueText, NumberStyles.Number | NumberStyles.Float, CultureInfo.InvariantCulture, out double value)) { - payload = new CounterRateAndValuePayload(GetCounterMetadata(meterName, instrumentName), null, unit, tags, rate, value, traceEvent.TimeStamp); + payload = new CounterRateAndValuePayload(metadata, null, unit, tags, rate, value, traceEvent.TimeStamp); } else { - payload = new RatePayload(GetCounterMetadata(meterName, instrumentName), null, unit, tags, rate, counterConfiguration.CounterFilter.DefaultIntervalSeconds, traceEvent.TimeStamp); + payload = new RatePayload(metadata, null, unit, tags, rate, counterConfiguration.CounterFilter.DefaultIntervalSeconds, traceEvent.TimeStamp); } } else @@ -284,7 +347,7 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe // for observable instruments we assume the lack of data is meaningful and remove it from the UI // this happens when the ObservableCounter callback function throws an exception // or when the ObservableCounter doesn't include a measurement for a particular set of tag values. - payload = new CounterEndedPayload(GetCounterMetadata(meterName, instrumentName), traceEvent.TimeStamp); + payload = new CounterEndedPayload(metadata, traceEvent.TimeStamp); } } @@ -306,16 +369,22 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe string tags = (string)traceEvent.PayloadValue(5); //string rateText = (string)traceEvent.PayloadValue(6); // Not currently using rate for UpDownCounters. string valueText = (string)traceEvent.PayloadValue(7); + int? id = null; + if (traceEvent.Version >= 2) + { + id = (int)traceEvent.PayloadValue(8); + } if (!configuration.CounterFilter.IsIncluded(meterName, instrumentName)) { return; } + CounterMetadata metadata = GetCounterMetadata(meterName, instrumentName, id); if (double.TryParse(valueText, NumberStyles.Number | NumberStyles.Float, CultureInfo.InvariantCulture, out double value)) { // UpDownCounter reports the value, not the rate - this is different than how Counter behaves. - payload = new UpDownCounterPayload(GetCounterMetadata(meterName, instrumentName), null, unit, tags, value, traceEvent.TimeStamp); + payload = new UpDownCounterPayload(metadata, null, unit, tags, value, traceEvent.TimeStamp); } else @@ -323,7 +392,7 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe // for observable instruments we assume the lack of data is meaningful and remove it from the UI // this happens when the ObservableUpDownCounter callback function throws an exception // or when the ObservableUpDownCounter doesn't include a measurement for a particular set of tag values. - payload = new CounterEndedPayload(GetCounterMetadata(meterName, instrumentName), traceEvent.TimeStamp); + payload = new CounterEndedPayload(metadata, traceEvent.TimeStamp); } } @@ -344,6 +413,13 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe string unit = (string)obj.PayloadValue(4); string tags = (string)obj.PayloadValue(5); string quantilesText = (string)obj.PayloadValue(6); + //int count - unused arg 7 + //double sum - unused arg 8 + int? id = null; + if (obj.Version >= 2) + { + id = (int)obj.PayloadValue(9); + } if (!configuration.CounterFilter.IsIncluded(meterName, instrumentName)) { @@ -352,8 +428,8 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe //Note quantiles can be empty. IList quantiles = ParseQuantiles(quantilesText); - - payload = new AggregatePercentilePayload(GetCounterMetadata(meterName, instrumentName), null, unit, tags, quantiles, obj.TimeStamp); + CounterMetadata metadata = GetCounterMetadata(meterName, instrumentName, id); + payload = new AggregatePercentilePayload(metadata, null, unit, tags, quantiles, obj.TimeStamp); } private static void HandleHistogramLimitReached(TraceEvent obj, CounterConfiguration configuration, out ICounterPayload payload) diff --git a/src/tests/EventPipeTracee/DuplicateNameMetrics.cs b/src/tests/EventPipeTracee/DuplicateNameMetrics.cs new file mode 100644 index 000000000..189bc194e --- /dev/null +++ b/src/tests/EventPipeTracee/DuplicateNameMetrics.cs @@ -0,0 +1,50 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Diagnostics.Metrics; + + + +namespace EventPipeTracee +{ + // The constructor overloads for Meter and Counter that take tags were added in .NET 8.0 + // so this class is only available when built against 8.0 and later +#if NET8_0_OR_GREATER + internal sealed class DuplicateNameMetrics : IDisposable + { + private Meter _meter1; + private Meter _meter2; + private Counter _counter1a; + private Counter _counter1b; + private Counter _counter2a; + private Counter _counter2b; + + public DuplicateNameMetrics() + { + _meter1 = new Meter("AmbiguousNameMeter", "", [new("MeterTag", "one")]); + _meter2 = new Meter("AmbiguousNameMeter", "", [new("MeterTag", "two")]); + _counter1a = _meter1.CreateCounter("AmbiguousNameCounter", "", "", [new("InstrumentTag", "A")]); + _counter1b = _meter1.CreateCounter("AmbiguousNameCounter", "", "", [new("InstrumentTag", "B")]); + _counter2a = _meter2.CreateCounter("AmbiguousNameCounter", "", "", [new("InstrumentTag", "A")]); + _counter2b = _meter2.CreateCounter("AmbiguousNameCounter", "", "", [new("InstrumentTag", "B")]); + } + + + public void IncrementCounter(int v = 1) + { + _counter1a.Add(v); + _counter1b.Add(v + 1); + _counter2a.Add(v + 2); + _counter2b.Add(v + 3); + } + + public void Dispose() + { + _meter1?.Dispose(); + _meter2?.Dispose(); + } + } +#endif +} diff --git a/src/tests/EventPipeTracee/EventPipeTracee.csproj b/src/tests/EventPipeTracee/EventPipeTracee.csproj index ddd9ff2c2..f02e3fee9 100644 --- a/src/tests/EventPipeTracee/EventPipeTracee.csproj +++ b/src/tests/EventPipeTracee/EventPipeTracee.csproj @@ -3,6 +3,7 @@ Exe $(BuildProjectFramework) $(BuildTargetFrameworks) + NET8_0_OR_GREATER diff --git a/src/tests/EventPipeTracee/Program.cs b/src/tests/EventPipeTracee/Program.cs index 1decd119a..9c61e0db0 100644 --- a/src/tests/EventPipeTracee/Program.cs +++ b/src/tests/EventPipeTracee/Program.cs @@ -32,8 +32,10 @@ namespace EventPipeTracee string loggerCategory = args[1]; bool diagMetrics = args.Any("DiagMetrics".Equals); + bool duplicateNameMetrics = args.Any("DuplicateNameMetrics".Equals); Console.WriteLine($"{pid} EventPipeTracee: DiagMetrics {diagMetrics}"); + Console.WriteLine($"{pid} EventPipeTracee: DuplicateNameMetrics {duplicateNameMetrics}"); Console.WriteLine($"{pid} EventPipeTracee: start process"); Console.Out.Flush(); @@ -60,8 +62,6 @@ namespace EventPipeTracee Console.WriteLine($"{pid} EventPipeTracee: {DateTime.UtcNow} Awaiting start"); Console.Out.Flush(); - using CustomMetrics metrics = diagMetrics ? new CustomMetrics() : null; - // Wait for server to send something int input = pipeStream.ReadByte(); @@ -70,10 +70,14 @@ namespace EventPipeTracee CancellationTokenSource recordMetricsCancellationTokenSource = new(); - if (diagMetrics) + if (diagMetrics || duplicateNameMetrics) { _ = Task.Run(async () => { + using CustomMetrics metrics = diagMetrics ? new CustomMetrics() : null; +#if NET8_0_OR_GREATER + using DuplicateNameMetrics dupMetrics = duplicateNameMetrics ? new DuplicateNameMetrics() : null; +#endif // Recording a single value appeared to cause test flakiness due to a race // condition with the timing of when dotnet-counters starts collecting and // when these values are published. Publishing values repeatedly bypasses this problem. @@ -81,8 +85,11 @@ namespace EventPipeTracee { recordMetricsCancellationTokenSource.Token.ThrowIfCancellationRequested(); - metrics.IncrementCounter(); - metrics.RecordHistogram(10.0f); + metrics?.IncrementCounter(); + metrics?.RecordHistogram(10.0f); +#if NET8_0_OR_GREATER + dupMetrics?.IncrementCounter(); +#endif await Task.Delay(1000).ConfigureAwait(true); } diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventCounterPipelineUnitTests.cs b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventCounterPipelineUnitTests.cs index 355324db2..72852297c 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventCounterPipelineUnitTests.cs +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventCounterPipelineUnitTests.cs @@ -29,27 +29,42 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests _output = output; } + class ExpectedCounter + { + public string ProviderName { get; } + public string CounterName { get; } + public string MeterTags { get; } + public string InstrumentTags { get; } + + public ExpectedCounter(string providerName, string counterName, string meterTags = null, string instrumentTags = null) + { + ProviderName = providerName; + CounterName = counterName; + MeterTags = meterTags; + InstrumentTags = instrumentTags; + } + + public bool MatchesCounterMetadata(CounterMetadata metadata) + { + if (metadata.ProviderName != ProviderName) return false; + if (metadata.CounterName != CounterName) return false; + if (MeterTags != null && metadata.MeterTags != MeterTags) return false; + if (InstrumentTags != null && metadata.InstrumentTags != InstrumentTags) return false; + return true; + } + } + private sealed class TestMetricsLogger : ICountersLogger { - private readonly List _expectedCounters = new(); - private Dictionary _metrics = new(); + private readonly List _expectedCounters = new(); + private Dictionary _metrics = new(); private readonly TaskCompletionSource _foundExpectedCountersSource; - public TestMetricsLogger(IDictionary> expectedCounters, TaskCompletionSource foundExpectedCountersSource) + public TestMetricsLogger(IEnumerable expectedCounters, TaskCompletionSource foundExpectedCountersSource) { _foundExpectedCountersSource = foundExpectedCountersSource; - - if (expectedCounters.Count > 0) - { - foreach (string providerName in expectedCounters.Keys) - { - foreach (string counterName in expectedCounters[providerName]) - { - _expectedCounters.Add(CreateKey(providerName, counterName)); - } - } - } - else + _expectedCounters = new(expectedCounters); + if (_expectedCounters.Count == 0) { foundExpectedCountersSource.SetResult(null); } @@ -59,48 +74,46 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests public void Log(ICounterPayload payload) { - string key = CreateKey(payload); - - _metrics[key] = payload; + bool isValuePayload = payload.EventType switch + { + EventType.Gauge => true, + EventType.UpDownCounter => true, + EventType.Histogram => true, + EventType.Rate => true, + _ => false + }; + if(!isValuePayload) + { + return; + } - // Complete the task source if the last expected key was removed. - if (_expectedCounters.Remove(key) && _expectedCounters.Count == 0) + ExpectedCounter expectedCounter = _expectedCounters.Find(c => c.MatchesCounterMetadata(payload.CounterMetadata)); + if(expectedCounter != null) { - _foundExpectedCountersSource.TrySetResult(null); + _expectedCounters.Remove(expectedCounter); + _metrics.Add(expectedCounter, payload); + // Complete the task source if the last expected key was removed. + if (_expectedCounters.Count == 0) + { + _foundExpectedCountersSource.TrySetResult(null); + } } } public Task PipelineStarted(CancellationToken token) => Task.CompletedTask; public Task PipelineStopped(CancellationToken token) => Task.CompletedTask; - - private static string CreateKey(ICounterPayload payload) - { - return CreateKey(payload.CounterMetadata.ProviderName, payload.CounterMetadata.CounterName); - } - - private static string CreateKey(string providerName, string counterName) - { - return $"{providerName}_{counterName}"; - } } [SkippableTheory, MemberData(nameof(Configurations))] public async Task TestCounterEventPipeline(TestConfiguration config) { - if (config.RuntimeFrameworkVersionMajor > 8) - { - throw new SkipTestException("Not supported on .NET 9.0 and greater"); - } string[] expectedCounters = new[] { "cpu-usage", "working-set" }; string expectedProvider = "System.Runtime"; - IDictionary> expectedMap = new Dictionary>(); - expectedMap.Add(expectedProvider, expectedCounters); - TaskCompletionSource foundExpectedCountersSource = new(TaskCreationOptions.RunContinuationsAsynchronously); - TestMetricsLogger logger = new(expectedMap, foundExpectedCountersSource); + TestMetricsLogger logger = new(expectedCounters.Select(name => new ExpectedCounter(expectedProvider, name)), foundExpectedCountersSource); await using (TestRunner testRunner = await PipelineTestUtilities.StartProcess(config, "CounterRemoteTest", _output)) { @@ -114,7 +127,8 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests new EventPipeCounterGroup { ProviderName = expectedProvider, - CounterNames = expectedCounters + CounterNames = expectedCounters, + Type = CounterGroupType.EventCounter } }, CounterIntervalSeconds = 1 @@ -133,5 +147,53 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests Assert.Equal(expectedCounters, actualMetrics); Assert.True(logger.Metrics.All(m => string.Equals(m.CounterMetadata.ProviderName, expectedProvider))); } + + [SkippableTheory, MemberData(nameof(Configurations))] + public async Task TestDuplicateNameMetrics(TestConfiguration config) + { + if(config.RuntimeFrameworkVersionMajor < 9) + { + throw new SkipTestException("MetricsEventSource only supports instrument IDs starting in .NET 9.0."); + } + string providerName = "AmbiguousNameMeter"; + string counterName = "AmbiguousNameCounter"; + ExpectedCounter[] expectedCounters = + [ + new ExpectedCounter(providerName, counterName, "MeterTag=one","InstrumentTag=A"), + new ExpectedCounter(providerName, counterName, "MeterTag=one","InstrumentTag=B"), + new ExpectedCounter(providerName, counterName, "MeterTag=two","InstrumentTag=A"), + new ExpectedCounter(providerName, counterName, "MeterTag=two","InstrumentTag=B"), + ]; + TaskCompletionSource foundExpectedCountersSource = new(TaskCreationOptions.RunContinuationsAsynchronously); + TestMetricsLogger logger = new(expectedCounters, foundExpectedCountersSource); + + await using (TestRunner testRunner = await PipelineTestUtilities.StartProcess(config, "DuplicateNameMetrics", _output)) + { + DiagnosticsClient client = new(testRunner.Pid); + + await using MetricsPipeline pipeline = new(client, new MetricsPipelineSettings + { + Duration = Timeout.InfiniteTimeSpan, + CounterGroups = new[] + { + new EventPipeCounterGroup + { + ProviderName = providerName, + CounterNames = [counterName] + } + }, + CounterIntervalSeconds = 1, + MaxTimeSeries = 1000 + }, new[] { logger }); + + await PipelineTestUtilities.ExecutePipelineWithTracee( + pipeline, + testRunner, + foundExpectedCountersSource); + } + + // confirm that all four tag combinations published a value + Assert.Equal(4, logger.Metrics.Count()); + } } }