Fix call pattern that throws. (#6626)

rrector · sergeybykov · commit a1ea24789375 · 2020-06-30T19:39:59.000-07:00
* Fix call pattern that throws. Change from related activity ids to actually setting the activity id for the current event being logged. * Avoid allocations in EventSourceEvents Co-authored-by: ReubenBond <rebond@microsoft.com> (cherry picked from commit 29400a2)
diff --git a/src/Orleans.Core/Diagnostics/EventSourceEvents.cs b/src/Orleans.Core/Diagnostics/EventSourceEvents.cs
@@ -13,45 +13,45 @@ public void OnTimeout(Message message)
         {
             if (this.IsEnabled())
             {
-                OnTimeout(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.OnTimeout();
+                }
             }
         }
 
-        [Event(1)]
-        public void OnTimeout(Guid activityId)
-        {
-            this.WriteEventWithRelatedActivityId(1, activityId);
-        }
+        [Event(1, Level = EventLevel.Warning)]
+        private void OnTimeout() => this.WriteEvent(1);
 
         [NonEvent]
         public void OnTargetSiloFail(Message message)
         {
             if (this.IsEnabled())
             {
-                OnTargetSiloFail(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.OnTargetSiloFail();
+                }
             }
         }
 
-        [Event(2)]
-        public void OnTargetSiloFail(Guid activityId)
-        {
-            this.WriteEventWithRelatedActivityId(2, activityId);
-        }
+        [Event(2, Level = EventLevel.Warning)]
+        private void OnTargetSiloFail() => this.WriteEvent(2);
 
         [NonEvent]
         public void DoCallback(Message message)
         {
             if (this.IsEnabled())
             {
-                DoCallback(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.DoCallback();
+                }
             }
         }
 
-        [Event(3)]
-        public void DoCallback(Guid activityId)
-        {
-            WriteEventWithRelatedActivityId(3, activityId);
-        }
+        [Event(3, Level = EventLevel.Verbose)]
+        private void DoCallback() => this.WriteEvent(3);
     }
 
     [EventSource(Name = "Microsoft-Orleans-OutsideRuntimeClient")]
@@ -64,45 +64,45 @@ public void SendRequest(Message message)
         {
             if (this.IsEnabled())
             {
-                SendRequest(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.SendRequest();
+                }
             }
         }
 
-        [Event(1)]
-        public void SendRequest(Guid activityId)
-        {
-            WriteEventWithRelatedActivityId(1, activityId);
-        }
+        [Event(1, Level = EventLevel.Verbose)]
+        private void SendRequest() => this.WriteEvent(1);
 
         [NonEvent]
         public void ReceiveResponse(Message message)
         {
             if (this.IsEnabled())
             {
-                ReceiveResponse(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.ReceiveResponse();
+                }
             }
         }
 
-        [Event(2)]
-        public void ReceiveResponse(Guid activityId)
-        {
-            WriteEventWithRelatedActivityId(2, activityId);
-        }
+        [Event(2, Level = EventLevel.Verbose)]
+        private void ReceiveResponse() => this.WriteEvent(2);
 
         [NonEvent]
         public void SendResponse(Message message)
         {
             if (this.IsEnabled())
             {
-                SendResponse(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.SendResponse();
+                }
             }
         }
 
-        [Event(3)]
-        public void SendResponse(Guid activityId)
-        {
-            WriteEventWithRelatedActivityId(3, activityId);
-        }
+        [Event(3, Level = EventLevel.Verbose)]
+        private void SendResponse() => this.WriteEvent(3);
     }
 
     [EventSource(Name = "Microsoft-Orleans-Dispatcher")]
@@ -115,12 +115,15 @@ public void ReceiveMessage(Message message)
         {
             if (this.IsEnabled())
             {
-                ReceiveMessage(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.ReceiveMessage();
+                }
             }
         }
 
-        [Event(1)]
-        public void ReceiveMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);
+        [Event(1, Level = EventLevel.Verbose)]
+        private void ReceiveMessage() => WriteEvent(1);
     }
 
     [EventSource(Name = "Microsoft-Orleans-InsideRuntimeClient")]
