Socket's connect operations tracing #38620

alnikola · 2020-06-30T14:42:11Z

Socket's connect start, stop and cancelled events are logged as activities via EventSource.

Contributes to #37428

ghost · 2020-06-30T14:42:16Z

Tagging subscribers to this area: @dotnet/ncl
Notify danmosemsft if you want to be subscribed.

alnikola · 2020-06-30T14:55:41Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-06-30T14:55:54Z

Azure Pipelines successfully started running 1 pipeline(s).

src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

stephentoub · 2020-06-30T15:31:38Z

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

+namespace System.Net.Sockets
+{
+    [EventSource(Name = "System.Net.Sockets")]
+    internal sealed class SocketsTelemetry : EventSource


We now have two EventSources in this library. Is that really what we want? I'm not clear on why the decision was made to add a new one. I really don't want to be in a position of having to carry both forward indefinitely.
cc: @noahfalk, @brianrob, @davidsh

Generally, you have one EventSource per area of functionality. There's no hard and fast rule, but unless there's a reason to have multiple EventSources I'd recommend just having one. It also makes it easier to consume the events.

@alnikola, this doesn't need to block your PR, but I do want us to resolve this for .NET 5. Can you please make sure there's an issue for it?

Issue already exists, but it's outside .NET 5.0 scope.

That is related but different. These PRs are actively doubling the number of event sources used. How is a customer supposed to reason about that: they want socket events, but they need to enable two different providers depending on the events they want? There's no good reason for it. If we're doing a new one because we don't like the old one, we should remove the old one. If we're fine with the old one, we shouldn't introduce the new class. Adding new types like this adds overhead, adds confusion, and adds legacy code to be maintained.

(and if we really want to use that same issue, the description and the milestone should be updated)

I created a dedicated issue #38754 for this, but it needs to be triaged to see if it can fit in .NET 5.0 scope.

I added some thoughts to #38754 and may have more once I get a chance to look into this more

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs

scalablecory

We have an established pattern for logging elsewhere of checking Enabled before calling the logging method, rather than checking it inside the method.

I prefer this new pattern's readability, but it looks like in some cases it will add some extra overhead when tracing is disabled. These are logged on a relatively expensive connect operation so overhead here will get swallowed, but still pointing out in case we use this pattern in less expensive areas.

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

- ConnectFailed always calls ConnectStop - Redundant Write method removed

alnikola · 2020-07-01T12:11:09Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-07-01T12:11:23Z

Azure Pipelines successfully started running 1 pipeline(s).

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

alnikola · 2020-07-03T11:06:33Z

FYI. There is a typo in the last commit name. It's intended to be ConnectStopInternal.

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs

- ConnectCanceled logs Stop

…dler

noahfalk

I made a few suggestions inline but the high order bit is probably to resolve whether a new EventSource should exist at all in #38754.

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

…s://github.com/alnikola/runtime into alnikola/827-log-timings-in-socketshttphandler

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs

noahfalk · 2020-07-14T10:09:19Z

I prefer this new pattern's readability, but it looks like in some cases it will add some extra overhead when tracing is disabled

Assuming the if check is at the top of the EventSource method and you do no argument transformation beforehand the overhead should be call-setup/return. This varies based on arguments and machine, but I usually consider it in the 1ns order of magnitude. If performance on that scale matters for a given scenario then certainly we should benchmark and go from there.

noahfalk · 2020-07-14T10:16:27Z

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs

@@ -2071,6 +2072,8 @@ private bool CanUseConnectEx(EndPoint remoteEP)

        internal IAsyncResult UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback? callback, object? state, bool flowContext = false)
        {
+            if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStart(remoteEP);


Style-wise I've always found it preferable to eliminate these IsEnabled() calls entirely and rely on the checks that occur inside the EventSource, but I think the mono-linker will fully remove this pattern so its purely style and tiny perf at this point. Style is best decided by the folks who have to work on the code rather than me : )

- Functional tests

…led are logged via public non-event methods

alnikola · 2020-07-14T12:23:58Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-07-14T12:24:11Z

Azure Pipelines successfully started running 1 pipeline(s).

ManickaP

LGTM

SocketsTelemetry logs Connect operations

870f476

alnikola added the area-System.Net.Sockets label Jun 30, 2020

alnikola added this to the 5.0.0 milestone Jun 30, 2020

alnikola requested a review from a team June 30, 2020 14:42

ManickaP reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj Outdated Show resolved Hide resolved

stephentoub reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs Outdated Show resolved Hide resolved

stephentoub reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Outdated Show resolved Hide resolved

stephentoub reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Outdated Show resolved Hide resolved

stephentoub reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs Outdated Show resolved Hide resolved

stephentoub reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs Outdated Show resolved Hide resolved

scalablecory reviewed Jun 30, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Outdated Show resolved Hide resolved

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Outdated Show resolved Hide resolved

alnikola added 3 commits June 30, 2020 18:03

IsEnabled is called for the specific EventLevel

aec1bc4

.csproj formatting reverted

b4b42fe

- IsEnabled is checked before invoking a telemetry method

7002376

- ConnectFailed always calls ConnectStop - Redundant Write method removed

jaredpar mentioned this pull request Jul 1, 2020

OSX machines are de-provisioned during CI / PR runs leading to failures #34472

Closed

brianrob reviewed Jul 2, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Show resolved Hide resolved

ConnectStartInternal

c693fe7

stephentoub reviewed Jul 3, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Show resolved Hide resolved

stephentoub reviewed Jul 3, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Outdated Show resolved Hide resolved

stephentoub reviewed Jul 3, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs Outdated Show resolved Hide resolved

- Cancelled to Canceled

a6d7e3d

- ConnectCanceled logs Stop

alnikola mentioned this pull request Jul 3, 2020

Merge new Telemetry logging with existing NetEventSources #38754

Open

Merge branch 'master' into alnikola/827-log-timings-in-socketshttphan…

f16a84d

…dler

Merge branch 'master' into alnikola/827-log-timings-in-socketshttphan…

4e89fed

…dler

noahfalk reviewed Jul 13, 2020

View reviewed changes

alnikola added 4 commits July 13, 2020 13:48

Log.IsEnabled check made more limker trimming-friendly

245458e

Merge branch 'alnikola/827-log-timings-in-socketshttphandler' of http…

d64ba15

…s://github.com/alnikola/runtime into alnikola/827-log-timings-in-socketshttphandler

Remaining SocketsTelemetry.IsEnabled calls fixed

abd9c9d

ConnectFailure's details are logged

ecce3af

stephentoub reviewed Jul 13, 2020

View reviewed changes

src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs Show resolved Hide resolved

ManickaP reviewed Jul 13, 2020

View reviewed changes

noahfalk reviewed Jul 14, 2020

View reviewed changes

alnikola added 2 commits July 14, 2020 13:14

- ConnectStart for sync flow is added

6c305f2

- Functional tests

ConnectStop and ConnectFailed as well as ConnectStop and ConnectCance…

33707e2

…led are logged via public non-event methods

ManickaP approved these changes Jul 14, 2020

View reviewed changes

alnikola merged commit a84538d into dotnet:master Jul 14, 2020

alnikola deleted the alnikola/827-log-timings-in-socketshttphandler branch July 14, 2020 14:18

ManickaP mentioned this pull request Aug 13, 2020

Renamed EventSources "Microsoft-"->"Private.InternalDiagnostics.". #40781

Merged

MihaZupan mentioned this pull request Sep 24, 2020

Fix System.Net.Sockets telemetry #42188

Merged

ghost locked as resolved and limited conversation to collaborators Dec 8, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Socket's connect operations tracing #38620

Socket's connect operations tracing #38620

alnikola commented Jun 30, 2020

ghost commented Jun 30, 2020

alnikola commented Jun 30, 2020

azure-pipelines bot commented Jun 30, 2020

stephentoub Jun 30, 2020

brianrob Jul 2, 2020

stephentoub Jul 3, 2020

alnikola Jul 3, 2020

stephentoub Jul 3, 2020 •

edited

Loading

stephentoub Jul 3, 2020

alnikola Jul 3, 2020

stephentoub Jul 3, 2020

noahfalk Jul 13, 2020

scalablecory left a comment

alnikola commented Jul 1, 2020

azure-pipelines bot commented Jul 1, 2020

alnikola commented Jul 3, 2020

noahfalk left a comment

noahfalk commented Jul 14, 2020

noahfalk Jul 14, 2020

alnikola commented Jul 14, 2020

azure-pipelines bot commented Jul 14, 2020

ManickaP left a comment

Socket's connect operations tracing #38620

Socket's connect operations tracing #38620

Conversation

alnikola commented Jun 30, 2020

ghost commented Jun 30, 2020

alnikola commented Jun 30, 2020

azure-pipelines bot commented Jun 30, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

stephentoub Jul 3, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

scalablecory left a comment

Choose a reason for hiding this comment

alnikola commented Jul 1, 2020

azure-pipelines bot commented Jul 1, 2020

alnikola commented Jul 3, 2020

noahfalk left a comment

Choose a reason for hiding this comment

noahfalk commented Jul 14, 2020

Choose a reason for hiding this comment

alnikola commented Jul 14, 2020

azure-pipelines bot commented Jul 14, 2020

ManickaP left a comment

Choose a reason for hiding this comment

stephentoub Jul 3, 2020 •

edited

Loading