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

Prevent ActivityId leak across threads #55625

Merged
merged 2 commits into from
Jul 15, 2021
Merged

Conversation

noahfalk
Copy link
Member

Fixes #51608

Previously running an async task with two or more levels of nesting on the EventSource activity stack would leave the ActivityID set on the old thread after being swapped out at a yield point. This meant that threadpool threads would often have stale ActivityIDs present when they began a new work item. This in turn produced non-sensical logs where it appeared that unrelated work items were nested within each other.

Most of this change is adding tests. The ActivityIdIsZeroedOnThreadSwitchOut test is the one being fixed. The remainder of the new tests pass both before and after the change. I added those to better describe some of the existing behavior and add a little confidence that the change didn't have unintended effects elsewhere. As best I can tell the Activity tracking feature didn't have any testing previously and there is certainly still room for improvement on test coverage.

@dotnet/dotnet-diag - can someone kindly review this?
@brianrob - could you review this?

Fixes dotnet#51608

Previously running an async task with two or more levels of nesting on the EventSource activity stack would leave the ActivityID set
on the old thread after being swapped out at a yield point. This meant that threadpool threads would often have stale ActivityIDs
present when they began a new work item. This in turn produced non-sensical logs where it appeared that unrelated work items were
nested within each other.

Most of this change is adding tests. The ActivityIdIsZeroedOnThreadSwitchOut test is the one being fixed. The remainder of the new
tests pass both before and after the change. I added those to better describe some of the existing behavior and add a little confidence
that the change didn't have unintended effects elsewhere. As best I can tell the Activity tracking feature didn't have any testing previously
and there is certainly still room for improvement on test coverage.
@ghost
Copy link

ghost commented Jul 14, 2021

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

Issue Details

Fixes #51608

Previously running an async task with two or more levels of nesting on the EventSource activity stack would leave the ActivityID set on the old thread after being swapped out at a yield point. This meant that threadpool threads would often have stale ActivityIDs present when they began a new work item. This in turn produced non-sensical logs where it appeared that unrelated work items were nested within each other.

Most of this change is adding tests. The ActivityIdIsZeroedOnThreadSwitchOut test is the one being fixed. The remainder of the new tests pass both before and after the change. I added those to better describe some of the existing behavior and add a little confidence that the change didn't have unintended effects elsewhere. As best I can tell the Activity tracking feature didn't have any testing previously and there is certainly still room for improvement on test coverage.

@dotnet/dotnet-diag - can someone kindly review this?
@brianrob - could you review this?

Author: noahfalk
Assignees: -
Labels:

area-System.Diagnostics.Tracing

Milestone: -

- stop leaking the ActivityEventSource
- disable the tests in the browser where Activity tracking isn't enabled
// Are we popping off a value? (we have a prev, and it creator is cur)
// Special case only relevant for mixed SetActivityID usage:
//
// Are we MAYBE popping off a value? (we have a prev, and it creator is cur)
Copy link
Member

Choose a reason for hiding this comment

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

So this refers to the case where get scheduled on the same thread, but with some execution context such that it was the parent scope of the context we were in, yet not necessarily from popping the event nesting?

Copy link
Member Author

@noahfalk noahfalk Jul 15, 2021

Choose a reason for hiding this comment

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

Yep : ) For example something like this:

async Task A()
{
    Task b = Task.Run(B);
    await Task.Yield();
}

async Task B()
{
     EventSource.Log.FooStart(); // this pushes a new activity
     await Task.Yield(); // assume that when this yields the scheduler decides to resume running A() on this thread.
                                  // A's current activity is one level less nested than the current activity in B()
     EventSource.Log.FooStop();
}

Copy link
Member

@hoyosjs hoyosjs left a comment

Choose a reason for hiding this comment

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

Looks good if I understood those two scenarios correctly.

@noahfalk noahfalk merged commit 617fce4 into dotnet:main Jul 15, 2021
@ghost ghost locked as resolved and limited conversation to collaborators Aug 14, 2021
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.

EventSource Activity ID isn't always reset across async await
2 participants