Event listener overhead reduction pt. 3 #52455

MihaZupan · 2021-05-07T17:31:56Z

Building on top of #51822 and #52092.

Reduced the size of EventWrittenEventArgs for the common case
- As a minimum, events need the EventSource, EventId, TimeStamp and Payload.
- Moved the rest to a MoreInfo class that's allocated only if more parameters are set:
- ActivityId, RelatedActivityId, Tags, Opcode, Level, Keywords, ThreadId, PayloadNames, EventName, Message
Stored ParameterNames on EventMetadata instead of EventWrittenEventArgs
Avoided duplication around TraceLoggingEventTypes 293538e

Method	Toolchain	Mean	Error	Ratio	Gen 0	Allocated
WriteEventNoParams	base	74.98 ns	0.635 ns	1.00	0.0440	184 B
WriteEventNoParams	after 52092 (current main)	56.56 ns	0.447 ns	0.75	0.0325	136 B
WriteEventNoParams	new	49.36 ns	0.430 ns	0.66	0.0134	56 B

WriteHttpRequestStart	base	809.63 ns	5.650 ns	1.00	0.1068	448 B
WriteHttpRequestStart	after 52092 (current main)	206.04 ns	2.987 ns	0.25	0.1070	448 B
WriteHttpRequestStart	new	186.86 ns	1.385 ns	0.23	0.0880	368 B

FullYarpRequest	base	5,913.87 ns	43.604 ns	1.00	1.2054	5048 B
FullYarpRequest	after 52092 (current main)	1,973.14 ns	7.223 ns	0.33	1.1368	4761 B
FullYarpRequest	new	1,764.72 ns	10.423 ns	0.30	0.7744	3241 B

Should be all from me around EventSource for a while.

PR adding a subset of these benchmarks to the performance repo: dotnet/performance#1800

Store PayloadNames on EventMetadata instead of EventWrittenEventArgs

ghost · 2021-05-07T17:32:02Z

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

Building on top of #51822 and #52092.

Reduced the size of EventWrittenEventArgs for the common case
- As a minimum, events need the EventSource, EventId, TimeStamp and Payload.
- Moved the rest to a MoreInfo class that's allocated only if more parameters are set:
- ActivityId, RelatedActivityId, Tags, Opcode, Level, Keywords, ThreadId, PayloadNames, EventName, Message
Stored ParameterNames on EventMetadata instead of EventWrittenEventArgs
Avoided duplication around TraceLoggingEventTypes 293538e

Benchmarks.cs

Method	Toolchain	Mean	Error	Ratio	Gen 0	Allocated
WriteEventNoParams	base	74.98 ns	0.635 ns	1.00	0.0440	184 B
WriteEventNoParams	after 52092 (current main)	56.56 ns	0.447 ns	0.75	0.0325	136 B
WriteEventNoParams	new	49.36 ns	0.430 ns	0.66	0.0134	56 B

WriteHttpRequestStart	base	809.63 ns	5.650 ns	1.00	0.1068	448 B
WriteHttpRequestStart	after 52092 (current main)	206.04 ns	2.987 ns	0.25	0.1070	448 B
WriteHttpRequestStart	new	186.86 ns	1.385 ns	0.23	0.0880	368 B

FullYarpRequest	base	5,913.87 ns	43.604 ns	1.00	1.2054	5048 B
FullYarpRequest	after 52092 (current main)	1,973.14 ns	7.223 ns	0.33	1.1368	4761 B
FullYarpRequest	new	1,764.72 ns	10.423 ns	0.30	0.7744	3241 B

Should be all from me around EventSource for a while. I'll put up a PR to get some of these benchmarks in the performance repo.

Author:	MihaZupan
Assignees:	-
Labels:	`area-System.Diagnostics.Tracing`
Milestone:	6.0.0

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

MihaZupan · 2021-05-07T18:38:43Z

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

