Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Next Next commit
Add event to RuntimeEventSource for AppContext switches
Fixes #56142
  • Loading branch information
agocke committed Aug 12, 2021
commit e0a1602e42482779f0d64cbcd5200506d5776293
17 changes: 17 additions & 0 deletions src/libraries/System.Private.CoreLib/src/System/AppContext.cs
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,23 @@ public static void SetSwitch(string switchName, bool isEnabled)
}
}

internal static void LogSwitchValues(RuntimeEventSource ev)
{
if (s_switches is null)
{
return;
}

lock (s_switches)
{
foreach (var (k, v) in s_switches)
Copy link
Member

Choose a reason for hiding this comment

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

This is only going to log switches set using AppContext.SetSwitch . It won't log switches set using build properties and runtime.json that I think are much more common these days. Do we need to log those too?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes, I would like to include those as well -- do you know which API they go through if not SetSwitch?

Copy link
Member

Choose a reason for hiding this comment

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

AppDomain.SetData (#47922 tracks adding AppContext.SetData for completeness)

Also, the runtime startup goes over everything that is in runtime.json and calls AppDomain.SetData for it.

Copy link
Member Author

Choose a reason for hiding this comment

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

In that case I will also add everything in s_dataStore which has a boolean value. I'm trying to avoid grabbing everything in s_dataStore to limit the amount of potential user data that's recorded.

{
// Convert bool to int because it's cheaper to log (no boxing)
ev.LogAppContextSwitch(k, v ? 0 : 1);
}
}
}

#if !CORERT
internal static unsafe void Setup(char** pNames, char** pValues, int count)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,12 @@ public static void Initialize()
// as you can't make a constructor partial.
private RuntimeEventSource(int _) { }

[Event(2, Level = EventLevel.Informational)]
Copy link
Contributor

Choose a reason for hiding this comment

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

For ease of use, it might be best to assign this a keyword.

When you got to enable this, it'll create the counters. They won't get turned on unless you specify EventCounterIntervalSec as a filter parameter, though. That being said, we don't want to have the presence of the filter string be the switch for enabling counters or not.

You can do this by adding a nested class like this:

public static class Keywords
{
	public const EventKeyword AppContext = (EventKeyword)0x1;
}

Then you can assign it to the event by updating the EventAttribute to have the EventKeyword parameter.

This way a user can turn on just this event without having to turn on all the counters.

CC @brianrob to weigh in on the experience of this.

Copy link
Member Author

Choose a reason for hiding this comment

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

Sorry, I'm not understanding this at all. Are you saying that we should add an additional registration key for just grabbing the AppContext switches?

Copy link
Member

Choose a reason for hiding this comment

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

Let me try to re-state @josalem's position and see if I get it right. I think that @josalem is saying that right now, everything in this EventSource gets turned on all at once because there is no ability to filter. The counters get created but not actually enabled because a filter string is required to turn them on, but I think he's saying that in the future, he'd like for this not to be the case, and so wants to future proof this with a keyword. Keywords are one of the constructs that let you filter, and so I believe he's just proposing adding a keyword to allow this to be turned on and off independently of the counters. @josalem did I get that right?

I have another question on this - is this where we would want this and other future managed code events to live, when their functionality is in CoreLib, or do we think that the event should live somewhere like FrameworkEventSource?

Copy link
Member

Choose a reason for hiding this comment

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

I should also add that I think this event is a great idea, and I will absolutely turn this on by default in PerfView.

Copy link
Member Author

Choose a reason for hiding this comment

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

I think this is a reasonable place for the AppContext switch events to live -- I'm not sure I'd be bold enough to take a stronger position than that.

Copy link
Member

Choose a reason for hiding this comment

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

Fair enough. I was aiming that question more at @josalem. :)

Copy link
Contributor

Choose a reason for hiding this comment

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

Your assessment is spot-on, Brian.

I think it is fine for now. If we add a keyword for the AppContext switches, we can at least turn on just those events. Not specifying EventCounterIntervalSec means we can turn on the world without enabling the counters, but it's not ideal as an enabling mechanism.

internal void LogAppContextSwitch(string switchName, int value)
Copy link
Member

Choose a reason for hiding this comment

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

