[master] Enhance EventPipe tests (dotnet/coreclr#26322)

* Enhance EventPipe tests with better logging to better understand intermittent test failures that crop up in CI and can't be reproduced locally

* Remove unused field
* increase event count in attempt to give SampleProfiler thread a chance to fire

* Update logger to singleton so it can be used anywhere in the test
* updated logging for all tests
* reduced number of events sent to 100,000 instead of 1,000,000

Commit migrated from https://github.com/dotnet/coreclr/commit/47cd01e5979943b152d398ddcc319e4ed15ab05b

diff --git a/src/coreclr/tests/src/tracing/eventpipe/common/IpcTraceTest.cs b/src/coreclr/tests/src/tracing/eventpipe/common/IpcTraceTest.cs
index cebf4b1..41fef89 100644 (file)
--- a/src/coreclr/tests/src/tracing/eventpipe/common/IpcTraceTest.cs
+++ b/src/coreclr/tests/src/tracing/eventpipe/common/IpcTraceTest.cs
@@ -14,6 +14,25 @@ using Microsoft.Diagnostics.Tools.RuntimeClient;
 
 namespace Tracing.Tests.Common
 {
+    public class Logger
+    {
+        public static Logger logger = new Logger();
+        private TextWriter _log;
+        private Stopwatch _sw;
+        public Logger(TextWriter log = null)
+        {
+            _log = log ?? Console.Out;
+            _sw = new Stopwatch();
+        }
+
+        public void Log(string message)
+        {
+            if (!_sw.IsRunning)
+                _sw.Start();
+            _log.WriteLine($"{_sw.Elapsed.TotalSeconds,5:f1}s: {message}");
+        }
+    }
+
     public class ExpectedEventCount
     {
         // The acceptable percent error on the expected value
@@ -89,6 +108,7 @@ namespace Tracing.Tests.Common
         // and don't care about the number of events sent
         private Dictionary<string, ExpectedEventCount> _expectedEventCounts;
         private Dictionary<string, int> _actualEventCounts = new Dictionary<string, int>();
+        private int _droppedEvents = 0;
         private SessionConfiguration _sessionConfiguration;
 
         // A function to be called with the EventPipeEventSource _before_
@@ -108,39 +128,42 @@ namespace Tracing.Tests.Common
             _sessionConfiguration = sessionConfiguration?.InjectSentinel() ?? new SessionConfiguration(
                 circularBufferSizeMB: 1000,
                 format: EventPipeSerializationFormat.NetTrace,
-                providers: new List<Provider> { new Provider("Microsoft-Windows-DotNETRuntime") });
+                providers: new List<Provider> { 
+                    new Provider("Microsoft-Windows-DotNETRuntime"),
+                    new Provider("SentinelEventSource")
+                });
             _optionalTraceValidator = optionalTraceValidator;
         }
 
         private int Fail(string message = "")
         {
-            Console.WriteLine("Test FAILED!");
-            Console.WriteLine(message);
-            Console.WriteLine("Configuration:");
-            Console.WriteLine("{");
-            Console.WriteLine($"\tbufferSize: {_sessionConfiguration.CircularBufferSizeInMB},");
-            Console.WriteLine("\tproviders: [");
+            Logger.logger.Log("Test FAILED!");
+            Logger.logger.Log(message);
+            Logger.logger.Log("Configuration:");
+            Logger.logger.Log("{");
+            Logger.logger.Log($"\tbufferSize: {_sessionConfiguration.CircularBufferSizeInMB},");
+            Logger.logger.Log("\tproviders: [");
             foreach (var provider in _sessionConfiguration.Providers)
             {
-                Console.WriteLine($"\t\t{provider.ToString()},");
+                Logger.logger.Log($"\t\t{provider.ToString()},");
             }
-            Console.WriteLine("\t]");
-            Console.WriteLine("}\n");
-            Console.WriteLine("Expected:");
-            Console.WriteLine("{");
+            Logger.logger.Log("\t]");
+            Logger.logger.Log("}\n");
+            Logger.logger.Log("Expected:");
+            Logger.logger.Log("{");
             foreach (var (k, v) in _expectedEventCounts)
             {
-                Console.WriteLine($"\t\"{k}\" = {v}");
+                Logger.logger.Log($"\t\"{k}\" = {v}");
             }
-            Console.WriteLine("}\n");
+            Logger.logger.Log("}\n");
 
-            Console.WriteLine("Actual:");
-            Console.WriteLine("{");
+            Logger.logger.Log("Actual:");
+            Logger.logger.Log("{");
             foreach (var (k, v) in _actualEventCounts)
             {
-                Console.WriteLine($"\t\"{k}\" = {v}");
+                Logger.logger.Log($"\t\"{k}\" = {v}");
             }
-            Console.WriteLine("}");
+            Logger.logger.Log("}");
 
             return -1;
         }
@@ -148,9 +171,14 @@ namespace Tracing.Tests.Common
         private int Validate()
         {
             var processId = Process.GetCurrentProcess().Id;
+            Logger.logger.Log("Connecting to EventPipe...");
             var binaryReader = EventPipeClient.CollectTracing(processId, _sessionConfiguration, out var eventpipeSessionId);
             if (eventpipeSessionId == 0)
+            {
+                Logger.logger.Log("Failed to connect to EventPipe!");
                 return -1;
+            }
+            Logger.logger.Log($"Connected to EventPipe with sessionID '0x{eventpipeSessionId:x}'");
             
             // CollectTracing returns before EventPipe::Enable has returned, so the
             // the sources we want to listen for may not have been enabled yet.
@@ -158,10 +186,12 @@ namespace Tracing.Tests.Common
             ManualResetEvent sentinelEventReceived = new ManualResetEvent(false);
             var sentinelTask = new Task(() =>
             {
+                Logger.logger.Log("Started sending sentinel events...");
                 while (!sentinelEventReceived.WaitOne(50))
                 {
                     SentinelEventSource.Log.SentinelEvent();
                 }
+                Logger.logger.Log("Stopped sending sentinel events");
             });
             sentinelTask.Start();
 
@@ -169,37 +199,64 @@ namespace Tracing.Tests.Common
             Func<int> optionalTraceValidationCallback = null;
             var readerTask = new Task(() =>
             {
+                Logger.logger.Log("Creating EventPipeEventSource...");
                 source = new EventPipeEventSource(binaryReader);
+                Logger.logger.Log("EventPipeEventSource created");
+
                 source.Dynamic.All += (eventData) =>
                 {
-                    if (eventData.ProviderName == "SentinelEventSource")
-                    {
-                        sentinelEventReceived.Set();
-                    }
-                    else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _))
+                    try
                     {
-                        _actualEventCounts[eventData.ProviderName]++;
+                        if (eventData.ProviderName == "SentinelEventSource")
+                        {
+                            if (!sentinelEventReceived.WaitOne(0))
+                                Logger.logger.Log("Saw sentinel event");
+                            sentinelEventReceived.Set();
+                        }
+
+                        else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _))
+                        {
+                            _actualEventCounts[eventData.ProviderName]++;
+                        }
+                        else
+                        {
+                            Logger.logger.Log($"Saw new provider '{eventData.ProviderName}'");
+                            _actualEventCounts[eventData.ProviderName] = 1;
+                        }
                     }
-                    else
+                    catch (Exception e)
                     {
-                        _actualEventCounts[eventData.ProviderName] = 1;
+                        Logger.logger.Log("Exception in Dynamic.All callback " + e.ToString());
                     }
                 };
