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
// 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_
_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;
}
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.
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();
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)
{
if (optionalTraceValidationCallback != null)
{
+ Logger.logger.Log("Validating optional callback...");
return optionalTraceValidationCallback();
}
else
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;
}
}
{
public static int Main(string[] args)
{
- Console.WriteLine("EventPipe validation test");
var providers = new List<Provider>()
{
new Provider("Microsoft-DotNETCore-SampleProfiler"),
};
var configuration = new SessionConfiguration(circularBufferSizeMB: 1024, format: EventPipeSerializationFormat.NetTrace, providers: providers);
- Console.WriteLine("Validation method: RunAndValidateEventCounts");
return IpcTraceTest.RunAndValidateEventCounts(_expectedEventCounts, _eventGeneratingAction, configuration, _DoesTraceContainEvents);
}
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;
};
};
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();
}
};