From d4bc0dfb0f93146ea27cef8dd47b677761abd674 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 25 Jun 2020 17:15:34 +0200 Subject: [PATCH 01/11] Add telemetry to System.Net.NameResolution --- .../src/System.Net.NameResolution.csproj | 3 + .../src/System/Net/Dns.cs | 168 +++++++++++--- .../src/System/Net/NameResolutionTelemetry.cs | 210 ++++++++++++++++++ .../Fakes/FakeNameResolutionTelemetry.cs | 23 ++ ...ystem.Net.NameResolution.Unit.Tests.csproj | 3 + 5 files changed, 377 insertions(+), 30 deletions(-) create mode 100644 src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs create mode 100644 src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs diff --git a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj index 498f4e8fce267a..15c3993716f9b7 100644 --- a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj +++ b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj @@ -9,6 +9,7 @@ + @@ -16,6 +17,8 @@ Link="Common\System\Net\InternalException.cs" /> + diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index 5a18dd685aaa4d..dce398dc4618a2 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -2,11 +2,13 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System.Diagnostics; using System.Globalization; using System.Net.Internals; using System.Net.Sockets; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Internal; namespace System.Net { @@ -18,7 +20,21 @@ public static string GetHostName() { NameResolutionPal.EnsureSocketsAreInitialized(); - string name = NameResolutionPal.GetHostName(); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(string.Empty); + + string name; + try + { + name = NameResolutionPal.GetHostName(); + } + catch when (LogFailure(string.Empty, stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + NameResolutionTelemetry.Log.AfterResolution(string.Empty, stopwatch, successful: true); + if (NetEventSource.IsEnabled) NetEventSource.Info(null, name); return name; } @@ -360,22 +376,35 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr { ValidateHostName(hostName); - SocketError errorCode = NameResolutionPal.TryGetAddrInfo(hostName, justAddresses, out string? newHostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(hostName); - if (errorCode != SocketError.Success) + object result; + try { - if (NetEventSource.IsEnabled) NetEventSource.Error(hostName, $"{hostName} DNS lookup failed with {errorCode}"); - throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); - } + SocketError errorCode = NameResolutionPal.TryGetAddrInfo(hostName, justAddresses, out string? newHostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); - object result = justAddresses ? (object) - addresses : - new IPHostEntry + if (errorCode != SocketError.Success) { - AddressList = addresses, - HostName = newHostName!, - Aliases = aliases - }; + if (NetEventSource.IsEnabled) NetEventSource.Error(hostName, $"{hostName} DNS lookup failed with {errorCode}"); + throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + } + + result = justAddresses ? (object) + addresses : + new IPHostEntry + { + AddressList = addresses, + HostName = newHostName!, + Aliases = aliases + }; + } + catch when (LogFailure(hostName, stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + NameResolutionTelemetry.Log.AfterResolution(hostName, stopwatch, successful: true); return result; } @@ -394,21 +423,58 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd // will only return that address and not the full list. // Do a reverse lookup to get the host name. - string? name = NameResolutionPal.TryGetNameInfo(address, out SocketError errorCode, out int nativeErrorCode); - if (errorCode != SocketError.Success) + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(address); + + SocketError errorCode; + string? name; + try + { + name = NameResolutionPal.TryGetNameInfo(address, out errorCode, out int nativeErrorCode); + if (errorCode != SocketError.Success) + { + if (NetEventSource.IsEnabled) NetEventSource.Error(address, $"{address} DNS lookup failed with {errorCode}"); + throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + } + Debug.Assert(name != null); + } + catch when (LogFailure(address, stopwatch)) { - if (NetEventSource.IsEnabled) NetEventSource.Error(address, $"{address} DNS lookup failed with {errorCode}"); - throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + Debug.Fail("LogFailure should return false"); + throw; } + NameResolutionTelemetry.Log.AfterResolution(address, stopwatch, successful: true); + // Do the forward lookup to get the IPs for that host name - errorCode = NameResolutionPal.TryGetAddrInfo(name!, justAddresses, out string? hostName, out string[] aliases, out IPAddress[] addresses, out nativeErrorCode); + stopwatch = NameResolutionTelemetry.Log.ResolutionStart(name); - if (errorCode != SocketError.Success) + object result; + try + { + errorCode = NameResolutionPal.TryGetAddrInfo(name, justAddresses, out string? hostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); + + if (errorCode != SocketError.Success) + { + if (NetEventSource.IsEnabled) NetEventSource.Error(address, $"forward lookup for '{name}' failed with {errorCode}"); + } + + result = justAddresses ? + (object)addresses : + new IPHostEntry + { + HostName = hostName!, + Aliases = aliases, + AddressList = addresses + }; + } + catch when (LogFailure(name, stopwatch)) { - if (NetEventSource.IsEnabled) NetEventSource.Error(address, $"forward lookup for '{name}' failed with {errorCode}"); + Debug.Fail("LogFailure should return false"); + throw; } + NameResolutionTelemetry.Log.AfterResolution(name, stopwatch, successful: true); + // One of three things happened: // 1. Success. // 2. There was a ptr record in dns, but not a corollary A/AAA record. @@ -416,15 +482,7 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd // - Workaround, Check "Use this connection's dns suffix in dns registration" on that network // adapter's advanced dns settings. // Return whatever we got. - - return justAddresses ? - (object)addresses : - new IPHostEntry - { - HostName = hostName!, - Aliases = aliases, - AddressList = addresses - }; + return result; } private static Task GetHostEntryCoreAsync(string hostName, bool justReturnParsedIp, bool throwOnIIPAny) => @@ -466,7 +524,44 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR if (NameResolutionPal.SupportsGetAddrInfoAsync && ipAddress is null) { ValidateHostName(hostName); - return NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); + + if (NameResolutionTelemetry.IsEnabled) + { + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(hostName); + + Task coreTask; + try + { + coreTask = NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); + } + catch when (LogFailure(hostName, stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + coreTask.ContinueWith( + (task, state) => + { + var tuple = (Tuple)state!; + NameResolutionTelemetry.Log.AfterResolution( + hostName: tuple.Item1, + stopwatch: tuple.Item2, + successful: task.IsCompletedSuccessfully); + }, + state: Tuple.Create(hostName, stopwatch), + cancellationToken: default, + TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); + + // coreTask is not actually a base Task, but Task / Task + // We have to return it and not the continuation + return coreTask; + } + else + { + return NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); + } } return justAddresses ? (Task) @@ -496,5 +591,18 @@ private static void ValidateHostName(string hostName) SR.Format(SR.net_toolong, nameof(hostName), MaxHostName.ToString(NumberFormatInfo.CurrentInfo))); } } + + + private static bool LogFailure(string hostName, ValueStopwatch stopwatch) + { + NameResolutionTelemetry.Log.AfterResolution(hostName, stopwatch, successful: false); + return false; + } + + private static bool LogFailure(IPAddress address, ValueStopwatch stopwatch) + { + NameResolutionTelemetry.Log.AfterResolution(address, stopwatch, successful: false); + return false; + } } } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs new file mode 100644 index 00000000000000..0805d1797484a5 --- /dev/null +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -0,0 +1,210 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Runtime.InteropServices; +using System.Threading; +using Microsoft.Extensions.Internal; + +namespace System.Net +{ + [EventSource(Name = "System.Net.NameResolution")] + internal sealed class NameResolutionTelemetry : EventSource + { + public static readonly NameResolutionTelemetry Log = new NameResolutionTelemetry(); + + public static new bool IsEnabled => Log.IsEnabled(); + + private PollingCounter? _lookupsRequestedCounter; + private EventCounter? _lookupsDuration; + + private long _lookupsRequested; + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // The cumulative number of name resolution requests started since the process started. + _lookupsRequestedCounter ??= new PollingCounter("dns-lookups-requested", this, () => Interlocked.Read(ref _lookupsRequested)) + { + DisplayName = "DNS Lookups Requested" + }; + + _lookupsDuration ??= new EventCounter("dns-lookups-duration", this) + { + DisplayName = "Average DNS Lookup Duration", + DisplayUnits = "ms" + }; + } + } + + private const int MaxIPFormattedLength = 128; + + [Event(1, Level = EventLevel.Informational)] + public ValueStopwatch ResolutionStart(string hostName) + { + Debug.Assert(hostName != null); + + if (IsEnabled()) + { + Interlocked.Increment(ref _lookupsRequested); + WriteEvent(eventId: 1, hostName); + return ValueStopwatch.StartNew(); + } + + return default; + } + + [NonEvent] + public ValueStopwatch ResolutionStart(IPAddress address) + { + Debug.Assert(address != null); + + if (IsEnabled()) + { + Interlocked.Increment(ref _lookupsRequested); + WriteEvent(eventId: 1, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); + return ValueStopwatch.StartNew(); + } + + return default; + } + + [NonEvent] + public void AfterResolution(string hostName, ValueStopwatch stopwatch, bool successful) + { + if (stopwatch.IsActive) + { + double duration = stopwatch.GetElapsedTime().TotalMilliseconds; + + _lookupsDuration!.WriteMetric(duration); + + if (successful) + { + ResolutionSuccess(hostName, duration); + } + else + { + ResolutionFailure(hostName, duration); + } + } + } + + [NonEvent] + public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool successful) + { + if (stopwatch.IsActive) + { + double duration = stopwatch.GetElapsedTime().TotalMilliseconds; + + _lookupsDuration!.WriteMetric(duration); + + WriteEvent( + eventId: successful ? 2 : 3, + FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength]), + duration); + } + } + + + [Event(2, Level = EventLevel.Informational)] + private void ResolutionSuccess(string hostName, double duration) => WriteEvent(eventId: 2, hostName, duration); + + [Event(3, Level = EventLevel.Informational)] + private void ResolutionFailure(string hostName, double duration) => WriteEvent(eventId: 3, hostName, duration); + + + [NonEvent] + private static Span FormatIPAddressNullTerminated(IPAddress address, Span destination) + { + Debug.Assert(address != null); + + bool success = address.TryFormat(destination, out int charsWritten); + Debug.Assert(success); + + Debug.Assert(charsWritten < destination.Length); + destination[charsWritten] = '\0'; + + return destination.Slice(0, charsWritten + 1); + } + + + [NonEvent] + private unsafe void WriteEvent(int eventId, Span arg1) + { + Debug.Assert(!arg1.IsEmpty && arg1[^1] == '\0', "Expecting a null-terminated ROS"); + + if (IsEnabled()) + { + fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) + { + EventData descr = new EventData + { + DataPointer = (IntPtr)(arg1Ptr), + Size = arg1.Length * sizeof(char) + }; + + WriteEventCore(eventId, eventDataCount: 1, &descr); + } + } + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, string? arg1, double arg2) + { + if (IsEnabled()) + { + arg1 ??= ""; + + fixed (char* arg1Ptr = arg1) + { + const int NumEventDatas = 2; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData + { + DataPointer = (IntPtr)(arg1Ptr), + Size = (arg1.Length + 1) * sizeof(char) + }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(double) + }; + + WriteEventCore(eventId, NumEventDatas, descrs); + } + } + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, Span arg1, double arg2) + { + Debug.Assert(!arg1.IsEmpty && arg1[^1] == '\0', "Expecting a null-terminated ROS"); + + if (IsEnabled()) + { + fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) + { + const int NumEventDatas = 2; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData + { + DataPointer = (IntPtr)(arg1Ptr), + Size = arg1.Length * sizeof(char) + }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(double) + }; + + WriteEventCore(eventId, NumEventDatas, descrs); + } + } + } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs new file mode 100644 index 00000000000000..34f8de4bb35517 --- /dev/null +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -0,0 +1,23 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.Extensions.Internal; + +namespace System.Net +{ + internal class NameResolutionTelemetry + { + public static NameResolutionTelemetry Log => new NameResolutionTelemetry(); + + public static readonly bool IsEnabled = false; + + public ValueStopwatch ResolutionStart(string hostName) => default; + + public ValueStopwatch ResolutionStart(IPAddress address) => default; + + public void AfterResolution(string hostName, ValueStopwatch stopwatch, bool successful) { } + + public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool successful) { } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj b/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj index fa51396ca607c2..d385507b8a5cd0 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj @@ -27,6 +27,7 @@ + @@ -38,5 +39,7 @@ Link="Common\System\Net\InternalException.cs" /> + \ No newline at end of file From 1d29cedda82e6097337cb19ad8ffebcf2a9a4404 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 25 Jun 2020 21:47:39 +0200 Subject: [PATCH 02/11] Rename hostName to hostNameOrAddress --- .../src/System/Net/Dns.cs | 2 +- .../src/System/Net/NameResolutionTelemetry.cs | 16 ++++++++-------- .../Fakes/FakeNameResolutionTelemetry.cs | 4 ++-- 3 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index dce398dc4618a2..4ca562cfd73a47 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -545,7 +545,7 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR { var tuple = (Tuple)state!; NameResolutionTelemetry.Log.AfterResolution( - hostName: tuple.Item1, + hostNameOrAddress: tuple.Item1, stopwatch: tuple.Item2, successful: task.IsCompletedSuccessfully); }, diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 0805d1797484a5..69732e6976e37b 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -43,14 +43,14 @@ protected override void OnEventCommand(EventCommandEventArgs command) private const int MaxIPFormattedLength = 128; [Event(1, Level = EventLevel.Informational)] - public ValueStopwatch ResolutionStart(string hostName) + public ValueStopwatch ResolutionStart(string hostNameOrAddress) { - Debug.Assert(hostName != null); + Debug.Assert(hostNameOrAddress != null); if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); - WriteEvent(eventId: 1, hostName); + WriteEvent(eventId: 1, hostNameOrAddress); return ValueStopwatch.StartNew(); } @@ -73,7 +73,7 @@ public ValueStopwatch ResolutionStart(IPAddress address) } [NonEvent] - public void AfterResolution(string hostName, ValueStopwatch stopwatch, bool successful) + public void AfterResolution(string hostNameOrAddress, ValueStopwatch stopwatch, bool successful) { if (stopwatch.IsActive) { @@ -83,11 +83,11 @@ public void AfterResolution(string hostName, ValueStopwatch stopwatch, bool succ if (successful) { - ResolutionSuccess(hostName, duration); + ResolutionSuccess(hostNameOrAddress, duration); } else { - ResolutionFailure(hostName, duration); + ResolutionFailure(hostNameOrAddress, duration); } } } @@ -110,10 +110,10 @@ public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool su [Event(2, Level = EventLevel.Informational)] - private void ResolutionSuccess(string hostName, double duration) => WriteEvent(eventId: 2, hostName, duration); + private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(eventId: 2, hostNameOrAddress, duration); [Event(3, Level = EventLevel.Informational)] - private void ResolutionFailure(string hostName, double duration) => WriteEvent(eventId: 3, hostName, duration); + private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(eventId: 3, hostNameOrAddress, duration); [NonEvent] diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs index 34f8de4bb35517..22534105bcc06b 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -12,11 +12,11 @@ internal class NameResolutionTelemetry public static readonly bool IsEnabled = false; - public ValueStopwatch ResolutionStart(string hostName) => default; + public ValueStopwatch ResolutionStart(string hostNameOrAddress) => default; public ValueStopwatch ResolutionStart(IPAddress address) => default; - public void AfterResolution(string hostName, ValueStopwatch stopwatch, bool successful) { } + public void AfterResolution(string hostNameOrAddress, ValueStopwatch stopwatch, bool successful) { } public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool successful) { } } From 0646d45df231364fbe6bb2f004364f77a89284b8 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 25 Jun 2020 21:57:24 +0200 Subject: [PATCH 03/11] Use constants for event IDs --- .../src/System/Net/NameResolutionTelemetry.cs | 20 +++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 69732e6976e37b..0427e1bb67776e 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -17,6 +17,10 @@ internal sealed class NameResolutionTelemetry : EventSource public static new bool IsEnabled => Log.IsEnabled(); + private const int ResolutionStartEventId = 1; + private const int ResolutionSuccessEventId = 2; + private const int ResolutionFailureEventId = 3; + private PollingCounter? _lookupsRequestedCounter; private EventCounter? _lookupsDuration; @@ -42,7 +46,7 @@ protected override void OnEventCommand(EventCommandEventArgs command) private const int MaxIPFormattedLength = 128; - [Event(1, Level = EventLevel.Informational)] + [Event(ResolutionStartEventId, Level = EventLevel.Informational)] public ValueStopwatch ResolutionStart(string hostNameOrAddress) { Debug.Assert(hostNameOrAddress != null); @@ -50,7 +54,7 @@ public ValueStopwatch ResolutionStart(string hostNameOrAddress) if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); - WriteEvent(eventId: 1, hostNameOrAddress); + WriteEvent(ResolutionStartEventId, hostNameOrAddress); return ValueStopwatch.StartNew(); } @@ -65,7 +69,7 @@ public ValueStopwatch ResolutionStart(IPAddress address) if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); - WriteEvent(eventId: 1, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); + WriteEvent(ResolutionStartEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); return ValueStopwatch.StartNew(); } @@ -102,18 +106,18 @@ public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool su _lookupsDuration!.WriteMetric(duration); WriteEvent( - eventId: successful ? 2 : 3, + successful ? ResolutionSuccessEventId : ResolutionFailureEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength]), duration); } } - [Event(2, Level = EventLevel.Informational)] - private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(eventId: 2, hostNameOrAddress, duration); + [Event(ResolutionSuccessEventId, Level = EventLevel.Informational)] + private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(ResolutionSuccessEventId, hostNameOrAddress, duration); - [Event(3, Level = EventLevel.Informational)] - private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(eventId: 3, hostNameOrAddress, duration); + [Event(ResolutionFailureEventId, Level = EventLevel.Informational)] + private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(ResolutionFailureEventId, hostNameOrAddress, duration); [NonEvent] From ae6eb2a6c6c0bbe01ffe6e5e186a361a91c578ca Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 29 Jun 2020 17:26:45 +0200 Subject: [PATCH 04/11] Address PR feedback --- .../src/System/Net/Dns.cs | 10 +-- .../src/System/Net/NameResolutionTelemetry.cs | 71 ++++++++++++------- .../Fakes/FakeNameResolutionTelemetry.cs | 4 +- 3 files changed, 51 insertions(+), 34 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index 4ca562cfd73a47..51ff7d52f09f1e 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -20,7 +20,7 @@ public static string GetHostName() { NameResolutionPal.EnsureSocketsAreInitialized(); - ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(string.Empty); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(string.Empty); string name; try @@ -376,7 +376,7 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr { ValidateHostName(hostName); - ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(hostName); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); object result; try @@ -423,7 +423,7 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd // will only return that address and not the full list. // Do a reverse lookup to get the host name. - ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(address); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(address); SocketError errorCode; string? name; @@ -446,7 +446,7 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd NameResolutionTelemetry.Log.AfterResolution(address, stopwatch, successful: true); // Do the forward lookup to get the IPs for that host name - stopwatch = NameResolutionTelemetry.Log.ResolutionStart(name); + stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); object result; try @@ -527,7 +527,7 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR if (NameResolutionTelemetry.IsEnabled) { - ValueStopwatch stopwatch = NameResolutionTelemetry.Log.ResolutionStart(hostName); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); Task coreTask; try diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 0427e1bb67776e..69402f545ca600 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -17,7 +17,7 @@ internal sealed class NameResolutionTelemetry : EventSource public static new bool IsEnabled => Log.IsEnabled(); - private const int ResolutionStartEventId = 1; + private const int ResolutionStartingEventId = 1; private const int ResolutionSuccessEventId = 2; private const int ResolutionFailureEventId = 3; @@ -30,7 +30,7 @@ protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) { - // The cumulative number of name resolution requests started since the process started. + // The cumulative number of name resolution requests started since events were enabled _lookupsRequestedCounter ??= new PollingCounter("dns-lookups-requested", this, () => Interlocked.Read(ref _lookupsRequested)) { DisplayName = "DNS Lookups Requested" @@ -44,33 +44,54 @@ protected override void OnEventCommand(EventCommandEventArgs command) } } + private const int MaxIPFormattedLength = 128; - [Event(ResolutionStartEventId, Level = EventLevel.Informational)] - public ValueStopwatch ResolutionStart(string hostNameOrAddress) + // Methods below assume that ResolutionSuccess and ResolutionFailure have the same signature + + [Event(ResolutionStartingEventId, Level = EventLevel.Informational)] + private void ResolutionStarting(string hostNameOrAddress) => WriteEvent(ResolutionStartingEventId, hostNameOrAddress); + + [Event(ResolutionSuccessEventId, Level = EventLevel.Informational)] + private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(ResolutionSuccessEventId, hostNameOrAddress, duration); + + [Event(ResolutionFailureEventId, Level = EventLevel.Informational)] + private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(ResolutionFailureEventId, hostNameOrAddress, duration); + + + [NonEvent] + public ValueStopwatch BeforeResolution(string hostNameOrAddress) { Debug.Assert(hostNameOrAddress != null); if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); - WriteEvent(ResolutionStartEventId, hostNameOrAddress); - return ValueStopwatch.StartNew(); + + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) + { + ResolutionStarting(hostNameOrAddress); + return ValueStopwatch.StartNew(); + } } return default; } [NonEvent] - public ValueStopwatch ResolutionStart(IPAddress address) + public ValueStopwatch BeforeResolution(IPAddress address) { Debug.Assert(address != null); if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); - WriteEvent(ResolutionStartEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); - return ValueStopwatch.StartNew(); + + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) + { + WriteEvent(ResolutionStartingEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); + return ValueStopwatch.StartNew(); + } } return default; @@ -113,13 +134,6 @@ public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool su } - [Event(ResolutionSuccessEventId, Level = EventLevel.Informational)] - private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(ResolutionSuccessEventId, hostNameOrAddress, duration); - - [Event(ResolutionFailureEventId, Level = EventLevel.Informational)] - private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(ResolutionFailureEventId, hostNameOrAddress, duration); - - [NonEvent] private static Span FormatIPAddressNullTerminated(IPAddress address, Span destination) { @@ -135,10 +149,13 @@ private static Span FormatIPAddressNullTerminated(IPAddress address, Span< } + // WriteEvent overloads taking Span are imitating string arguments + // Span arguments are expected to be null-terminated + [NonEvent] private unsafe void WriteEvent(int eventId, Span arg1) { - Debug.Assert(!arg1.IsEmpty && arg1[^1] == '\0', "Expecting a null-terminated ROS"); + Debug.Assert(!arg1.IsEmpty && arg1.IndexOf('\0') == arg1.Length - 1, "Expecting a null-terminated ROS"); if (IsEnabled()) { @@ -156,13 +173,13 @@ private unsafe void WriteEvent(int eventId, Span arg1) } [NonEvent] - private unsafe void WriteEvent(int eventId, string? arg1, double arg2) + private unsafe void WriteEvent(int eventId, Span arg1, double arg2) { + Debug.Assert(!arg1.IsEmpty && arg1.IndexOf('\0') == arg1.Length - 1, "Expecting a null-terminated ROS"); + if (IsEnabled()) { - arg1 ??= ""; - - fixed (char* arg1Ptr = arg1) + fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) { const int NumEventDatas = 2; EventData* descrs = stackalloc EventData[NumEventDatas]; @@ -170,7 +187,7 @@ private unsafe void WriteEvent(int eventId, string? arg1, double arg2) descrs[0] = new EventData { DataPointer = (IntPtr)(arg1Ptr), - Size = (arg1.Length + 1) * sizeof(char) + Size = arg1.Length * sizeof(char) }; descrs[1] = new EventData { @@ -184,13 +201,13 @@ private unsafe void WriteEvent(int eventId, string? arg1, double arg2) } [NonEvent] - private unsafe void WriteEvent(int eventId, Span arg1, double arg2) + private unsafe void WriteEvent(int eventId, string? arg1, double arg2) { - Debug.Assert(!arg1.IsEmpty && arg1[^1] == '\0', "Expecting a null-terminated ROS"); - if (IsEnabled()) { - fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) + arg1 ??= ""; + + fixed (char* arg1Ptr = arg1) { const int NumEventDatas = 2; EventData* descrs = stackalloc EventData[NumEventDatas]; @@ -198,7 +215,7 @@ private unsafe void WriteEvent(int eventId, Span arg1, double arg2) descrs[0] = new EventData { DataPointer = (IntPtr)(arg1Ptr), - Size = arg1.Length * sizeof(char) + Size = (arg1.Length + 1) * sizeof(char) }; descrs[1] = new EventData { diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs index 22534105bcc06b..d645949b238744 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -12,9 +12,9 @@ internal class NameResolutionTelemetry public static readonly bool IsEnabled = false; - public ValueStopwatch ResolutionStart(string hostNameOrAddress) => default; + public ValueStopwatch BeforeResolution(string hostNameOrAddress) => default; - public ValueStopwatch ResolutionStart(IPAddress address) => default; + public ValueStopwatch BeforeResolution(IPAddress address) => default; public void AfterResolution(string hostNameOrAddress, ValueStopwatch stopwatch, bool successful) { } From 1f5dcff3d71d9237835eac2bd6c16141447eb493 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 29 Jun 2020 17:35:59 +0200 Subject: [PATCH 05/11] Reduce overhead when only the counter is needed --- .../src/System/Net/Dns.cs | 30 +++++++++++-------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index 51ff7d52f09f1e..d47b163227ff33 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -540,19 +540,23 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR throw; } - coreTask.ContinueWith( - (task, state) => - { - var tuple = (Tuple)state!; - NameResolutionTelemetry.Log.AfterResolution( - hostNameOrAddress: tuple.Item1, - stopwatch: tuple.Item2, - successful: task.IsCompletedSuccessfully); - }, - state: Tuple.Create(hostName, stopwatch), - cancellationToken: default, - TaskContinuationOptions.ExecuteSynchronously, - TaskScheduler.Default); + // Only pay for the overhead if events will be fired + if (stopwatch.IsActive) + { + coreTask.ContinueWith( + (task, state) => + { + var tuple = (Tuple)state!; + NameResolutionTelemetry.Log.AfterResolution( + hostNameOrAddress: tuple.Item1, + stopwatch: tuple.Item2, + successful: task.IsCompletedSuccessfully); + }, + state: Tuple.Create(hostName, stopwatch), + cancellationToken: default, + TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); + } // coreTask is not actually a base Task, but Task / Task // We have to return it and not the continuation From e70461c27ee88d29853b9a59e799c43fbb87d6b3 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 2 Jul 2020 16:01:00 +0200 Subject: [PATCH 06/11] Make NameResolution Telemetry an activity --- .../src/System/Net/Dns.cs | 34 ++--- .../src/System/Net/NameResolutionTelemetry.cs | 121 ++++-------------- .../Fakes/FakeNameResolutionTelemetry.cs | 4 +- 3 files changed, 38 insertions(+), 121 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index d47b163227ff33..a60c70f13b0652 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -27,13 +27,13 @@ public static string GetHostName() { name = NameResolutionPal.GetHostName(); } - catch when (LogFailure(string.Empty, stopwatch)) + catch when (LogFailure(stopwatch)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(string.Empty, stopwatch, successful: true); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); if (NetEventSource.IsEnabled) NetEventSource.Info(null, name); return name; @@ -398,13 +398,13 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr Aliases = aliases }; } - catch when (LogFailure(hostName, stopwatch)) + catch when (LogFailure(stopwatch)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(hostName, stopwatch, successful: true); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); return result; } @@ -437,13 +437,13 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd } Debug.Assert(name != null); } - catch when (LogFailure(address, stopwatch)) + catch when (LogFailure(stopwatch)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(address, stopwatch, successful: true); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); // Do the forward lookup to get the IPs for that host name stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); @@ -467,13 +467,13 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd AddressList = addresses }; } - catch when (LogFailure(name, stopwatch)) + catch when (LogFailure(stopwatch)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(name, stopwatch, successful: true); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); // One of three things happened: // 1. Success. @@ -534,7 +534,7 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR { coreTask = NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); } - catch when (LogFailure(hostName, stopwatch)) + catch when (LogFailure(stopwatch)) { Debug.Fail("LogFailure should return false"); throw; @@ -546,13 +546,11 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR coreTask.ContinueWith( (task, state) => { - var tuple = (Tuple)state!; NameResolutionTelemetry.Log.AfterResolution( - hostNameOrAddress: tuple.Item1, - stopwatch: tuple.Item2, + stopwatch: (ValueStopwatch)state!, successful: task.IsCompletedSuccessfully); }, - state: Tuple.Create(hostName, stopwatch), + state: stopwatch, cancellationToken: default, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); @@ -597,15 +595,9 @@ private static void ValidateHostName(string hostName) } - private static bool LogFailure(string hostName, ValueStopwatch stopwatch) + private static bool LogFailure(ValueStopwatch stopwatch) { - NameResolutionTelemetry.Log.AfterResolution(hostName, stopwatch, successful: false); - return false; - } - - private static bool LogFailure(IPAddress address, ValueStopwatch stopwatch) - { - NameResolutionTelemetry.Log.AfterResolution(address, stopwatch, successful: false); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: false); return false; } } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 69402f545ca600..80148506b0d6d6 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -17,9 +17,9 @@ internal sealed class NameResolutionTelemetry : EventSource public static new bool IsEnabled => Log.IsEnabled(); - private const int ResolutionStartingEventId = 1; - private const int ResolutionSuccessEventId = 2; - private const int ResolutionFailureEventId = 3; + private const int ResolutionStartEventId = 1; + private const int ResolutionStopEventId = 2; + private const int ResolutionFailedEventId = 3; private PollingCounter? _lookupsRequestedCounter; private EventCounter? _lookupsDuration; @@ -47,16 +47,14 @@ protected override void OnEventCommand(EventCommandEventArgs command) private const int MaxIPFormattedLength = 128; - // Methods below assume that ResolutionSuccess and ResolutionFailure have the same signature + [Event(ResolutionStartEventId, Level = EventLevel.Informational)] + private void ResolutionStart(string hostNameOrAddress) => WriteEvent(ResolutionStartEventId, hostNameOrAddress); - [Event(ResolutionStartingEventId, Level = EventLevel.Informational)] - private void ResolutionStarting(string hostNameOrAddress) => WriteEvent(ResolutionStartingEventId, hostNameOrAddress); + [Event(ResolutionStopEventId, Level = EventLevel.Informational)] + private void ResolutionStop() => WriteEvent(ResolutionStopEventId); - [Event(ResolutionSuccessEventId, Level = EventLevel.Informational)] - private void ResolutionSuccess(string hostNameOrAddress, double duration) => WriteEvent(ResolutionSuccessEventId, hostNameOrAddress, duration); - - [Event(ResolutionFailureEventId, Level = EventLevel.Informational)] - private void ResolutionFailure(string hostNameOrAddress, double duration) => WriteEvent(ResolutionFailureEventId, hostNameOrAddress, duration); + [Event(ResolutionFailedEventId, Level = EventLevel.Informational)] + private void ResolutionFailed() => WriteEvent(ResolutionFailedEventId); [NonEvent] @@ -70,9 +68,10 @@ public ValueStopwatch BeforeResolution(string hostNameOrAddress) if (IsEnabled(EventLevel.Informational, EventKeywords.None)) { - ResolutionStarting(hostNameOrAddress); - return ValueStopwatch.StartNew(); + ResolutionStart(hostNameOrAddress); } + + return ValueStopwatch.StartNew(); } return default; @@ -89,47 +88,31 @@ public ValueStopwatch BeforeResolution(IPAddress address) if (IsEnabled(EventLevel.Informational, EventKeywords.None)) { - WriteEvent(ResolutionStartingEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); - return ValueStopwatch.StartNew(); + WriteEvent(ResolutionStartEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); } + + return ValueStopwatch.StartNew(); } return default; } [NonEvent] - public void AfterResolution(string hostNameOrAddress, ValueStopwatch stopwatch, bool successful) + public void AfterResolution(ValueStopwatch stopwatch, bool successful) { if (stopwatch.IsActive) { - double duration = stopwatch.GetElapsedTime().TotalMilliseconds; - - _lookupsDuration!.WriteMetric(duration); + _lookupsDuration!.WriteMetric(stopwatch.GetElapsedTime().TotalMilliseconds); - if (successful) - { - ResolutionSuccess(hostNameOrAddress, duration); - } - else + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) { - ResolutionFailure(hostNameOrAddress, duration); - } - } - } - - [NonEvent] - public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool successful) - { - if (stopwatch.IsActive) - { - double duration = stopwatch.GetElapsedTime().TotalMilliseconds; - - _lookupsDuration!.WriteMetric(duration); + if (!successful) + { + ResolutionFailed(); + } - WriteEvent( - successful ? ResolutionSuccessEventId : ResolutionFailureEventId, - FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength]), - duration); + ResolutionStop(); + } } } @@ -171,61 +154,5 @@ private unsafe void WriteEvent(int eventId, Span arg1) } } } - - [NonEvent] - private unsafe void WriteEvent(int eventId, Span arg1, double arg2) - { - Debug.Assert(!arg1.IsEmpty && arg1.IndexOf('\0') == arg1.Length - 1, "Expecting a null-terminated ROS"); - - if (IsEnabled()) - { - fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) - { - const int NumEventDatas = 2; - EventData* descrs = stackalloc EventData[NumEventDatas]; - - descrs[0] = new EventData - { - DataPointer = (IntPtr)(arg1Ptr), - Size = arg1.Length * sizeof(char) - }; - descrs[1] = new EventData - { - DataPointer = (IntPtr)(&arg2), - Size = sizeof(double) - }; - - WriteEventCore(eventId, NumEventDatas, descrs); - } - } - } - - [NonEvent] - private unsafe void WriteEvent(int eventId, string? arg1, double arg2) - { - if (IsEnabled()) - { - arg1 ??= ""; - - fixed (char* arg1Ptr = arg1) - { - const int NumEventDatas = 2; - EventData* descrs = stackalloc EventData[NumEventDatas]; - - descrs[0] = new EventData - { - DataPointer = (IntPtr)(arg1Ptr), - Size = (arg1.Length + 1) * sizeof(char) - }; - descrs[1] = new EventData - { - DataPointer = (IntPtr)(&arg2), - Size = sizeof(double) - }; - - WriteEventCore(eventId, NumEventDatas, descrs); - } - } - } } } diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs index d645949b238744..91d51be7015b1f 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -16,8 +16,6 @@ internal class NameResolutionTelemetry public ValueStopwatch BeforeResolution(IPAddress address) => default; - public void AfterResolution(string hostNameOrAddress, ValueStopwatch stopwatch, bool successful) { } - - public void AfterResolution(IPAddress address, ValueStopwatch stopwatch, bool successful) { } + public void AfterResolution(ValueStopwatch stopwatch, bool successful) { } } } From ed0d6935dcb09e846eadc576f65e3408eef0921f Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Sat, 4 Jul 2020 17:42:47 +0200 Subject: [PATCH 07/11] Remove redundant check --- .../src/System/Net/Dns.cs | 26 ++++++++----------- 1 file changed, 11 insertions(+), 15 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index a60c70f13b0652..5a9f4e1e195fde 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -540,21 +540,17 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR throw; } - // Only pay for the overhead if events will be fired - if (stopwatch.IsActive) - { - coreTask.ContinueWith( - (task, state) => - { - NameResolutionTelemetry.Log.AfterResolution( - stopwatch: (ValueStopwatch)state!, - successful: task.IsCompletedSuccessfully); - }, - state: stopwatch, - cancellationToken: default, - TaskContinuationOptions.ExecuteSynchronously, - TaskScheduler.Default); - } + coreTask.ContinueWith( + (task, state) => + { + NameResolutionTelemetry.Log.AfterResolution( + stopwatch: (ValueStopwatch)state!, + successful: task.IsCompletedSuccessfully); + }, + state: stopwatch, + cancellationToken: default, + TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); // coreTask is not actually a base Task, but Task / Task // We have to return it and not the continuation From e2a563a94b0edad199f56657a9172b0606b2d1cd Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Sat, 4 Jul 2020 17:51:02 +0200 Subject: [PATCH 08/11] Fix indentation --- .../src/System.Net.NameResolution.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj index 15c3993716f9b7..4f302b04c10949 100644 --- a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj +++ b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj @@ -18,7 +18,7 @@ + Link="Common\Extensions\ValueStopwatch\ValueStopwatch.cs" /> From baa86857c11a2cf604a15b84dcd35721ff0d4db5 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 13 Jul 2020 16:23:53 +0200 Subject: [PATCH 09/11] Check IsEnabled before AfterResolution to help linker --- .../src/System/Net/Dns.cs | 18 ++++++++++++------ .../src/System/Net/NameResolutionTelemetry.cs | 2 -- .../Fakes/FakeNameResolutionTelemetry.cs | 2 +- 3 files changed, 13 insertions(+), 9 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index c02f75a2384696..6fdee369e79ad7 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -32,7 +32,8 @@ public static string GetHostName() throw; } - NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(null, name); return name; @@ -337,7 +338,8 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr throw; } - NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); return result; } @@ -376,7 +378,8 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd throw; } - NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); // Do the forward lookup to get the IPs for that host name stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); @@ -406,7 +409,8 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd throw; } - NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); // One of three things happened: // 1. Success. @@ -458,7 +462,7 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR { ValidateHostName(hostName); - if (NameResolutionTelemetry.IsEnabled) + if (NameResolutionTelemetry.Log.IsEnabled()) { ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); @@ -526,7 +530,9 @@ private static void ValidateHostName(string hostName) private static bool LogFailure(ValueStopwatch stopwatch) { - NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: false); + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: false); + return false; } } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 80148506b0d6d6..c216dcbf96db52 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -15,8 +15,6 @@ internal sealed class NameResolutionTelemetry : EventSource { public static readonly NameResolutionTelemetry Log = new NameResolutionTelemetry(); - public static new bool IsEnabled => Log.IsEnabled(); - private const int ResolutionStartEventId = 1; private const int ResolutionStopEventId = 2; private const int ResolutionFailedEventId = 3; diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs index 91d51be7015b1f..cd409cbc602d34 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -10,7 +10,7 @@ internal class NameResolutionTelemetry { public static NameResolutionTelemetry Log => new NameResolutionTelemetry(); - public static readonly bool IsEnabled = false; + public bool IsEnabled() => false; public ValueStopwatch BeforeResolution(string hostNameOrAddress) => default; From 77361924bed3225c6366af447ec3cf9195971ee3 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 14 Jul 2020 17:45:06 +0200 Subject: [PATCH 10/11] Add Telemetry tests --- .../src/System/Net/Dns.cs | 6 +- ...Net.NameResolution.Functional.Tests.csproj | 2 + .../tests/FunctionalTests/TelemetryTest.cs | 145 ++++++++++++++++++ 3 files changed, 151 insertions(+), 2 deletions(-) create mode 100644 src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index 6fdee369e79ad7..98cb7ccbc0b559 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -379,10 +379,12 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd } if (NameResolutionTelemetry.Log.IsEnabled()) + { NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); - // Do the forward lookup to get the IPs for that host name - stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); + // Do the forward lookup to get the IPs for that host name + stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); + } object result; try diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj index 047766b57b8788..dd84b09c72b138 100644 --- a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj @@ -1,6 +1,7 @@ $(NetCoreAppCurrent)-Windows_NT;$(NetCoreAppCurrent)-Unix;$(NetCoreAppCurrent)-Browser + true @@ -10,6 +11,7 @@ + + { + const string ValidHostName = "microsoft.com"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + await Dns.GetHostEntryAsync(ValidHostName); + await Dns.GetHostAddressesAsync(ValidHostName); + + Dns.GetHostEntry(ValidHostName); + Dns.GetHostAddresses(ValidHostName); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ValidHostName, null, null)); + Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(ValidHostName, null, null)); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + Assert.True(events.Count >= 2 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(6, starts.Length); + Assert.All(starts, s => Assert.Equal(ValidHostName, Assert.Single(s.Payload).ToString())); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(6, stops.Length); + + Assert.DoesNotContain(events, e => e.EventName == "ResolutionFailed"); + }).Dispose(); + } + + [OuterLoop] + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public static void EventSource_ResolveInvalidHostName_LogsStartFailureStop() + { + RemoteExecutor.Invoke(async () => + { + const string InvalidHostName = "invalid...example.com"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + await Assert.ThrowsAsync(async () => await Dns.GetHostEntryAsync(InvalidHostName)); + await Assert.ThrowsAsync(async () => await Dns.GetHostAddressesAsync(InvalidHostName)); + + Assert.Throws(() => Dns.GetHostEntry(InvalidHostName)); + Assert.Throws(() => Dns.GetHostAddresses(InvalidHostName)); + + Assert.Throws(() => Dns.EndGetHostEntry(Dns.BeginGetHostEntry(InvalidHostName, null, null))); + Assert.Throws(() => Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(InvalidHostName, null, null))); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + Assert.True(events.Count >= 3 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(6, starts.Length); + Assert.All(starts, s => Assert.Equal(InvalidHostName, Assert.Single(s.Payload).ToString())); + + EventWrittenEventArgs[] failures = events.Where(e => e.EventName == "ResolutionFailed").ToArray(); + Assert.Equal(6, failures.Length); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(6, stops.Length); + }).Dispose(); + } + + [OuterLoop] + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public static void EventSource_GetHostEntryForIP_LogsStartStop() + { + RemoteExecutor.Invoke(async () => + { + const string ValidIPAddress = "8.8.4.4"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + IPAddress ipAddress = IPAddress.Parse(ValidIPAddress); + + await Dns.GetHostEntryAsync(ValidIPAddress); + await Dns.GetHostEntryAsync(ipAddress); + + Dns.GetHostEntry(ValidIPAddress); + Dns.GetHostEntry(ipAddress); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ValidIPAddress, null, null)); + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ipAddress, null, null)); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + // Each GetHostEntry over an IP will yield 2 resolutions + Assert.True(events.Count >= 2 * 2 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(12, starts.Length); + Assert.Equal(6, starts.Count(s => Assert.Single(s.Payload).ToString() == ValidIPAddress)); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(12, stops.Length); + + Assert.DoesNotContain(events, e => e.EventName == "ResolutionFailed"); + }).Dispose(); + } + } +} From 3ecd713608954afb35ca63c56e6719dafbb225f7 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 14 Jul 2020 20:43:34 +0200 Subject: [PATCH 11/11] Throws => ThrowsAny --- .../tests/FunctionalTests/TelemetryTest.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs index d2259f9d98deaa..739ae3c39e064f 100644 --- a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs @@ -75,14 +75,14 @@ public static void EventSource_ResolveInvalidHostName_LogsStartFailureStop() var events = new ConcurrentQueue(); await listener.RunWithCallbackAsync(events.Enqueue, async () => { - await Assert.ThrowsAsync(async () => await Dns.GetHostEntryAsync(InvalidHostName)); - await Assert.ThrowsAsync(async () => await Dns.GetHostAddressesAsync(InvalidHostName)); + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostEntryAsync(InvalidHostName)); + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostAddressesAsync(InvalidHostName)); - Assert.Throws(() => Dns.GetHostEntry(InvalidHostName)); - Assert.Throws(() => Dns.GetHostAddresses(InvalidHostName)); + Assert.ThrowsAny(() => Dns.GetHostEntry(InvalidHostName)); + Assert.ThrowsAny(() => Dns.GetHostAddresses(InvalidHostName)); - Assert.Throws(() => Dns.EndGetHostEntry(Dns.BeginGetHostEntry(InvalidHostName, null, null))); - Assert.Throws(() => Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(InvalidHostName, null, null))); + Assert.ThrowsAny(() => Dns.EndGetHostEntry(Dns.BeginGetHostEntry(InvalidHostName, null, null))); + Assert.ThrowsAny(() => Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(InvalidHostName, null, null))); }); Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself