SqlClient diagnostics Before event should record timestamp

[trstringer]

The following logging of the before event for SqlClient diagnostics should include a timestamp member. This would be as simple as adding Timestamp = Stopwatch.GetTimestamp() to the anonymous type passed into DiagnosticListener.Write().

Please assign this issue to me, as I will be making the code change and submitting the pull request (I am the author of the code in question).

[stephentoub]

@vancem, what's the recommended approach here? I'd have thought the infrastructure should be responsible for metadata like timestamps on events, rather than every event itself needing to store such data?

[trstringer]

Thanks for the quick response, @stephentoub! Looping @avanderhoorn into the conversation as well!

[avanderhoorn]

The idea of providing the timestamp is so that all consumers are working from the same data set when showing timings/durations/etc. Imagine that the your looking at IntelliTrace and it says the command took 19.78ms, then Glimpse says that the time was 20.34ms and then some other tool said it took 21.01ms... It would be a little off putting to need to rationalize why the timings are different. Hence we include this data for things like command duration, or http client request timings where multiple tools are likely to want to show the data. Here is a sample of where we are doing the same thing for HttpClient - dotnet/corefx@edbd7ba.

[vancem]

Generally speaking, yes, the expectation is that the logging in infrastructure should be doing that part which it can do uniformly, and the timestamp is certainly something that the logging infrastructure can do. This is particularly true for Timestamp since it is very easy for different code to have different notions of time (is it ticks, nanoseconds, 100ns, seconds as a double?, where is the start point?). If the logging infrastructure does it at least it is consistent over all events logged to that code. If individual events do it, it is likely to be inconsistent or chaotic (some people use Stopwatch, others Environment.TickCount ...)

So Timestamp is not a great idea, however it is useful sometimes to include ElapsedTime on the stop of a start-stop pair. The main value of this is that it is more convenient for the recipient (he does not need to create a state machine to match up start-stop pairs and subtract the timestamps), and it allows you to only send the Stop event in many cases (thus halving your overhead but still getting the important information). The decision to do this is more scenario dependent (does the information being logged need other massaging, or is it likely that humans will actually look at the events in raw form).

[stephentoub]

The idea of providing the timestamp

I wasn't arguing against having a timestamp... I was suggesting that it shouldn't be the job of the code logging the event to store a timestamp, but rather the EventSource or DiagnosticSource infrastructure can/should be doing that for every event, regardless of what additional information is logged.

This seems to align with Vance's feedback as well, if I'm interpreting it correctly.

[avanderhoorn]

Given further discussion on this, we have opened #8511 which should be able to track metadata like this in a more consistent way.

[saurabh500]

@tstringer @avanderhoorn Do we still need this issue? The related https://github.com/dotnet/corefx/issues/8511 was closed. However i don't understand if the timestamp in Diagnostics is solved or not

[vancem]

As mentioned in #8511 the meta-data issue has been solved with System.Diagnostics.Activity (#15103), this is because you can attach meta-data to the activity, and access it from within the DiagnosticSource.Write() callback. It also addresses the timestamp issue because Activities have the notion of a start and stop time.

However this existence of this type does not make it light up. For that the instrumentation sites need to be updated to use the Activities. For outgoing HTTP this was #17141. For Incoming HTTP it is aspnet/Hosting#964. We will also need an update for SQL client.

The min-bar would be to update the logging so that it uses the StartActivity() and StopActivity() APIs (and follow naming conventions). We should do this work.

This issue has a bad title for this, so is probably best to create a new issue for this and close this one, referring to it.

@lmolkova @glennc

[divega]

As recently announced in the .NET Blog, focus on new SqlClient features an improvements is moving to the new Microsoft.Data.SqlClient package. For this reason, we are moving this issue to the new repo at https://github.com/dotnet/SqlClient. We will still use https://github.com/dotnet/corefx to track issues on other providers like System.Data.Odbc and System.Data.OleDB, and general ADO.NET and .NET data access issues.

[David-Engel]

@saurabh500 Need your input for triaging.

[divega]

FWIW, I think the conclusion on #101 (comment) is that the right way to do this is to start using Activity APIs, but that would be better tracked in a new issue.

cc @vancem in case this guidance has changed.

[David-Engel]

This was a small change so we went ahead and made it. The change will be in the next preview release of Microsoft.Data.SqlClient. We have another backlog item (not on GitHub) for enhancing the Activity tracing that we will work on in the future.