@@ -133,36 +136,45 @@ public void SendRequest(Message message)
         {
             if (this.IsEnabled())
             {
-                SendRequest(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.SendRequest();
+                }
             }
         }
 
-        [Event(1)]
-        public void SendRequest(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);
+        [Event(1, Level = EventLevel.Verbose)]
+        private void SendRequest() => WriteEvent(1);
 
         [NonEvent]
         public void ReceiveResponse(Message message)
         {
             if (this.IsEnabled())
             {
-                ReceiveResponse(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.ReceiveResponse();
+                }
             }
         }
 
-        [Event(2)]
-        public void ReceiveResponse(Guid activityId) => WriteEventWithRelatedActivityId(2, activityId);
+        [Event(2, Level = EventLevel.Verbose)]
+        private void ReceiveResponse() => WriteEvent(2);
 
         [NonEvent]
         public void SendResponse(Message message)
         {
             if (this.IsEnabled())
             {
-                SendResponse(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.SendResponse();
+                }
             }
         }
 
-        [Event(3)]
-        public void SendResponse(Guid activityId) => WriteEventWithRelatedActivityId(3, activityId);
+        [Event(3, Level = EventLevel.Verbose)]
+        private void SendResponse() => WriteEvent(3);
     }
 
     [EventSource(Name = "Microsoft-Orleans-GatewayAcceptor")]
@@ -175,12 +187,15 @@ public void HandleMessage(Message message)
         {
             if (this.IsEnabled())
             {
-                HandleMessage(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.HandleMessage();
+                }
             }
         }
 
-        [Event(1)]
-        public void HandleMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);
+        [Event(1, Level = EventLevel.Verbose)]
+        private void HandleMessage() => WriteEvent(1);
 
     }
 
@@ -194,12 +209,15 @@ public void HandleMessage(Message message)
         {
             if (this.IsEnabled())
             {
-                HandleMessage(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.HandleMessage();
+                }
             }
         }
 
-        [Event(1)]
-        public void HandleMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);
+        [Event(1, Level = EventLevel.Verbose)]
+        private void HandleMessage() => WriteEvent(1);
     }
 
     [EventSource(Name = "Microsoft-Orleans-IncomingMessageAgent")]
@@ -212,11 +230,51 @@ public void ReceiveMessage(Message message)
         {
             if (this.IsEnabled())
             {
-                ReceiveMessage(message.TraceContext?.ActivityId ?? Guid.Empty);
+                using (message.SetThreadActivityId())
+                {
+                    this.ReceiveMessage();
+                }
             }
         }
 