+                Logger.logger.Log("Dynamic.All callback registered");
 
                 if (_optionalTraceValidator != null)
                 {
+                    Logger.logger.Log("Running optional trace validator");
                     optionalTraceValidationCallback = _optionalTraceValidator(source);
+                    Logger.logger.Log("Finished running optional trace validator");
                 }
 
+                Logger.logger.Log("Starting stream processing...");
                 source.Process();
+                Logger.logger.Log("Stopping stream processing");
+                Logger.logger.Log($"Dropped {source.EventsLost} events");
             });
 
             readerTask.Start();
             sentinelEventReceived.WaitOne();
+
+            Logger.logger.Log("Starting event generating action...");
             _eventGeneratingAction();
+            Logger.logger.Log("Stopping event generating action");
+
+            Logger.logger.Log("Sending StopTracing command...");
             EventPipeClient.StopTracing(processId, eventpipeSessionId);
+            Logger.logger.Log("Finished StopTracing command");
 
             readerTask.Wait();
+            Logger.logger.Log("Reader task finished");
 
             foreach (var (provider, expectedCount) in _expectedEventCounts)
             {
@@ -218,6 +275,7 @@ namespace Tracing.Tests.Common
 
             if (optionalTraceValidationCallback != null)
             {
+                Logger.logger.Log("Validating optional callback...");
                 return optionalTraceValidationCallback();
             }
             else
@@ -232,19 +290,21 @@ namespace Tracing.Tests.Common
             SessionConfiguration? sessionConfiguration = null,
             Func<EventPipeEventSource, Func<int>> optionalTraceValidator = null)
         {
-            Console.WriteLine("TEST STARTING");
+            Logger.logger.Log("==TEST STARTING==");
             var test = new IpcTraceTest(expectedEventCounts, eventGeneratingAction, sessionConfiguration, optionalTraceValidator);
             try
             {
                 var ret = test.Validate();
                 if (ret == 100)
-                    Console.WriteLine("TEST PASSED!");
+                    Logger.logger.Log("==TEST FINISHED: PASSED!==");
+                else
+                    Logger.logger.Log("==TEST FINISHED: FAILED!==");
                 return ret;
             }
             catch (Exception e)
             {
-                Console.WriteLine("TEST FAILED!");
-                Console.WriteLine(e);
+                Logger.logger.Log(e.ToString());
+                Logger.logger.Log("==TEST FINISHED: FAILED!==");
                 return -1;
             }
         }

