Add Activity to DiagnosticSource by lmolkova · Pull Request #15103 · dotnet/corefx

lmolkova · 2017-01-12T01:34:22Z

This change introduces Activity class which provides operation context for DiagnosticSource, see #15023 and User Guide for more details.

dnfclas · 2017-01-12T01:34:26Z

Hi @lmolkova, I'm your friendly neighborhood .NET Foundation Pull Request Bot (You can call me DNFBOT). Thanks for your contribution!

In order for us to evaluate and accept your PR, we ask that you sign a contribution license agreement. It's all electronic and will take just minutes. I promise there's no faxing. https://cla2.dotnetfoundation.org.

TTYL, DNFBOT;

jkotas · 2017-01-12T04:10:18Z

@vancem PTLA

jkotas · 2017-01-12T04:11:23Z

@lmolkova Could you please sign the contribution agreement using the above link?

karelz · 2017-01-12T16:56:16Z

It adds new API -- @vancem do we need API review first? Or is it porting of Desktop API?

karelz · 2017-01-12T16:56:42Z

cc: @valenis

dnfclas · 2017-01-12T16:56:49Z

Hi @lmolkova, I'm your friendly neighborhood .NET Foundation Pull Request Bot (You can call me DNFBOT). Thanks for your contribution!

In order for us to evaluate and accept your PR, we ask that you sign a contribution license agreement. It's all electronic and will take just minutes. I promise there's no faxing. https://cla2.dotnetfoundation.org.

TTYL, DNFBOT;

vancem · 2017-01-12T17:12:20Z

To answer @karelz, this is new surface area, and needs a API review. @lmolkova previously created issue #15023 to track that API review. I suggested that she create this pull request because it will have many of the details (e.g. descriptions of each API and the guidance on how to use the class) which would be helpful in doing the review.

We should of course wait for the review to be complete before merging this pull request.

karelz · 2017-01-12T17:15:43Z

Got it, that makes sense - folks usually add [WIP] prefix to PRs like that. Let me do that.

dnfclas · 2017-01-12T17:57:12Z

@lmolkova, Thanks for signing the contribution license agreement so quickly! Actual humans will now validate the agreement and then evaluate the PR.

Thanks, DNFBOT;

cwe1ss · 2017-01-27T13:05:41Z

+            get
+            {
+                if (ParentId != null)
+                    yield return new KeyValuePair<string, string>("ParentId", ParentId);


ParentId shouldn't be returned as a tag because it is a property.
If it stays as a tag, what's the reason for having ParentId but not Id, OperationName, ... as tags?!?

ParentId is returned in Tags to simplify activity logging: we include ParentId to make sure it will be logged. It's good idea to apply the same behavior to Id and operation name.

The user didn't add the ParentId tag so why should it be returned on a call to Tags?! "ParentId" is a magic string that could easily be avoided by accessing the property.

Therefore I vote for not including it as a tag.

cwe1ss · 2017-01-27T13:08:10Z

+        }
+
+        /// <summary>
+        /// Tags are string-string key-value pairs that represent information that will


cwe1ss · 2017-01-27T13:11:28Z