+ {
+#if !ES_BUILD_STANDALONE
+ [RequiresUnreferencedCode(EventSourceRequiresUnreferenceMessage)]
+#endif


@LakshanF is adding this attribute sufficient here?

(TraceLoggingEventTypes initialization & synchronization was moved into this getter in 293538e)

noahfalk · 2021-05-11T02:10:43Z

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

 {
- Guid activityId = m_activityId;
- if (activityId == Guid.Empty)
+ if (_moreInfo is MoreEventInfo moreInfo && moreInfo.ActivityId != Guid.Empty)


What happens to performance if you add TplEventSource keyword=0x80 to the trace which enables activity tracking? Even if the Yarp telemetry doesn't enable the keyword there is a decent (and growing) chance that some other EventSource session will enable it and the effects are global. I'm worried that it may be a common scenario that causes EventListener to fall off the fast path in which case it may be better to add ActivityId (but not RelatedActivityId) to the default field set.

How common is it for users to enable activity tracking while using in-process EventListeners as well?

The perf wouldn't be much worse in that case (an extra object allocation). If you believe using EventListener and 0x80 at the same time is common enough I can move the ActivityId off of ExtraInfo as you suggested.

My guess is that the usage would be uncorrelated, but if both are independently common enough then there could still be significant overlap - this is just educated guessing on my part. If the perf consequence isn't that meaningful then there is no need to worry, but I assumed you wouldn't have done the optimization at all if it didn't make a difference.

Method Toolchain Mean Error Ratio Gen 0 Allocated

WriteEventNoParams OnExtraInfo 55.46 ns 1.125 ns 1.00 0.0134 56 B

WriteEventNoParams OnBaseObject 53.52 ns 0.420 ns 0.96 0.0172 72 B

WriteEventNoParams_ActivityId OnExtraInfo 84.18 ns 0.631 ns 1.00 0.0401 168 B

WriteEventNoParams_ActivityId OnBaseObject 77.48 ns 0.679 ns 0.92 0.0172 72 B

FullYarpRequest OnExtraInfo 1,939.21 ns 38.206 ns 1.00 0.7744 3241 B

FullYarpRequest OnBaseObject 1,948.20 ns 20.337 ns 1.00 0.8469 3545 B

FullYarpRequest_ActivityId OnExtraInfo 5,101.87 ns 85.053 ns 1.00 2.4490 10266 B

FullYarpRequest_ActivityId OnBaseObject 4,558.92 ns 31.574 ns 0.89 1.6022 6713 B

Moved it back onto the base object.
Looks like a measurable improvement for the case when ActivityId is accessed while not really affecting other cases.

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

noahfalk · 2021-05-11T02:19:48Z

@josalem @davmason @sywhang

noahfalk

This looked good to me though I'd like one off @josalem, @sywhang, @davmason to take a look as well.

josalem

I read this one when it first went up, but apparently forgot to hit the approve button! Thanks!

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

sywhang

LGTM

MihaZupan · 2021-05-12T05:09:16Z

Failure: #11063

MihaZupan added 7 commits May 7, 2021 15:03

Remove unused field

1be69f3

Reduce common-case EventWrittenEventArgs overheads

5ae5982

Store PayloadNames on EventMetadata instead of EventWrittenEventArgs

Avoid duplication around TraceLoggingEventTypes

293538e

Move GetParameterNames into property getter

320f6cf

While => For

e156172

Add EventMetadata.ParameterTypes

9e944ec

Defer fetching ParameterTypes

e384ec2

MihaZupan added this to the 6.0.0 milestone May 7, 2021

MihaZupan requested review from josalem, noahfalk and sywhang May 7, 2021 17:31

ghost added the area-System.Diagnostics.Tracing label May 7, 2021

MihaZupan commented May 7, 2021

View reviewed changes

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs Outdated Show resolved Hide resolved

MihaZupan mentioned this pull request May 7, 2021

Add EventListener microbenchmarks dotnet/performance#1800

Merged

Add RequiresUnreferencedCode attribute to TraceLoggingEventTypes getter

ff80ae3

MihaZupan commented May 7, 2021

View reviewed changes

MihaZupan added 2 commits May 7, 2021 21:04

Revert init => get

c3f7ecf

ActivityId => RelatedActivityId

9acb0ae

noahfalk reviewed May 11, 2021

View reviewed changes

noahfalk approved these changes May 11, 2021

View reviewed changes

josalem approved these changes May 11, 2021

View reviewed changes

src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs Outdated Show resolved Hide resolved

MihaZupan added 4 commits May 11, 2021 23:28

Merge branch 'main' into event-listener-3

8a5b9a5

Remove eventId arg from DispatchToAllListeners

8eccbc8

Store the first caller's ActivityId in EventWrittenEventArgs

c0ad809

Move ActivityId from MoreInfo to base object

8a67553

sywhang approved these changes May 12, 2021

View reviewed changes

MihaZupan merged commit 2e618ff into dotnet:main May 12, 2021

ghost locked as resolved and limited conversation to collaborators Jun 11, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Event listener overhead reduction pt. 3 #52455

Event listener overhead reduction pt. 3 #52455

Uh oh!

MihaZupan commented May 7, 2021 •

edited

Loading

ghost commented May 7, 2021

Uh oh!

MihaZupan May 7, 2021 •

edited

Loading

noahfalk May 11, 2021

MihaZupan May 11, 2021

noahfalk May 11, 2021

MihaZupan May 11, 2021 •

edited

Loading

Uh oh!

noahfalk commented May 11, 2021

noahfalk left a comment •

edited

Loading

josalem left a comment

Uh oh!

sywhang left a comment

MihaZupan commented May 12, 2021

Labels

4 participants

Method	Toolchain	Mean	Error	Ratio	Gen 0	Allocated
WriteEventNoParams	OnExtraInfo	55.46 ns	1.125 ns	1.00	0.0134	56 B
WriteEventNoParams	OnBaseObject	53.52 ns	0.420 ns	0.96	0.0172	72 B

WriteEventNoParams_ActivityId	OnExtraInfo	84.18 ns	0.631 ns	1.00	0.0401	168 B
WriteEventNoParams_ActivityId	OnBaseObject	77.48 ns	0.679 ns	0.92	0.0172	72 B

FullYarpRequest	OnExtraInfo	1,939.21 ns	38.206 ns	1.00	0.7744	3241 B
FullYarpRequest	OnBaseObject	1,948.20 ns	20.337 ns	1.00	0.8469	3545 B

FullYarpRequest_ActivityId	OnExtraInfo	5,101.87 ns	85.053 ns	1.00	2.4490	10266 B
FullYarpRequest_ActivityId	OnBaseObject	4,558.92 ns	31.574 ns	0.89	1.6022	6713 B

Event listener overhead reduction pt. 3 #52455

Event listener overhead reduction pt. 3 #52455

Uh oh!

Conversation

MihaZupan commented May 7, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

ghost commented May 7, 2021

Uh oh!

MihaZupan May 7, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

noahfalk May 11, 2021

Choose a reason for hiding this comment

MihaZupan May 11, 2021

Choose a reason for hiding this comment

noahfalk May 11, 2021

Choose a reason for hiding this comment

MihaZupan May 11, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

noahfalk commented May 11, 2021

noahfalk left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

josalem left a comment

Choose a reason for hiding this comment

Uh oh!

sywhang left a comment

Choose a reason for hiding this comment

MihaZupan commented May 12, 2021

Labels

4 participants

MihaZupan commented May 7, 2021 •

edited

Loading

MihaZupan May 7, 2021 •

edited

Loading

MihaZupan May 11, 2021 •

edited

Loading

noahfalk left a comment •

edited

Loading