private void Test_Write_Metric(Listener listener)
{
TestUtilities.CheckNoEventSourcesRunning("Start");
using (var logger = new MyEventSource())
{
var tests = new List <SubTest>();
/*************************************************************************/
tests.Add(new SubTest("Log 1 event",
delegate()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 event in single period",
delegate()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
logger.Request(25);
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 2, 31, 6, 25, 37);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 event in two periods",
delegate()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
Thread.Sleep(1500); // Sleep for 1.5 seconds
logger.Request(25);
Thread.Sleep(1000); // Sleep for 1 seconds (at time = 2.5 second exactly two messages should be received)
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37);
ValidateSingleEventCounter(evts[2], "Request", 1, 25, 0, 25, 25);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 different events in a period",
delegate()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(25);
logger.Error();
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 25, 0, 25, 25);
ValidateSingleEventCounter(evts[1], "Error", 1, 1, 0, 1, 1);
}));
/*************************************************************************/
EventTestHarness.RunTests(tests, listener, logger);
}
TestUtilities.CheckNoEventSourcesRunning("Stop");
}
private void Test_Write_Metric(Listener listener)
{
Console.WriteLine("Version of Runtime {0}", Environment.Version);
Console.WriteLine("Version of OS {0}", Environment.OSVersion);
TestUtilities.CheckNoEventSourcesRunning("Start");
using (var logger = new MyEventSource())
{
var tests = new List <SubTest>();
/*************************************************************************/
tests.Add(new SubTest("Log 1 event, explicit poll at end",
delegate()
{
listener.EnableTimer(logger, 1); // Set to poll every second, but we dont actually care because the test ends before that.
logger.Request(5);
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
// There will be two events (request and error) for time 0 and 2 more at 1 second and 2 more when we shut it off.
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 1, 5, 0, 5, 5);
ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 events, explicit poll at end",
delegate()
{
listener.EnableTimer(logger, 1); // Set to poll every second, but we dont actually care because the test ends before that.
logger.Request(5);
logger.Request(10);
listener.EnableTimer(logger, 0); // poll
},
delegate(List <Event> evts)
{
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10);
ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 3 events in two polling periods (explicit polling)",
delegate()
{
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
logger.Request(5);
logger.Request(10);
logger.Error();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
logger.Request(8);
logger.Error();
logger.Error();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
},
delegate(List <Event> evts)
{
Assert.Equal(6, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10);
ValidateSingleEventCounter(evts[3], "Error", 1, 1, 0, 1, 1);
ValidateSingleEventCounter(evts[4], "Request", 1, 8, 0, 8, 8);
ValidateSingleEventCounter(evts[5], "Error", 2, 1, 0, 1, 1);
}));
/*************************************************************************/
tests.Add(new SubTest("Log multiple events in",
delegate()
{
listener.EnableTimer(logger, .1); /* Poll every .1 s */
// logs at 0 seconds because of EnableTimer command
Sleep(100);
logger.Request(1);
Sleep(100);
logger.Request(2);
logger.Error();
Sleep(100);
logger.Request(4);
Sleep(100);
logger.Error();
logger.Request(8);
Sleep(100);
logger.Request(16);
Sleep(200);
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
int requestCount = 0;
float requestSum = 0;
float requestMin = float.MaxValue;
float requestMax = float.MinValue;
int errorCount = 0;
float errorSum = 0;
float errorMin = float.MaxValue;
float errorMax = float.MinValue;
float timeSum = 0;
for (int j = 0; j < evts.Count; j += 2)
{
var requestPayload = ValidateEventHeaderAndGetPayload(evts[j]);
Assert.Equal("Request", requestPayload["Name"]);
var count = (int)requestPayload["Count"];
requestCount += count;
if (count > 0)
{
requestSum += (float)requestPayload["Mean"] * count;
}
requestMin = Math.Min(requestMin, (float)requestPayload["Min"]);
requestMax = Math.Max(requestMax, (float)requestPayload["Max"]);
float requestIntevalSec = (float)requestPayload["IntervalSec"];
var errorPayload = ValidateEventHeaderAndGetPayload(evts[j + 1]);
Assert.Equal("Error", errorPayload["Name"]);
count = (int)errorPayload["Count"];
errorCount += count;
if (count > 0)
{
errorSum += (float)errorPayload["Mean"] * count;
}
errorMin = Math.Min(errorMin, (float)errorPayload["Min"]);
errorMax = Math.Max(errorMax, (float)errorPayload["Max"]);
float errorIntevalSec = (float)requestPayload["IntervalSec"];
Assert.Equal(requestIntevalSec, errorIntevalSec);
timeSum += requestIntevalSec;
}
Assert.Equal(requestCount, 5);
Assert.Equal(requestSum, 31);
Assert.Equal(requestMin, 1);
Assert.Equal(requestMax, 16);
Assert.Equal(errorCount, 2);
Assert.Equal(errorSum, 2);
Assert.Equal(errorMin, 1);
Assert.Equal(errorMax, 1);
Assert.True(.4 < timeSum, $"FAILURE: .4 < {timeSum}"); // We should have at least 400 msec
Assert.True(timeSum < 2, $"FAILURE: {timeSum} < 2"); // But well under 2 sec.
// Do all the things that depend on the count of events last so we know everything else is sane
Assert.True(4 <= evts.Count, "We expect two metrices at the begining trigger and two at the end trigger. evts.Count = " + evts.Count);
Assert.True(evts.Count % 2 == 0, "We expect two metrics for every trigger. evts.Count = " + evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
// We expect the timer to have gone off at least twice, plus the explicit poll at the begining and end.
// Each one fires two events (one for requests, one for errors). so that is (2 + 2)*2 = 8
// We expect about 5 timer requests, but we don't get picky about the exact count
// We don't expect more than say 9 timer request so that is (2 + 9) * 2 = 22
Assert.True(8 <= evts.Count, $"FAILURE: 8 <= {evts.Count}");
Assert.True(evts.Count <= 22, $"FAILURE: {evts.Count} <= 22");
}));
/*************************************************************************/
// TODO expose Dispose() method and activate this test.
#if EventCounterDispose
tests.Add(new SubTest("EventCounter.Dispose()",
delegate()
{
// Creating and destroying
var myCounter = new EventCounter("counter for a transient object", logger);
myCounter.WriteMetric(10);
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
myCounter.Dispose();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
},
delegate(List <Event> evts)
{
Assert.Equal(5, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0);
ValidateSingleEventCounter(evts[2], "counter for a transient object", 1, 10, 0, 10, 10);
ValidateSingleEventCounter(evts[3], "Request", 0, 0, 0, 0, 0);
ValidateSingleEventCounter(evts[4], "Error", 0, 0, 0, 0, 0);
}));
#endif
/*************************************************************************/
EventTestHarness.RunTests(tests, listener, logger);
}
TestUtilities.CheckNoEventSourcesRunning("Stop");
}
private void Test_Write_Metric(Listener listener)
{
TestUtilities.CheckNoEventSourcesRunning("Start");
using (var logger = new MyEventSource())
{
var tests = new List <SubTest>();
/*************************************************************************/
tests.Add(new SubTest("EventCounter: Log 1 event, explicit poll at end",
delegate()
{
listener.EnableTimer(logger, 1); // Set to poll every second, but we dont actually care because the test ends before that.
logger.Request(5);
listener.EnableTimer(logger, 0);
},
delegate(List <Event> evts)
{
// There will be two events (request and error) for time 0 and 2 more at 1 second and 2 more when we shut it off.
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 1, 5, 0, 5, 5);
ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
}));
/*************************************************************************/
tests.Add(new SubTest("EventCounter: Log 2 events, explicit poll at end",
delegate()
{
listener.EnableTimer(logger, 1); // Set to poll every second, but we dont actually care because the test ends before that.
logger.Request(5);
logger.Request(10);
listener.EnableTimer(logger, 0); // poll
},
delegate(List <Event> evts)
{
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10);
ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
}));
/*************************************************************************/
tests.Add(new SubTest("EventCounter: Log 3 events in two polling periods (explicit polling)",
delegate()
{
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
logger.Request(5);
logger.Request(10);
logger.Error();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
logger.Request(8);
logger.Error();
logger.Error();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
},
delegate(List <Event> evts)
{
Assert.Equal(6, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10);
ValidateSingleEventCounter(evts[3], "Error", 1, 1, 0, 1, 1);
ValidateSingleEventCounter(evts[4], "Request", 1, 8, 0, 8, 8);
ValidateSingleEventCounter(evts[5], "Error", 2, 1, 0, 1, 1);
}));
/*************************************************************************/
int num100msecTimerTicks = 0;
tests.Add(new SubTest("EventCounter: Log multiple events in multiple periods",
delegate()
{
// We have had problems with timer ticks not being called back 100% reliably.
// However timers really don't have a strong guarantee (only that the happen eventually)
// So what we do is create a timer callback that simply counts the number of callbacks.
// This acts as a marker to show whether the timer callbacks are happening promptly.
// If we don't get enough of these tick callbacks then we don't require EventCounter to
// be sending periodic callbacks either.
num100msecTimerTicks = 0;
using (var timer = new System.Threading.Timer(delegate(object state) { num100msecTimerTicks++; EventTestHarness.LogWriteLine("Tick"); }, null, 100, 100))
{
listener.EnableTimer(logger, .1); /* Poll every .1 s */
// logs at 0 seconds because of EnableTimer command
Sleep(100);
logger.Request(1);
Sleep(100);
logger.Request(2);
logger.Error();
Sleep(100);
logger.Request(4);
Sleep(100);
logger.Request(8);
logger.Error();
Sleep(100);
logger.Request(16);
Sleep(220);
listener.EnableTimer(logger, 0);
}
},
delegate(List <Event> evts)
{
int requestCount = 0;
float requestSum = 0;
float requestMin = float.MaxValue;
float requestMax = float.MinValue;
int errorCount = 0;
float errorSum = 0;
float errorMin = float.MaxValue;
float errorMax = float.MinValue;
float timeSum = 0;
for (int j = 0; j < evts.Count; j += 2)
{
var requestPayload = ValidateEventHeaderAndGetPayload(evts[j]);
Assert.Equal("Request", requestPayload["Name"]);
var count = (int)requestPayload["Count"];
requestCount += count;
if (count > 0)
{
requestSum += (float)requestPayload["Mean"] * count;
}
requestMin = Math.Min(requestMin, (float)requestPayload["Min"]);
requestMax = Math.Max(requestMax, (float)requestPayload["Max"]);
float requestIntervalSec = (float)requestPayload["IntervalSec"];
var errorPayload = ValidateEventHeaderAndGetPayload(evts[j + 1]);
Assert.Equal("Error", errorPayload["Name"]);
count = (int)errorPayload["Count"];
errorCount += count;
if (count > 0)
{
errorSum += (float)errorPayload["Mean"] * count;
}
errorMin = Math.Min(errorMin, (float)errorPayload["Min"]);
errorMax = Math.Max(errorMax, (float)errorPayload["Max"]);
float errorIntervalSec = (float)requestPayload["IntervalSec"];
Assert.Equal(requestIntervalSec, errorIntervalSec);
timeSum += requestIntervalSec;
}
EventTestHarness.LogWriteLine("Validating: Count={0} RequestSum={1:n3} TimeSum={2:n3} ", evts.Count, requestSum, timeSum);
Assert.Equal(5, requestCount);
Assert.Equal(31, requestSum);
Assert.Equal(1, requestMin);
Assert.Equal(16, requestMax);
Assert.Equal(2, errorCount);
Assert.Equal(2, errorSum);
Assert.Equal(1, errorMin);
Assert.Equal(1, errorMax);
Assert.True(.4 < timeSum, $"FAILURE: .4 < {timeSum}"); // We should have at least 400 msec
Assert.True(timeSum < 2, $"FAILURE: {timeSum} < 2"); // But well under 2 sec.
// Do all the things that depend on the count of events last so we know everything else is sane
Assert.True(4 <= evts.Count, "We expect two metrics at the beginning trigger and two at the end trigger. evts.Count = " + evts.Count);
Assert.True(evts.Count % 2 == 0, "We expect two metrics for every trigger. evts.Count = " + evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
// We should always get the unconditional callback at the start and end of the trace.
Assert.True(4 <= evts.Count, $"FAILURE EventCounter Multi-event: 4 <= {evts.Count} ticks: {num100msecTimerTicks} thread: {Environment.CurrentManagedThreadId}");
// We expect the timer to have gone off at least twice, plus the explicit poll at the beginning and end.
// Each one fires two events (one for requests, one for errors). so that is (2 + 2)*2 = 8
// We expect about 7 timer requests, but we don't get picky about the exact count
// Putting in a generous buffer, we double 7 to say we don't expect more than 14 timer fires
// so that is (2 + 14) * 2 = 32
if (num100msecTimerTicks > 3) // We seem to have problems with timer events going off 100% reliably. To avoid failures here we only check if in the 700 msec test we get at least 3 100 msec ticks.
{
Assert.True(8 <= evts.Count, $"FAILURE: 8 <= {evts.Count}");
}
Assert.True(evts.Count <= 32, $"FAILURE: {evts.Count} <= 32");
}));
/*************************************************************************/
tests.Add(new SubTest("EventCounter: Dispose()",
delegate()
{
// Creating and destroying
var myCounter = new EventCounter("counter for a transient object", logger);
myCounter.WriteMetric(10);
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
myCounter.Dispose();
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
},
delegate(List <Event> evts)
{
// The static counters (Request and Error), should not log any counts and stay at zero.
// The new counter will exist for the first poll but will not exist for the second.
Assert.Equal(5, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[2], "counter for a transient object", 1, 10, 0, 10, 10);
ValidateSingleEventCounter(evts[3], "Request", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
ValidateSingleEventCounter(evts[4], "Error", 0, 0, 0, float.PositiveInfinity, float.NegativeInfinity);
}));
/*************************************************************************/
EventTestHarness.RunTests(tests, listener, logger);
}
TestUtilities.CheckNoEventSourcesRunning("Stop");
}
private void Test_Write_Metric(Listener listener)
{
TestUtilities.CheckNoEventSourcesRunning("Start");
using (var logger = new MyEventSource())
{
var tests = new List<SubTest>();
/*************************************************************************/
tests.Add(new SubTest("Log 1 event",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate (List<Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 event in single period",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
logger.Request(25);
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate (List<Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 2, 31, 6, 25, 37);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 event in two periods",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
Thread.Sleep(1500); // Sleep for 1.5 seconds
logger.Request(25);
Thread.Sleep(1000); // Sleep for 1 seconds (at time = 2.5 second exactly two messages should be received)
listener.EnableTimer(logger, 0);
},
delegate (List<Event> evts)
{
Assert.Equal(4, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37);
ValidateSingleEventCounter(evts[2], "Request", 1, 25, 0, 25, 25);
}));
/*************************************************************************/
tests.Add(new SubTest("Log 2 different events in a period",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(25);
logger.Error();
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
},
delegate (List<Event> evts)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 25, 0, 25, 25);
ValidateSingleEventCounter(evts[1], "Error", 1, 1, 0, 1, 1);
}));
/*************************************************************************/
EventTestHarness.RunTests(tests, listener, logger);
}
TestUtilities.CheckNoEventSourcesRunning("Stop");
}