diff --git a/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/ExceptionThrown_V1.cs b/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/ExceptionThrown_V1.cs
index 2d493a1..fe0813f 100644 (file)
--- a/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/ExceptionThrown_V1.cs
+++ b/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/ExceptionThrown_V1.cs
@@ -35,6 +35,8 @@ namespace Tracing.Tests.ExceptionThrown_V1
         {
             for (int i = 0; i < 1000; i++)
             {
+                if (i % 100 == 0)
+                    Logger.logger.Log($"Thrown an excpetion {i} times...");
                 try
                 {
                     throw new ArgumentNullException("Throw ArgumentNullException");

diff --git a/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/GCStartStop.cs b/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/GCStartStop.cs
index bca9989..d50461c 100644 (file)
--- a/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/GCStartStop.cs
+++ b/src/coreclr/tests/src/tracing/eventpipe/eventsvalidation/GCStartStop.cs
@@ -15,7 +15,6 @@ namespace Tracing.Tests.GCStartStop
     {
         public static int Main(string[] args)
         {
-            Console.WriteLine("EventPipe validation test");
             var providers = new List<Provider>()
             {
                 new Provider("Microsoft-DotNETCore-SampleProfiler"),
@@ -23,7 +22,6 @@ namespace Tracing.Tests.GCStartStop
             };
             
             var configuration = new SessionConfiguration(circularBufferSizeMB: 1024, format: EventPipeSerializationFormat.NetTrace,  providers: providers);
-            Console.WriteLine("Validation method: RunAndValidateEventCounts");
             return IpcTraceTest.RunAndValidateEventCounts(_expectedEventCounts, _eventGeneratingAction, configuration, _DoesTraceContainEvents);
         }
 
@@ -36,27 +34,26 @@ namespace Tracing.Tests.GCStartStop
 
         private static Action _eventGeneratingAction = () => 
         {
-            Console.WriteLine("Event generating method: _eventGeneratingAction start");
             for (int i = 0; i < 1000; i++)
             {
+                if (i % 100 == 0)
+                    Logger.logger.Log($"Called GC.Collect() {i} times...");
                 ProviderValidation providerValidation = new ProviderValidation();
                 providerValidation = null;
                 GC.Collect();
             }
-            Console.WriteLine("Event generating method: _eventGeneratingAction end");
         };
 
         private static Func<EventPipeEventSource, Func<int>> _DoesTraceContainEvents = (source) => 
         {
-            Console.WriteLine("Callback method: _DoesTraceContainEvents");
             int GCStartEvents = 0;
             int GCEndEvents = 0;
             source.Clr.GCStart += (eventData) => GCStartEvents += 1;
             source.Clr.GCStop += (eventData) => GCEndEvents += 1;
             return () => {
-                Console.WriteLine("Event counts validation");
-                Console.WriteLine("GCStartEvents: " + GCStartEvents);
-                Console.WriteLine("GCEndEvents: " + GCEndEvents);
+                Logger.logger.Log("Event counts validation");
+                Logger.logger.Log("GCStartEvents: " + GCStartEvents);
+                Logger.logger.Log("GCEndEvents: " + GCEndEvents);
                 return GCStartEvents >= 1000 && GCEndEvents >= 1000 && GCStartEvents == GCEndEvents ? 100 : -1;
             };
         };

diff --git a/src/coreclr/tests/src/tracing/eventpipe/providervalidation/providervalidation.cs b/src/coreclr/tests/src/tracing/eventpipe/providervalidation/providervalidation.cs
index 2fd4693..f9e1a09 100644 (file)
--- a/src/coreclr/tests/src/tracing/eventpipe/providervalidation/providervalidation.cs
+++ b/src/coreclr/tests/src/tracing/eventpipe/providervalidation/providervalidation.cs
@@ -36,32 +36,28 @@ namespace Tracing.Tests.ProviderValidation
                 new Provider("Microsoft-DotNETCore-SampleProfiler")
             };
 
-            var tests = new int[] { 4, 10 }
-                .Select(x => (uint)Math.Pow(2, x))
-                .Select(bufferSize => new SessionConfiguration(circularBufferSizeMB: bufferSize, format: EventPipeSerializationFormat.NetTrace,  providers: providers))
-                .Select<SessionConfiguration, Func<int>>(configuration => () => IpcTraceTest.RunAndValidateEventCounts(_expectedEventCounts, _eventGeneratingAction, configuration));
+            var config = new SessionConfiguration(circularBufferSizeMB: (uint)Math.Pow(2, 10), format: EventPipeSerializationFormat.NetTrace,  providers: providers);
 
-            foreach (var test in tests)
-            {
-                var ret = test();
-                if (ret < 0)
-                    return ret;
-            }
-
-            return 100;
+            var ret = IpcTraceTest.RunAndValidateEventCounts(_expectedEventCounts, _eventGeneratingAction, config);
+            if (ret < 0)
+                return ret;
+            else
+                return 100;
         }
 
         private static Dictionary<string, ExpectedEventCount> _expectedEventCounts = new Dictionary<string, ExpectedEventCount>()
         {
-            { "MyEventSource", new ExpectedEventCount(1000, 0.30f) },
+            { "MyEventSource", new ExpectedEventCount(100_000, 0.30f) },
             { "Microsoft-Windows-DotNETRuntimeRundown", -1 },
             { "Microsoft-DotNETCore-SampleProfiler", -1 }
         };
 
         private static Action _eventGeneratingAction = () => 
         {
-            foreach (var _ in Enumerable.Range(0,1000))
+            for (int i = 0; i < 100_000; i++)
             {
+                if (i % 10_000 == 0)
+                    Logger.logger.Log($"Fired MyEvent {i:N0}/100,000 times...");
                 MyEventSource.Log.MyEvent();
             }
         };