@brianrob Would a single event with all of the data be better for something like this?

Copy link
Member

Choose a reason for hiding this comment

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

I think one event per switch is good. It makes it easy to consume the data, and I can't imagine we'll have so many that the cost of this event will be painful. If/when we choose to create events were we dump data in bulk, it makes both the event production and event consumption code more complex. On the production side, you have to chunk the data to ensure that you don't run up against size limitations (e.g. ETW has a 64K size limit per event). On the consumption side, you have to be more sophisticated in how you parse the event. There are definitely places were it's valuable - for example BulkType events in the runtime when we log heap snapshots. There are just tons of types, and so emitting each one in its own event is very costly.

{
base.WriteEvent(2, switchName, value);
}

protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command == EventCommand.Enable)
Expand Down Expand Up @@ -87,6 +93,8 @@ protected override void OnEventCommand(EventCommandEventArgs command)
_ilBytesJittedCounter ??= new PollingCounter("il-bytes-jitted", this, () => System.Runtime.JitInfo.GetCompiledILBytes()) { DisplayName = "IL Bytes Jitted", DisplayUnits = "B" };
_methodsJittedCounter ??= new PollingCounter("methods-jitted-count", this, () => System.Runtime.JitInfo.GetCompiledMethodCount()) { DisplayName = "Number of Methods Jitted" };
_jitTimeCounter ??= new IncrementingPollingCounter("time-in-jit", this, () => System.Runtime.JitInfo.GetCompilationTime().TotalMilliseconds) { DisplayName = "Time spent in JIT", DisplayUnits = "ms", DisplayRateTimeScale = new TimeSpan(0, 0, 1) };

AppContext.LogSwitchValues(this);
Copy link
Member

Choose a reason for hiding this comment

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

This is just logging values at a specific point in time (when the event source is enabled) - is that the desire?

I'm thinking of the possibility of scenarios like:

  • Initial values do not have SwitchX set
  • Event source is enabled, logging that SwitchX is not set
  • App sets SwitchX
  • Runtime (or app/library) reads SwitchX and is now configured a certain way

or

  • Initial values do not have SwitchX set
  • Runtime (or app/library) reads SwitchX and is now configured a certain way
  • App sets SwitchX
  • Event source is enabled, logging that SwitchX is set

Copy link
Member

Choose a reason for hiding this comment

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

I think most of those are edge cases. The 90% usage is:

  • Switch set in the entry point
  • Switch set in runtime.config.json (which comes from the csproj)

Copy link
Member

Choose a reason for hiding this comment

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

Definitely agree that those should not be the common case, but wanted to call it out.

  • Switch set in the entry point

I think part of my question is what does this end up looking like when tracing startup (where I'd expect the event source is enabled before the app's entry is is run)? Could it end up being the first scenario I had above?

Copy link
Member

Choose a reason for hiding this comment

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

I'm not sure, @brianrob @josalem do event sources OnCommand run before Main executes when you attach the event source at startup (which not many do).

@elinor-fung These are great questions BTW 👍🏾

Copy link
Member

Choose a reason for hiding this comment

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

They definitely can, but not all will. If the EventSource comes into existence before Main is called and it is told to turn on (e.g. EventPipe, ETW, or some EventListener tells it to), then it will trigger before Main. By design, there isn't anything that requires that Main run before events can be emitted. A good example here is FrameworkEventSource which often comes into existence before Main.

Copy link
Member

Choose a reason for hiding this comment

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

To add to this, if you want to ensure that these can be emitted early, make sure that the EventSource that emits them comes into existence early. That may already be the case, but if not, make sure it gets instantiated early, even if it doesn't log any events when instantiated. Just the instantiation will allow it to be enabled immediately (at least by ETW, but shortly by EventPipe once it comes up).

Copy link
Member

Choose a reason for hiding this comment

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

@elinor-fung, just read your first scenario - I think that the right way to handle a race between logging the current state and changes to switches is to dump the set of switches at the beginning of the tracing session as this code does. Additionally, any time a switch is configured, it should be logged immediately. This ensures that if switches change value or get set after the session is created, we see the change. This, combined with instantiating the EventSource early will ensure that we don't miss any data.

}

}
Expand Down