Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix Activity Start Time Precision #45175

Merged
merged 1 commit into from
Nov 25, 2020

Conversation

tarekgh
Copy link
Member

@tarekgh tarekgh commented Nov 25, 2020

#45111
#44354

The Activity class has a property called StartTimeUtc which report the starting time of the activity. Activity class existed for long time and users used to create it through the constructor new Activity(...). When running on .NET Core, we use DateTime.UtcNow to get the starting time. We do that because in .NET Core the DateTime.UtcNow is returned with high precision. When running on .NET Framework, we don't use DateTime.UtcNow because its accuracy is ~16ms which is not that precise. Instead we use a combination of Stopwatch and DateTime to calculate more precise time. Activity has internal method called GetUtcNow() which implemented for .NET Core by just calling DateTime.UtcNow and implemented for .NET Framework by using the Stopwatch and DateTime. Activity.StartTimeUtc just use GetUtcNow() to get the starting time.

In .NET 5.0 we have introduced a new type ActivitySource which allow creating and starting Activity objects through the public method StartActivity(...). But the implementation of this method always use DateTime.UtcNow for getting the starting time. That made the reported starting time on the .NET Framework not precise and users of the System.Diagnostics.DiagnosticSource package that shipped with .NET 5.0 started to notice that and caused problems in their trace reporting.

The fix here is, instead of having ActivitySource.StartActivity(...) calling DateTime.UtcNow, we are changing it to call Activity.GetUtcNow() which will make the reported time on .NET Framework more precise. This change has no real effect on .NET Core as Activity.GetUtcNow() there just calling DateTime.UtcNow.

@ghost
Copy link

ghost commented Nov 25, 2020

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

Issue Details

#45111
#44354

The Activity class has a property called StartTimeUtc which report the starting time of the activity. Activity class existed for long time and users used to create it through the constructor new Activity(...). When running on .NET Core, we use DateTime.UtcNow to get the starting time. We do that because in .NET Core the DateTime.UtcNow is returned with high precision. When running on .NET Framework, we don't use DateTime.UtcNow because its accuracy is ~16ms which is not that precise. Instead we use a combination of Stopwatch and DateTime to calculate more precise time. Activity has internal method called GetUtcNow() which implemented for .NET Core by just calling DateTime.UtcNow and implemented for .NET Framework by using the Stopwatch and DateTime. Activity.StartTimeUtc just use GetUtcNow() to get the starting time.

In .NET 5.0 we have introduced a new type ActivitySource which allow creating and starting Activity objects through the public method StartActivity(...). But the implementation of this method always use DateTime.UtcNow for getting the starting time. That made the reported starting time on the .NET Framework not precise and users of the System.Diagnostics.DiagnosticSource package that shipped with .NET 5.0 started to notice that and caused problems in their trace reporting.

The fix here is, instead of having ActivitySource.StartActivity(...) calling DateTime.UtcNow, we are changing it to call Activity.GetUtcNow() which will make the reported time on .NET Framework more precise. This change has no real effect on .NET Core as Activity.GetUtcNow() there just calling DateTime.UtcNow.

Author: tarekgh
Assignees: -
Labels:

area-System.Diagnostics.Tracing

Milestone: -

@tarekgh
Copy link
Member Author

tarekgh commented Nov 25, 2020

@ericstj @tommcdon this is the issue that I talked to you about and going to ask to port it to the servicing release. could

@sywhang could you please have a look as @noahfalk is off?

CC @cg110 @cijothomas

@tarekgh
Copy link
Member Author

tarekgh commented Nov 25, 2020

/backport to release/5.0

@github-actions
Copy link
Contributor

Started backporting to release/5.0: https://github.com/dotnet/runtime/actions/runs/382236457

@tommcdon tommcdon requested a review from sywhang November 25, 2020 01:03
Copy link
Contributor

@sywhang sywhang left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM!

@tarekgh
Copy link
Member Author

tarekgh commented Nov 25, 2020

The CI failure is unrelated and tracked by the issue #44306

@tarekgh tarekgh merged commit fe80a77 into dotnet:master Nov 25, 2020
@tarekgh tarekgh deleted the FixActivityStartTimePrecision branch November 25, 2020 04:44
@ghost ghost locked as resolved and limited conversation to collaborators Dec 25, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants