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

Add event to RuntimeEventSource for AppContext switches #57303

Merged
merged 20 commits into from
Aug 20, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
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
Original file line number Diff line number Diff line change
@@ -1,7 +1,10 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Diagnostics.Tracing;
using System.IO;
using System.Reflection;

Expand Down Expand Up @@ -30,5 +33,52 @@ private static string GetBaseDirectoryCore()

return directory;
}

internal static void LogSwitchValues(RuntimeEventSource ev)
{
if (s_switches is not null)
{
lock (s_switches)
{
foreach (KeyValuePair<string, bool> kvp in s_switches)
{
// Convert bool to int because it's cheaper to log (no boxing)
ev.LogAppContextSwitch(kvp.Key, kvp.Value ? 1 : 0);
}
}
}

if (s_dataStore is not null)
{
lock (s_dataStore)
{
if (s_switches is not null)
{
lock (s_switches)
{
LogDataStore(ev, s_switches);
}
}
else
{
LogDataStore(ev, null);
}

static void LogDataStore(RuntimeEventSource ev, Dictionary<string, bool>? switches)
{
Debug.Assert(s_dataStore is not null);
foreach (KeyValuePair<string, object?> kvp in s_dataStore)
{
if (kvp.Value is string s &&
bool.TryParse(s, out bool isEnabled) &&
switches?.ContainsKey(kvp.Key) != true)
{
ev.LogAppContextSwitch(kvp.Key, isEnabled ? 1 : 0);
}
}
}
}
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,11 @@ internal sealed partial class RuntimeEventSource : EventSource
{
internal const string EventSourceName = "System.Runtime";

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

private static RuntimeEventSource? s_RuntimeEventSource;
private PollingCounter? _gcHeapSizeCounter;
private IncrementingPollingCounter? _gen0GCCounter;
Expand Down Expand Up @@ -50,6 +55,17 @@ public static void Initialize()
// as you can't make a constructor partial.
private RuntimeEventSource(int _) { }

private enum EventId : int
{
AppContextSwitch = 1
}

[Event((int)EventId.AppContextSwitch, Level = EventLevel.Informational, Keywords = Keywords.AppContext)]
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.

agocke marked this conversation as resolved.
Show resolved Hide resolved
{
base.WriteEvent((int)EventId.AppContextSwitch, switchName, value);
Copy link
Member

Choose a reason for hiding this comment

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

Insight into GitHub's C# colorizer algorithm:
image
😄

}

protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command == EventCommand.Enable)
agocke marked this conversation as resolved.
Show resolved Hide resolved
Expand Down Expand Up @@ -87,6 +103,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);
josalem marked this conversation as resolved.
Show resolved Hide resolved
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
6 changes: 4 additions & 2 deletions src/tests/tracing/eventcounter/runtimecounters.cs
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,9 @@ protected override void OnEventSourceCreated(EventSource source)
{
Dictionary<string, string> refreshInterval = new Dictionary<string, string>();
refreshInterval.Add("EventCounterIntervalSec", "1");
EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval);
EnableEvents(source, EventLevel.Informational,
(EventKeywords)(-1 & (~1 /* RuntimeEventSource.Keywords.AppContext */)),
refreshInterval);
}
}

Expand Down Expand Up @@ -100,7 +102,7 @@ public static int Main(string[] args)
// Create an EventListener.
using (RuntimeCounterListener myListener = new RuntimeCounterListener())
{
Thread.Sleep(3000);
Thread.Sleep(3000);
if (myListener.Verify())
{
Console.WriteLine("Test passed");
Expand Down
114 changes: 114 additions & 0 deletions src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,114 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.IO;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using System.Threading;
using Tracing.Tests.Common;

namespace Tracing.Tests
{
public sealed class NativeRuntimeEventSourceTest
{
static int Main(string[] args)
{
SimpleEventListener.EnableKeywords = (EventKeywords)0;
using (SimpleEventListener noEventsListener = new SimpleEventListener("NoEvents"))
{
// Create an EventListener.
SimpleEventListener.EnableKeywords = (EventKeywords)0x4c14fccbd;
using (SimpleEventListener listener = new SimpleEventListener("Simple"))
{
// Trigger the allocator task.
System.Threading.Tasks.Task.Run(new Action(Allocator));

// Wait for events.
Thread.Sleep(1000);

// Generate some GC events.
GC.Collect(2, GCCollectionMode.Forced);

// Wait for more events.
Thread.Sleep(1000);

// Ensure that we've seen some events.
Assert.True("listener.EventCount > 0", listener.EventCount > 0);
}

// Generate some more GC events.
GC.Collect(2, GCCollectionMode.Forced);

// Ensure that we've seen no events.
Assert.True("noEventsListener.EventCount == 0", noEventsListener.EventCount == 0);
}

return 100;
}

private static void Allocator()
{
while (true)
{
for(int i=0; i<1000; i++)
GC.KeepAlive(new object());

Thread.Sleep(10);
}
}
}

internal sealed class SimpleEventListener : EventListener
{
private string m_name;

// Keep track of the set of keywords to be enabled.
public static EventKeywords EnableKeywords
{
get;
set;
}

public SimpleEventListener(string name)
{
m_name = name;
}

public int EventCount { get; private set; } = 0;

protected override void OnEventSourceCreated(EventSource eventSource)
{
if (eventSource.Name.Equals("Microsoft-Windows-DotNETRuntime"))
{
if (EnableKeywords != 0)
{
// Enable events.
EnableEvents(eventSource, EventLevel.Verbose, EnableKeywords);
}
else
{
// Enable the provider, but not any keywords, so we should get no events as long as no rundown occurs.
EnableEvents(eventSource, EventLevel.Critical, EnableKeywords);
}
}
}

protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
Console.WriteLine($"[{m_name}] ThreadID = {eventData.OSThreadId} ID = {eventData.EventId} Name = {eventData.EventName}");
Console.WriteLine($"TimeStamp: {eventData.TimeStamp.ToLocalTime()}");
Console.WriteLine($"LocalTime: {DateTime.Now}");
Console.WriteLine($"Difference: {DateTime.UtcNow - eventData.TimeStamp}");
Assert.True("eventData.TimeStamp <= DateTime.UtcNow", eventData.TimeStamp <= DateTime.UtcNow);
for (int i = 0; i < eventData.Payload.Count; i++)
{
string payloadString = eventData.Payload[i] != null ? eventData.Payload[i].ToString() : string.Empty;
Console.WriteLine($"\tName = \"{eventData.PayloadNames[i]}\" Value = \"{payloadString}\"");
}
Console.WriteLine("\n");

EventCount++;
}
}
}
Loading