+        {
+            get
+            {
+                for (var activity = this; activity != null; activity = activity.Parent)


In OpenTracing, baggage is copied to child spans/activities, so later changes to a parent don't affect children. This has advantages (immutability) and disadvantages though.

We would like to avoid copying baggage.
Code which adds baggage to parent activity should expect that new child activity could be created/sent outside of process at any moment, so for this case there is no difference if Baggage/SpanContext is mutable or not: any child activity may get or may not get parent baggage item.
There is a slight difference for in-proc children, that they will receive any parent update, but for the sake of performance, we allow it.

@lmolkova I believe we should preserve the semantics that there are COPIES made when children are made. The current implementation has this property because we don't allow mutation of EXISTING entries (we allow people to add a existing entry (which has the effect of overwriting that entry in 'GetBaggageItem' but the semantics is copy. If we every allowed update, we would want to copy in that case. (not an issue right now...).

cwe1ss · 2017-01-27T13:12:22Z

+        /// </summary>
+        /// <param name="operationName">Operations name <see cref="OperationName"/></param>
+        public Activity(string operationName)
+        {


Null/empty/whitespace check for operationName?

I'm uncertain about it. Why it is not valid? It does not seem to break anything. I also see opentracing-java does not require it.
OperationName is something which makes sense in client code which assigns and uses it.

You use it for the identifier in the DiagnosticSource.Write call. Is there any valid case for an empty/null operationName? I can't think of one

There is no good reason for a null operation name. However ideally logging is as lean as possible so if we can get away without some run time checking (do the checking later), that is better. If we believe this is a common error, then I would add it, but my intuition suggests that it won't be common and is not catastrophic even if it does happen, so we can do nothing.

cwe1ss · 2017-01-27T13:16:01Z

+        /// <returns>'this' for convinient chaining</returns>
+        public Activity AddTag(string key, string value)
+        {
+            _tags = new KeyValueListNode() { keyValue = new KeyValuePair<string, string>(key, value), Next = _tags };


Since tags and baggage are linked lists right now, there's no way to overwrite existing keys. However, I think this is a necessary and very important feature!

Could you share scenarios for this feature?
I can imagine there is some part of baggage which in fact describes some details about caller rather than global context. And should be updated on every child, e.g. caller version, user, device, whatever. We are considering such scenarios as a future step and it would be great to know if opentracing has a story for them.

Note that the implementation of baggage as a linked list does allow overwriting keys (after all you can call 'AddBaggage' at any time and it will add the new value to the list.

We chose this data structure because it was efficient it the most likely scenarios (a very small number of unique entries which can be passed very efficiently (no copy, simply reference), to any sub-activities).

It is true, however that the current implementation leaves the old value in the list. This does not affect the GetBaggageItem() (which gets the most recently added key), (which is the primary use for baggage, control at runtime), but does affect the 'Baggage' IEnumerable. This can of course be fixed, but having but does complicate the implementation. It is worth consideration...

cwe1ss · 2017-01-27T13:25:24Z

+        /// <returns>'this' for convinient chaining</returns>
+        public Activity SetStartTime(DateTime startTimeUtc)
+        {
+            StartTimeUtc = startTimeUtc;


What should happen if Kind is Unspecified or Local?

cwe1ss · 2017-01-27T13:26:54Z

+        /// <returns>'this' for convinient chaining</returns>
+        public Activity SetEndTime(DateTime endTimeUtc)
+        {
+            Duration = endTimeUtc - StartTimeUtc;


What if Duration ends up negative? What if endTime has a different Kind?

Why not have a Stop overload that accepts the endTimeUtc?

Stop will be called after DiagnosticSource.Write will notify user about activity being stopping.

Here I'd like to give control to user: if he wants to set stop time in the past, I don't see reasons to prevent it. I agree though we should insist on Utc Kind.

cwe1ss · 2017-01-27T13:33:07Z

+
+            Id = GenerateId();
+
+            Current = this;


I'm not sure if this is a good idea. Setting static properties in instance methods is bad practice and unexpected. Would it be better to have this in DiagnosticSource.StartActivity?!

cwe1ss · 2017-01-27T13:38:02Z

+        #region private 
+
+        private string GenerateId()
+        {


Weird algorithm.

As far as I've seen, most tracers use e.g. 128bit random numbers to be able to easily compute sampling rates. (1% of all requests means that all numbers below a threshold will be tracked)

Also, why have different logic for DEBUG/RELEASE?

I will simplify this

cwe1ss · 2017-01-27T13:41:29Z

+        /// reasonable, but arguments (e.g. specific accounts etc), should not be in
+        /// the name but rather in the tags.  
+        /// </summary>
+        public string OperationName { get; }


In OpenTracing there are cases where you want to overwrite the operationName. E.g the hosting layer uses a generic "http-in" and the MVC layer overwrites it with "controller/action".
Here this is problematic though because you use the operationName for the DiagnosticSource events as well. Not sure if/how to cover this?!

I see there may be a case for it. Another approach could be to start new Activity (Span) In MVC with a new name, however Tags won't flow.
I would prefer application to add Tag to activity describing controller/action rather than changing operationName. From the logs prospective, it's useful to see same operation name on start and stop events.

davidfowl · 2017-01-27T14:37:16Z

/cc @avanderhoorn @rynowak @Eilon @DamianEdwards

davidfowl · 2017-01-28T08:44:17Z

@lmolkova have you measured the performance impact of this on a typical http request?

lmolkova · 2017-01-31T22:29:20Z

@davidfowl

Outgoing

here are the measurements for a very short outgoing request to localhost, 10000 runs:

no instrumentation average: 0.336568179999999 ms
with instrumentation average: 0.35996597 ms.

Difference is around 23 microseconds per request in average.

Impact must not depend on outgoing request parameters, but may depend on DiagnosticSource event filter which is under user control.

Incoming

On a simple AspNet Core WebApi app with instrumented incoming request latency standard deviation is quite high comparing to outgoing requests even on 10000 runs.
In general I see similar ~25 microsecond or even smaller difference.

lmolkova · 2017-02-01T02:33:25Z

@karelz, the API #15023 has been approved and PR is ready for review. I wonder if it should still be labeled as no-merge and blocked?

karelz · 2017-02-01T02:36:19Z

@vancem do you want to wait on @cwe1ss feedback first, or just go ahead with this PR?

vancem · 2017-02-02T00:52:57Z

I just looked over all the feedback, and none of it feels blocking to me. However would like to take a look at exactly where we landed I will do this by tomorrow morning.

vancem · 2017-02-07T19:19:42Z

LGTM. While there still might be changes, I am OK with what IS present (it may be missing things, but they can be added compatibly). This allows us to check this in, and build an end-to-end system with it and be in a better position to add any missing things later.

…upport that

weshaggard · 2017-02-08T18:20:57Z

 <Project ToolsVersion="14.0" DefaultTargets="Build" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  <PropertyGroup>
    <BuildConfigurations>
+      net45-Windows_NT;


Does this configuration even build? We haven't even enabled net45 builds yet.

Correct, I cannot build it on net45. Do you suggest to remove build configuration for net45 until it's enabled?

I think @tarekgh was hitting this while trying to make netfx build configurations work so I suspect he will take care of removing this. However in general we should avoid adding configurations that don't work yet unless we have follow-up items to make them work.

For this library what is the goal of adding the net45 configuration?

The feature implemented here will be used in ASP.NET Core, which also targets .NET 4.5.1
Some APIs (CallContext, which is crucial for the feature) are not available on netstandard1.1 and available on .NET 4.5.

We are in the process of bringing up build support for netfx versions I would highly suggest you file a follow-up item to get that configuration enabled for this library if it is a desired configuration you want to support in the package.

weshaggard · 2017-02-08T18:21:44Z

      <OSGroup>Windows_NT</OSGroup>
      <TestTFMs>netcore50;net46</TestTFMs>
    </Project>
+    <Project Include="System.Diagnostics.DiagnosticSource.Tests.csproj">


The .builds files are no longer used. I suspect you didn't test any of these changes on desktop because I don't expect your desktop configuration even builds today.

Are .build files are no longer user for tests as well? I see many projects still have them.
Can I assume tests will run for the targets provided in .csproj and safely remove .build file from the repo?

Correct .builds files are no longer used. We just haven't deleted them all yet, we have a clean-up item to delete them all.

…urce_activity Add Activity to DiagnosticSource Commit migrated from dotnet/corefx@3290d33

dnfclas added the cla-required label Jan 12, 2017

karelz assigned vancem and lmolkova Jan 12, 2017

karelz added * NO MERGE * The PR is not ready for merge yet (see discussion for detailed reasons) area-System.Diagnostics.Tracing blocked Issue/PR is blocked on something - see comments labels Jan 12, 2017

karelz closed this Jan 12, 2017

karelz reopened this Jan 12, 2017

dnfclas added the cla-required label Jan 12, 2017

karelz changed the title ~~Add Activity to DiagnosticSource~~ [WIP] Add Activity to DiagnosticSource Jan 12, 2017

dnfclas added cla-signed and removed cla-required labels Jan 12, 2017

lmolkova force-pushed the dev/diagnosticsource_activity branch from 1de6e8c to 365361f Compare January 12, 2017 21:23

lmolkova force-pushed the dev/diagnosticsource_activity branch 4 times, most recently from 5562c65 to cef093b Compare January 27, 2017 03:53

cwe1ss reviewed Jan 27, 2017

View reviewed changes

lmolkova force-pushed the dev/diagnosticsource_activity branch from cef093b to e054224 Compare January 31, 2017 21:57

lmolkova changed the title ~~[WIP] Add Activity to DiagnosticSource~~ Add Activity to DiagnosticSource Jan 31, 2017

Liudmila Molkova added 5 commits February 7, 2017 16:22

Add Activity to DiagnosticSource #15023

cb468ec

review comments

038bbe9

update Activity user guide

cffa48d

Update Id generation schema

62c7055

Return Id generation algorithm, use Machine name on platforms which s…

3864212

…upport that

lmolkova force-pushed the dev/diagnosticsource_activity branch from 1a29d13 to ca3ce3b Compare February 8, 2017 00:48

rebase with master, fix uap build

3a0882c

lmolkova force-pushed the dev/diagnosticsource_activity branch from 6cd68af to 3a0882c Compare February 8, 2017 01:39

vancem merged commit 3290d33 into dotnet:master Feb 8, 2017

vancem removed * NO MERGE * The PR is not ready for merge yet (see discussion for detailed reasons) blocked Issue/PR is blocked on something - see comments labels Feb 8, 2017

weshaggard reviewed Feb 8, 2017

View reviewed changes

karelz modified the milestone: 2.0.0 Feb 9, 2017

glennc mentioned this pull request Feb 13, 2017

Start and Stop an Activity for each request aspnet/Hosting#939

Closed

picenka21 pushed a commit to picenka21/runtime that referenced this pull request Feb 18, 2022

Merge pull request dotnet/corefx#15103 from lmolkova/dev/diagnosticso…

ffb7b6f

…urce_activity Add Activity to DiagnosticSource Commit migrated from dotnet/corefx@3290d33

Conversation

lmolkova commented Jan 12, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dnfclas commented Jan 12, 2017

Uh oh!

jkotas commented Jan 12, 2017

Uh oh!

jkotas commented Jan 12, 2017

Uh oh!

karelz commented Jan 12, 2017

Uh oh!

karelz commented Jan 12, 2017

Uh oh!

dnfclas commented Jan 12, 2017

Uh oh!

vancem commented Jan 12, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

karelz commented Jan 12, 2017

Uh oh!

dnfclas commented Jan 12, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

davidfowl commented Jan 27, 2017

Uh oh!

davidfowl commented Jan 28, 2017

Uh oh!

lmolkova commented Jan 31, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Outgoing

Incoming

Uh oh!

lmolkova commented Feb 1, 2017

Uh oh!

lmolkova commented Jan 12, 2017 •

edited

Loading

vancem commented Jan 12, 2017 •

edited

Loading

lmolkova commented Jan 31, 2017 •

edited

Loading