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

Remove static modifiers from ThreadPool events in NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs #85563

Merged
merged 7 commits into from
May 13, 2023
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
Expand Up @@ -153,7 +153,7 @@ public unsafe void ThreadPoolWorkerThreadAdjustmentStats(
}

[Event(63, Level = EventLevel.Verbose, Message = Messages.IOEnqueue, Task = Tasks.ThreadPool, Opcode = Opcodes.IOEnqueue, Version = 0, Keywords = Keywords.ThreadingKeyword | Keywords.ThreadTransferKeyword)]
private static unsafe void ThreadPoolIOEnqueue(
private unsafe void ThreadPoolIOEnqueue(
IntPtr NativeOverlapped,
IntPtr Overlapped,
bool MultiDequeues,
Expand Down Expand Up @@ -188,7 +188,7 @@ public void ThreadPoolIOEnqueue(RegisteredWaitHandle registeredWaitHandle)
}

[Event(64, Level = EventLevel.Verbose, Message = Messages.IO, Task = Tasks.ThreadPool, Opcode = Opcodes.IODequeue, Version = 0, Keywords = Keywords.ThreadingKeyword | Keywords.ThreadTransferKeyword)]
private static unsafe void ThreadPoolIODequeue(
private unsafe void ThreadPoolIODequeue(
IntPtr NativeOverlapped,
IntPtr Overlapped,
ushort ClrInstanceID = DefaultClrInstanceId)
Expand Down
290 changes: 213 additions & 77 deletions src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -10,147 +10,283 @@
using System.Runtime.InteropServices;
using System.Threading;
using System.Threading.Tasks;
using Tracing.Tests.Common;
using System.Collections.Concurrent;
using System.ComponentModel;
using System.Collections;
using System.Collections.Generic;
using System.Text;

namespace Tracing.Tests
{
public sealed class NativeRuntimeEventSourceTest
{
static int Main()
private static int Main()
{
SimpleEventListener.EnableKeywords = (EventKeywords)0;
using (SimpleEventListener noEventsListener = new SimpleEventListener("NoEvents"))
// Create deaf listener
Listener.Level = EventLevel.Critical;
Listener.EnableKeywords = EventKeywords.None;
using (Listener noEventsListener = new("NoEvents"))
{
// Create an EventListener.
SimpleEventListener.EnableKeywords = (EventKeywords)0x4c14fccbd;
using (SimpleEventListener listener = new SimpleEventListener("Simple"))
using (NativeOverlappedClass nativeOverlappedClass = new())
{
// Trigger the allocator task.
Task.Run(new Action(Allocator));
// Create an EventListener.
Listener.Level = EventLevel.Verbose;
const EventKeywords EventKeywordThreading = (EventKeywords)65536;
Listener.EnableKeywords = (EventKeywords)0x4c14fccbd | EventKeywordThreading;

// If on Windows, attempt some Overlapped IO (triggers ThreadPool events)
if (OperatingSystem.IsWindows())
// Check for events e.g. ThreadPoolIODequeue = 64
// At least some of these events can be found in "src\libraries\System.Private.CoreLib\src\System\Threading\NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs"
Listener.TargetEventIds(63, 64, 65);

using (Listener listener = new())
{
// Trigger the allocator task.
Task.Run(() =>
{
while (true)
{
for (int i = 0; i < 1000; i++)
{
GC.KeepAlive(new object());
}

Thread.Sleep(10);
}
});

// If on Windows, attempt some Overlapped IO (triggers ThreadPool events)
DoOverlappedIO();
}

// Generate some GC events.
GC.Collect(2, GCCollectionMode.Forced);
// Trigger EventId 63 and 64
nativeOverlappedClass.ThreadPoolQueue();

Stopwatch sw = Stopwatch.StartNew();

while (sw.Elapsed <= TimeSpan.FromMinutes(1))
{
Thread.Sleep(100);
// Generate some GC events.
GC.Collect(2, GCCollectionMode.Forced);

if ((OperatingSystem.IsWindows() && listener.SeenProvidersAndEvents.Contains("Microsoft-Windows-DotNETRuntime/EVENTID(65)"))
|| (!OperatingSystem.IsWindows() && listener.EventCount > 0))
Stopwatch sw = Stopwatch.StartNew();

while (sw.Elapsed <= TimeSpan.FromMinutes(1d / 12d))
{
break;
Thread.Sleep(100);

if ((listener.EventsLeft <= 0) || (!OperatingSystem.IsWindows() && listener.EventCount > 0))
{
break;
}
}
}

// Ensure that we've seen some events.
foreach (string s in listener.SeenProvidersAndEvents)
{
Console.WriteLine(s);
}
Assert2.True("listener.EventCount > 0", listener.EventCount > 0);

Assert.True("listener.EventCount > 0", listener.EventCount > 0);

if (OperatingSystem.IsWindows())
{
Assert.True("Saw the ThreadPoolIOPack event", listener.SeenProvidersAndEvents.Contains("Microsoft-Windows-DotNETRuntime/EVENTID(65)"));
if (OperatingSystem.IsWindows())
{
StringBuilder stringBuilder = new();
foreach (var e in listener.GetFailedTargetEvents())
{
stringBuilder.Append((stringBuilder.Length > 0) ? ", " : "");
stringBuilder.Append(e.Key);
}
Assert2.True($"At least one of the EventIds ({stringBuilder}) where heard.", stringBuilder.Length < 1);
}
}
}

// 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);
Assert2.True("noEventsListener.EventCount == 0", noEventsListener.EventCount == 0);
}

return 100;
}

private static void Allocator()
private static unsafe void DoOverlappedIO()
{
while (true)
if (!OperatingSystem.IsWindows())
{
for(int i=0; i<1000; i++)
{
GC.KeepAlive(new object());
}

Thread.Sleep(10);
return;
}
}

private static unsafe void DoOverlappedIO()
{
Console.WriteLine("DOOVERLAPPEDIO");
Overlapped overlapped = new();
NativeOverlapped* pOverlap = overlapped.Pack(null, null);
Overlapped.Free(pOverlap);
}

private static class Assert2
{
public static void True(string name, bool condition)
{
if (!condition)
{
throw new Exception(
string.Format("Condition '{0}' is not true", name));
}
}
}
}

internal sealed class SimpleEventListener : EventListener
internal sealed unsafe class NativeOverlappedClass : IDisposable
{
public ConcurrentBag<string> SeenProvidersAndEvents { get; private set; } = new();
private string m_name;
private bool disposedValue;
private readonly NativeOverlapped* nativeOverlapped;

// Keep track of the set of keywords to be enabled.
public static EventKeywords EnableKeywords
public NativeOverlappedClass()
{
get;
set;
if (OperatingSystem.IsWindows())
{
nativeOverlapped = new Overlapped().Pack(null, null);
}
}

public SimpleEventListener(string name)
public bool ThreadPoolQueue()
{
m_name = name;
return OperatingSystem.IsWindows() && ThreadPool.UnsafeQueueNativeOverlapped(nativeOverlapped);
}

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

protected override void OnEventSourceCreated(EventSource eventSource)
private void Dispose(bool disposing)
{
if (eventSource.Name.Equals("Microsoft-Windows-DotNETRuntime"))
if (!disposedValue)
{
if (EnableKeywords != 0)
if (disposing)
{
// Enable events.
EnableEvents(eventSource, EventLevel.Verbose, EnableKeywords);
// TODO: dispose managed state (managed objects)
}
else

if (OperatingSystem.IsWindows())
{
// Enable the provider, but not any keywords, so we should get no events as long as no rundown occurs.
EnableEvents(eventSource, EventLevel.Critical, EnableKeywords);
Overlapped.Free(nativeOverlapped);
}

disposedValue = true;
}
}

protected override void OnEventWritten(EventWrittenEventArgs eventData)
~NativeOverlappedClass()
{
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++)
Dispose(disposing: false);
}

public void Dispose()
{
Dispose(disposing: true);
GC.SuppressFinalize(this);
}
}

internal sealed class Listener : EventListener
{
public static string EventSourceName = "Microsoft-Windows-DotNETRuntime";
public static EventLevel Level = EventLevel.Verbose;
public static EventKeywords EnableKeywords = EventKeywords.All;

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

private static readonly ConcurrentBag<int> targetEventIds = new();
private static readonly (string, string) defaultEventSourceNameName = ("Failed to listen", "Was not heard or didn't fire");

private readonly string name = "";
private readonly ConcurrentDictionary<int, (string, string)> eventIdSourceNameNames = new();

public Listener(string name = nameof(Listener))
{
this.name = $"({name}) ";
}

public static void TargetEventIds(params int[] ids)
{
targetEventIds.Clear();

foreach (int id in ids)
{
targetEventIds.Add(id);
}
}
public IEnumerable<KeyValuePair<int, (string, string)>> GetFailedTargetEvents()
{
foreach (KeyValuePair<int, (string, string)> e in eventIdSourceNameNames)
{
if (e.Value == defaultEventSourceNameName)
{
yield return e;
}
}
}
public override void Dispose()
{
base.Dispose();

foreach (KeyValuePair<int, (string, string)> e in eventIdSourceNameNames)
{
string payloadString = eventData.Payload[i] != null ? eventData.Payload[i].ToString() : string.Empty;
Console.WriteLine($"\tName = \"{eventData.PayloadNames[i]}\" Value = \"{payloadString}\"");
WriteLine(e);
}
Console.WriteLine("\n");

SeenProvidersAndEvents.Add($"{eventData.EventSource.Name}");
SeenProvidersAndEvents.Add($"{eventData.EventSource.Name}/EVENTID({eventData.EventId})");
WriteLine("\n");
}

protected override void OnEventSourceCreated(EventSource eventSource)
{
if ((eventSource.Name == EventSourceName) && eventIdSourceNameNames.IsEmpty)
{
foreach (var targetEventId in targetEventIds)
{
eventIdSourceNameNames[targetEventId] = defaultEventSourceNameName;
}
EventsLeft = eventIdSourceNameNames.Count;

EnableEvents(eventSource, Level, EnableKeywords);
}
}
protected override void OnEventWritten(EventWrittenEventArgs eventWrittenEventArgs)
{
EventCount++;

KeyValuePair<int, (string SourceName, string Name)> e = new(
eventWrittenEventArgs.EventId,
(eventWrittenEventArgs.EventSource.Name, eventWrittenEventArgs.EventName ?? ""));

EventsLeft -= (eventIdSourceNameNames.TryGetValue(e.Key, out (string, string) value) && value == defaultEventSourceNameName) ? 1 : 0;
eventIdSourceNameNames[e.Key] = e.Value;

WriteLine(e);

WriteLine($"OSThreadId = {eventWrittenEventArgs.OSThreadId}", ConsoleColor.Yellow);

WriteLine($"TimeStamp: {eventWrittenEventArgs.TimeStamp.ToLocalTime()}");
WriteLine($"local time: {DateTime.Now}");
WriteLine($"Difference: {DateTime.UtcNow - eventWrittenEventArgs.TimeStamp}");

for (int i = 0; (i < eventWrittenEventArgs.PayloadNames?.Count) && (i < eventWrittenEventArgs.Payload?.Count); i++)
{
WriteLine($"{eventWrittenEventArgs.PayloadNames[i]} = {eventWrittenEventArgs.Payload[i]}", ConsoleColor.Magenta);
}

WriteLine("\n");
}

private void Write(object? o = null, ConsoleColor? consoleColor = null)
{
ConsoleColor foregroundColor = Console.ForegroundColor;

if (o is KeyValuePair<int, (string, string)> e)
{
Console.ForegroundColor = ConsoleColor.Cyan;
Console.Write(name);

Console.ForegroundColor = (e.Value != defaultEventSourceNameName) ? ConsoleColor.Green : ConsoleColor.Red;
}
else if (consoleColor != null)
{
Console.ForegroundColor = (ConsoleColor)consoleColor;
}
Console.Write(o);

Console.ForegroundColor = foregroundColor;
}
private void WriteLine(object? o = null, ConsoleColor? consoleColor = null)
{
Write(o, consoleColor);
Console.WriteLine();
}
}
}