diff --git a/src/libraries/System.Private.CoreLib/src/System/Threading/NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs b/src/libraries/System.Private.CoreLib/src/System/Threading/NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs index 76e67f5da79fd..3e9cb4e3e3d68 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Threading/NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Threading/NativeRuntimeEventSource.PortableThreadPool.NativeSinks.cs @@ -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, @@ -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) diff --git a/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs b/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs index 6322f16e6d004..e1f8d5558683f 100644 --- a/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs +++ b/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs @@ -10,58 +10,83 @@ 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); + } } } @@ -69,88 +94,199 @@ static int Main() 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 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 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 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> GetFailedTargetEvents() + { + foreach (KeyValuePair e in eventIdSourceNameNames) + { + if (e.Value == defaultEventSourceNameName) + { + yield return e; + } + } + } + public override void Dispose() + { + base.Dispose(); + + foreach (KeyValuePair 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 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 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(); } } }