-        [Event(1)]
-        public void ReceiveMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);
+        [Event(1, Level = EventLevel.Verbose)]
+        private void ReceiveMessage() => WriteEvent(1);
+    }
+
+    internal static class EventSourceMessageExtensions
+    {
+        public static ActivityIdScope SetThreadActivityId(this Message message)
+        {
+            var activityId = message?.TraceContext?.ActivityId;
+
+            if (!(activityId is Guid messageActivityId) || messageActivityId == Guid.Empty)
+            {
+                return new ActivityIdScope(Guid.Empty, shouldReset: false);
+            }
+
+            EventSource.SetCurrentThreadActivityId(messageActivityId, out var oldActivity);
+            return new ActivityIdScope(oldActivity, shouldReset: messageActivityId != oldActivity);
+
+        }
+
+        internal readonly ref struct ActivityIdScope
+        {
+            private readonly Guid oldActivity;
+            private readonly bool shouldReset;
+
+            public ActivityIdScope(Guid oldActivity, bool shouldReset)
+            {
+                this.oldActivity = oldActivity;
+                this.shouldReset = shouldReset;
+            }
+
+            public void Dispose()
+            {
+                if (shouldReset)
+                {
+                    EventSource.SetCurrentThreadActivityId(oldActivity);
+                }
+            }
+        }
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -13,45 +13,45 @@ public void OnTimeout(Message message)`
`13`	`13`	`{`
`14`	`14`	`if (this.IsEnabled())`
`15`	`15`	`{`
`16`		`- OnTimeout(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`16`	`+ using (message.SetThreadActivityId())`
	`17`	`+ {`
	`18`	`+ this.OnTimeout();`
	`19`	`+ }`
`17`	`20`	`}`
`18`	`21`	`}`
`19`	`22`
`20`		`- [Event(1)]`
`21`		`- public void OnTimeout(Guid activityId)`
`22`		`- {`
`23`		`- this.WriteEventWithRelatedActivityId(1, activityId);`
`24`		`- }`
	`23`	`+ [Event(1, Level = EventLevel.Warning)]`
	`24`	`+ private void OnTimeout() => this.WriteEvent(1);`
`25`	`25`
`26`	`26`	`[NonEvent]`
`27`	`27`	`public void OnTargetSiloFail(Message message)`
`28`	`28`	`{`
`29`	`29`	`if (this.IsEnabled())`
`30`	`30`	`{`
`31`		`- OnTargetSiloFail(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`31`	`+ using (message.SetThreadActivityId())`
	`32`	`+ {`
	`33`	`+ this.OnTargetSiloFail();`
	`34`	`+ }`
`32`	`35`	`}`
`33`	`36`	`}`
`34`	`37`
`35`		`- [Event(2)]`
`36`		`- public void OnTargetSiloFail(Guid activityId)`
`37`		`- {`
`38`		`- this.WriteEventWithRelatedActivityId(2, activityId);`
`39`		`- }`
	`38`	`+ [Event(2, Level = EventLevel.Warning)]`
	`39`	`+ private void OnTargetSiloFail() => this.WriteEvent(2);`
`40`	`40`
`41`	`41`	`[NonEvent]`
`42`	`42`	`public void DoCallback(Message message)`
`43`	`43`	`{`
`44`	`44`	`if (this.IsEnabled())`
`45`	`45`	`{`
`46`		`- DoCallback(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`46`	`+ using (message.SetThreadActivityId())`
	`47`	`+ {`
	`48`	`+ this.DoCallback();`
	`49`	`+ }`
`47`	`50`	`}`
`48`	`51`	`}`
`49`	`52`
`50`		`- [Event(3)]`
`51`		`- public void DoCallback(Guid activityId)`
`52`		`- {`
`53`		`- WriteEventWithRelatedActivityId(3, activityId);`
`54`		`- }`
	`53`	`+ [Event(3, Level = EventLevel.Verbose)]`
	`54`	`+ private void DoCallback() => this.WriteEvent(3);`
`55`	`55`	`}`
`56`	`56`
`57`	`57`	`[EventSource(Name = "Microsoft-Orleans-OutsideRuntimeClient")]`
`@@ -64,45 +64,45 @@ public void SendRequest(Message message)`
`64`	`64`	`{`
`65`	`65`	`if (this.IsEnabled())`
`66`	`66`	`{`
`67`		`- SendRequest(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`67`	`+ using (message.SetThreadActivityId())`
	`68`	`+ {`
	`69`	`+ this.SendRequest();`
	`70`	`+ }`
`68`	`71`	`}`
`69`	`72`	`}`
`70`	`73`
`71`		`- [Event(1)]`
`72`		`- public void SendRequest(Guid activityId)`
`73`		`- {`
`74`		`- WriteEventWithRelatedActivityId(1, activityId);`
`75`		`- }`
	`74`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`75`	`+ private void SendRequest() => this.WriteEvent(1);`
`76`	`76`
`77`	`77`	`[NonEvent]`
`78`	`78`	`public void ReceiveResponse(Message message)`
`79`	`79`	`{`
`80`	`80`	`if (this.IsEnabled())`
`81`	`81`	`{`
`82`		`- ReceiveResponse(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`82`	`+ using (message.SetThreadActivityId())`
	`83`	`+ {`
	`84`	`+ this.ReceiveResponse();`
	`85`	`+ }`
`83`	`86`	`}`
`84`	`87`	`}`
`85`	`88`
`86`		`- [Event(2)]`
`87`		`- public void ReceiveResponse(Guid activityId)`
`88`		`- {`
`89`		`- WriteEventWithRelatedActivityId(2, activityId);`
`90`		`- }`
	`89`	`+ [Event(2, Level = EventLevel.Verbose)]`
	`90`	`+ private void ReceiveResponse() => this.WriteEvent(2);`
`91`	`91`
`92`	`92`	`[NonEvent]`
`93`	`93`	`public void SendResponse(Message message)`
`94`	`94`	`{`
`95`	`95`	`if (this.IsEnabled())`
`96`	`96`	`{`
`97`		`- SendResponse(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`97`	`+ using (message.SetThreadActivityId())`
	`98`	`+ {`
	`99`	`+ this.SendResponse();`
	`100`	`+ }`
`98`	`101`	`}`
`99`	`102`	`}`
`100`	`103`
`101`		`- [Event(3)]`
`102`		`- public void SendResponse(Guid activityId)`
`103`		`- {`
`104`		`- WriteEventWithRelatedActivityId(3, activityId);`
`105`		`- }`
	`104`	`+ [Event(3, Level = EventLevel.Verbose)]`
	`105`	`+ private void SendResponse() => this.WriteEvent(3);`
`106`	`106`	`}`
`107`	`107`
`108`	`108`	`[EventSource(Name = "Microsoft-Orleans-Dispatcher")]`
`@@ -115,12 +115,15 @@ public void ReceiveMessage(Message message)`
`115`	`115`	`{`
`116`	`116`	`if (this.IsEnabled())`
`117`	`117`	`{`
`118`		`- ReceiveMessage(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`118`	`+ using (message.SetThreadActivityId())`
	`119`	`+ {`
	`120`	`+ this.ReceiveMessage();`
	`121`	`+ }`
`119`	`122`	`}`
`120`	`123`	`}`
`121`	`124`
`122`		`- [Event(1)]`
`123`		`- public void ReceiveMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);`
	`125`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`126`	`+ private void ReceiveMessage() => WriteEvent(1);`
`124`	`127`	`}`
`125`	`128`
`126`	`129`	`[EventSource(Name = "Microsoft-Orleans-InsideRuntimeClient")]`
`@@ -133,36 +136,45 @@ public void SendRequest(Message message)`
`133`	`136`	`{`
`134`	`137`	`if (this.IsEnabled())`
`135`	`138`	`{`
`136`		`- SendRequest(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`139`	`+ using (message.SetThreadActivityId())`
	`140`	`+ {`
	`141`	`+ this.SendRequest();`
	`142`	`+ }`
`137`	`143`	`}`
`138`	`144`	`}`
`139`	`145`
`140`		`- [Event(1)]`
`141`		`- public void SendRequest(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);`
	`146`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`147`	`+ private void SendRequest() => WriteEvent(1);`
`142`	`148`
`143`	`149`	`[NonEvent]`
`144`	`150`	`public void ReceiveResponse(Message message)`
`145`	`151`	`{`
`146`	`152`	`if (this.IsEnabled())`
`147`	`153`	`{`
`148`		`- ReceiveResponse(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`154`	`+ using (message.SetThreadActivityId())`
	`155`	`+ {`
	`156`	`+ this.ReceiveResponse();`
	`157`	`+ }`
`149`	`158`	`}`
`150`	`159`	`}`
`151`	`160`
`152`		`- [Event(2)]`
`153`		`- public void ReceiveResponse(Guid activityId) => WriteEventWithRelatedActivityId(2, activityId);`
	`161`	`+ [Event(2, Level = EventLevel.Verbose)]`
	`162`	`+ private void ReceiveResponse() => WriteEvent(2);`
`154`	`163`
`155`	`164`	`[NonEvent]`
`156`	`165`	`public void SendResponse(Message message)`
`157`	`166`	`{`
`158`	`167`	`if (this.IsEnabled())`
`159`	`168`	`{`
`160`		`- SendResponse(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`169`	`+ using (message.SetThreadActivityId())`
	`170`	`+ {`
	`171`	`+ this.SendResponse();`
	`172`	`+ }`
`161`	`173`	`}`
`162`	`174`	`}`
`163`	`175`
`164`		`- [Event(3)]`
`165`		`- public void SendResponse(Guid activityId) => WriteEventWithRelatedActivityId(3, activityId);`
	`176`	`+ [Event(3, Level = EventLevel.Verbose)]`
	`177`	`+ private void SendResponse() => WriteEvent(3);`
`166`	`178`	`}`
`167`	`179`
`168`	`180`	`[EventSource(Name = "Microsoft-Orleans-GatewayAcceptor")]`
`@@ -175,12 +187,15 @@ public void HandleMessage(Message message)`
`175`	`187`	`{`
`176`	`188`	`if (this.IsEnabled())`
`177`	`189`	`{`
`178`		`- HandleMessage(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`190`	`+ using (message.SetThreadActivityId())`
	`191`	`+ {`
	`192`	`+ this.HandleMessage();`
	`193`	`+ }`
`179`	`194`	`}`
`180`	`195`	`}`
`181`	`196`
`182`		`- [Event(1)]`
`183`		`- public void HandleMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);`
	`197`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`198`	`+ private void HandleMessage() => WriteEvent(1);`
`184`	`199`
`185`	`200`	`}`
`186`	`201`
`@@ -194,12 +209,15 @@ public void HandleMessage(Message message)`
`194`	`209`	`{`
`195`	`210`	`if (this.IsEnabled())`
`196`	`211`	`{`
`197`		`- HandleMessage(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`212`	`+ using (message.SetThreadActivityId())`
	`213`	`+ {`
	`214`	`+ this.HandleMessage();`
	`215`	`+ }`
`198`	`216`	`}`
`199`	`217`	`}`
`200`	`218`
`201`		`- [Event(1)]`
`202`		`- public void HandleMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);`
	`219`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`220`	`+ private void HandleMessage() => WriteEvent(1);`
`203`	`221`	`}`
`204`	`222`
`205`	`223`	`[EventSource(Name = "Microsoft-Orleans-IncomingMessageAgent")]`
`@@ -212,11 +230,51 @@ public void ReceiveMessage(Message message)`
`212`	`230`	`{`
`213`	`231`	`if (this.IsEnabled())`
`214`	`232`	`{`
`215`		`- ReceiveMessage(message.TraceContext?.ActivityId ?? Guid.Empty);`
	`233`	`+ using (message.SetThreadActivityId())`
	`234`	`+ {`
	`235`	`+ this.ReceiveMessage();`
	`236`	`+ }`
`216`	`237`	`}`
`217`	`238`	`}`
`218`	`239`
`219`		`- [Event(1)]`
`220`		`- public void ReceiveMessage(Guid activityId) => WriteEventWithRelatedActivityId(1, activityId);`
	`240`	`+ [Event(1, Level = EventLevel.Verbose)]`
	`241`	`+ private void ReceiveMessage() => WriteEvent(1);`
	`242`	`+ }`
	`243`	`+`
	`244`	`+ internal static class EventSourceMessageExtensions`
	`245`	`+ {`
	`246`	`+ public static ActivityIdScope SetThreadActivityId(this Message message)`
	`247`	`+ {`
	`248`	`+ var activityId = message?.TraceContext?.ActivityId;`
	`249`	`+`
	`250`	`+ if (!(activityId is Guid messageActivityId) \|\| messageActivityId == Guid.Empty)`
	`251`	`+ {`
	`252`	`+ return new ActivityIdScope(Guid.Empty, shouldReset: false);`
	`253`	`+ }`
	`254`	`+`
	`255`	`+ EventSource.SetCurrentThreadActivityId(messageActivityId, out var oldActivity);`
	`256`	`+ return new ActivityIdScope(oldActivity, shouldReset: messageActivityId != oldActivity);`
	`257`	`+`
	`258`	`+ }`
	`259`	`+`
	`260`	`+ internal readonly ref struct ActivityIdScope`
	`261`	`+ {`
	`262`	`+ private readonly Guid oldActivity;`
	`263`	`+ private readonly bool shouldReset;`
	`264`	`+`
	`265`	`+ public ActivityIdScope(Guid oldActivity, bool shouldReset)`
	`266`	`+ {`
	`267`	`+ this.oldActivity = oldActivity;`
	`268`	`+ this.shouldReset = shouldReset;`
	`269`	`+ }`
	`270`	`+`
	`271`	`+ public void Dispose()`
	`272`	`+ {`
	`273`	`+ if (shouldReset)`
	`274`	`+ {`
	`275`	`+ EventSource.SetCurrentThreadActivityId(oldActivity);`
	`276`	`+ }`
	`277`	`+ }`
	`278`	`+ }`
`221`	`279`	`}`
`222`	`280`	`}`