Imported Upstream version 5.10.0.47

Former-commit-id: d0813289fa2d35e1f8ed77530acb4fb1df441bc0
This commit is contained in:
Xamarin Public Jenkins (auto-signing)
2018-01-24 17:04:36 +00:00
parent 88ff76fe28
commit e46a49ecf1
5927 changed files with 226314 additions and 129848 deletions

View File

@@ -6,6 +6,5 @@
<AssemblyKey>MSFT</AssemblyKey>
<IsNETCoreApp>true</IsNETCoreApp>
<IsUAP>true</IsUAP>
<IsNetFxNETStandard>true</IsNetFxNETStandard>
</PropertyGroup>
</Project>

View File

@@ -34,7 +34,8 @@ public sealed class MinimalEventCounterSource : EventSource
// using an EventAttribute for this method
// 2. Each counter supports a single float value, so conceptually it maps to a single
// measurement in the code.
// 3. You don't have to have
// 3. You don't have to have log with WriteEvent if you don't think you will ever care about details
// of individual requests (that counter data is sufficient).
WriteEvent(1, url, elapsedMSec); // This logs it to the event stream if events are on.
this.requestCounter.WriteMetric(elapsedMSec); // This adds it to the PerfCounter called 'Request' if PerfCounters are on
}
@@ -48,10 +49,10 @@ So, with that, we logged the metric to the `EventCounter`, but unless we can act
There is an extra keyword that you will need to specify the turn on the EventCounters.
```
PerfView /onlyProviders=*Samples-EventCounterDemos-Minimal:**EventCounterIntervalSec=1** collect
PerfView /onlyProviders=*Samples-EventCounterDemos-Minimal:EventCounterIntervalSec=1 collect
```
Note the bold part about `EventCounterIntervalSec`, that indicate the frequency of the sampling.
Note the part about `EventCounterIntervalSec`, that indicate the frequency of the sampling.
As usual, turn on PerfView, and then run the sample code, we will have something like this
@@ -69,7 +70,7 @@ Notice that, this command also log the events, so we will get both the events an
<img src="PerfViewCapture_Events.png" alt="PerfView Capture of Event Traces" title="PerfView Capture of Event Traces" />
As we mentioned, to avoid overhead, sometimes we will want just the counters. This command can be used to log <em>only</em> the counters:
As we mentioned, to avoid overhead, sometimes we will want just the counters. This command can be used to log *only* the counters:
```
PerfView /onlyProviders=*Samples-EventCounterDemos-Minimal:*:Critical:EventCounterIntervalSec=1 collect

View File

@@ -4,7 +4,6 @@
<BuildConfigurations>
netcoreapp;
uap;
netfx;
</BuildConfigurations>
</PropertyGroup>
</Project>

View File

@@ -54,9 +54,10 @@ namespace System.Diagnostics.Tracing
public bool DisableEvent(int eventId) { throw null; }
public bool EnableEvent(int eventId) { throw null; }
}
public class EventCounter {
public class EventCounter : IDisposable {
public EventCounter(string name, EventSource eventSource) { }
public void WriteMetric(float value) { }
public void Dispose() { }
}
[System.AttributeUsageAttribute((System.AttributeTargets)(12), Inherited = false)]
public partial class EventDataAttribute : System.Attribute

View File

@@ -5,12 +5,12 @@
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<ProjectGuid>{0D8C8BAE-E5A5-4E9F-B101-3D18BD81D261}</ProjectGuid>
<IsPartialFacadeAssembly Condition="'$(TargetGroup)' == 'netfx'">true</IsPartialFacadeAssembly>
<DefineConstants Condition="'$(TargetGroup)' == 'netcoreapp'">$(DefineConstants);FEATURE_ETLEVENTS</DefineConstants>
<DefineConstants Condition="'$(TargetGroup)' == 'netcoreapp'">$(DefineConstants);FEATURE_ETLEVENTS</DefineConstants>
<!-- CS0067: unused event, reference assembly does not care -->
<NoWarn>$(NoWarn);0067</NoWarn>
</PropertyGroup>
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netfx-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netfx-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'uap-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'uap-Release|AnyCPU'" />
<ItemGroup>

View File

@@ -6,7 +6,6 @@
uapaot-Windows_NT;
netcoreapp-Windows_NT;
netcoreapp-Unix;
netfx-Windows_NT;
</BuildConfigurations>
</PropertyGroup>
</Project>

View File

@@ -8,15 +8,13 @@
<!-- CSC adds a typeforward for the internal nested type EventSource.EventMetadata but
GenFacades doesn't consider this as a viable target for a typeforward since it's internal -->
<GenFacadesIgnoreMissingTypes Condition="'$(TargetGroup)' == 'netfx'">true</GenFacadesIgnoreMissingTypes>
<DefineContants Condition="'$(TargetGroup)' != 'netfx'">$(DefineConstants);SUPPORTS_EVENTCOMMANDEXECUTED</DefineContants>
<DefineConstants Condition="'$(TargetGroup)' == 'netfx'">$(DefineConstants);NO_EVENTCOMMANDEXECUTED_SUPPORT</DefineConstants>
</PropertyGroup>
<!-- Default configurations to help VS understand the options -->
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Unix-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Unix-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Windows_NT-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Windows_NT-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netfx-Windows_NT-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netfx-Windows_NT-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'uap-Windows_NT-Debug|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'uap-Windows_NT-Release|AnyCPU'" />
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'uapaot-Windows_NT-Debug|AnyCPU'" />
@@ -30,6 +28,7 @@
</ItemGroup>
<ItemGroup Condition="'$(TargetGroup)' == 'netfx'">
<Reference Include="mscorlib" />
<Reference Include="System" />
</ItemGroup>
<Import Project="$([MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildThisFileDirectory), dir.targets))\dir.targets" />
</Project>

View File

@@ -25,10 +25,12 @@ namespace System.Diagnostics.Tracing
/// See https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestEventCounter.cs
/// which shows tests, which are also useful in seeing actual use.
/// </summary>
public class EventCounter
public class EventCounter : IDisposable
{
/// <summary>
/// Initializes a new instance of the <see cref="EventCounter"/> class.
/// EVentCounters live as long as the EventSource that they are attached to unless they are
/// explicitly Disposed.
/// </summary>
/// <param name="name">The name.</param>
/// <param name="eventSource">The event source.</param>
@@ -46,11 +48,15 @@ namespace System.Diagnostics.Tracing
InitializeBuffer();
_name = name;
EventCounterGroup.AddEventCounter(eventSource, this);
_group = EventCounterGroup.GetEventCounterGroup(eventSource);
_group.Add(this);
_min = float.PositiveInfinity;
_max = float.NegativeInfinity;
}
/// <summary>
/// Writes the metric.
/// Writes 'value' to the stream of values tracked by the counter. This updates the sum and other statistics that will
/// be logged on the next timer interval.
/// </summary>
/// <param name="value">The value.</param>
public void WriteMetric(float value)
@@ -58,9 +64,30 @@ namespace System.Diagnostics.Tracing
Enqueue(value);
}
/// <summary>
/// Removes the counter from set that the EventSource will report on. After being disposed, this
/// counter will do nothing and its resource will be reclaimed if all references to it are removed.
/// If an EventCounter is not explicitly disposed it will be cleaned up automatically when the
/// EventSource it is attached to dies.
/// </summary>
public void Dispose()
{
var group = _group;
if (group != null)
{
group.Remove(this);
_group = null;
}
}
public override string ToString()
{
return "EventCounter '" + _name + "' Count " + _count + " Mean " + (((double)_sum) / _count).ToString("n3");
}
#region private implementation
private readonly string _name;
private EventCounterGroup _group;
#region Buffer Management
@@ -68,9 +95,12 @@ namespace System.Diagnostics.Tracing
private const int BufferedSize = 10;
private const float UnusedBufferSlotValue = float.NegativeInfinity;
private const int UnsetIndex = -1;
private volatile float[] _bufferedValues;
private volatile float[] _bufferedValues;
private volatile int _bufferedValuesIndex;
// arbitrarily we use _bufferfValues as the lock object.
private object MyLock { get { return _bufferedValues; } }
private void InitializeBuffer()
{
_bufferedValues = new float[BufferedSize];
@@ -92,10 +122,8 @@ namespace System.Diagnostics.Tracing
{
// It is possible that two threads both think the buffer is full, but only one get to actually flush it, the other
// will eventually enter this code path and potentially calling Flushing on a buffer that is not full, and that's okay too.
lock (_bufferedValues)
{
lock (MyLock) // Lock the counter
Flush();
}
i = 0;
}
@@ -110,6 +138,7 @@ namespace System.Diagnostics.Tracing
private void Flush()
{
Debug.Assert(Monitor.IsEntered(MyLock));
for (int i = 0; i < _bufferedValues.Length; i++)
{
var value = Interlocked.Exchange(ref _bufferedValues[i], UnusedBufferSlotValue);
@@ -135,31 +164,36 @@ namespace System.Diagnostics.Tracing
private void OnMetricWritten(float value)
{
Debug.Assert(Monitor.IsEntered(MyLock));
_sum += value;
_sumSquared += value * value;
if (_count == 0 || value > _max)
{
if (value > _max)
_max = value;
}
if (_count == 0 || value < _min)
{
if (value < _min)
_min = value;
}
_count++;
}
internal EventCounterPayload GetEventCounterPayload()
{
lock (_bufferedValues)
lock (MyLock) // Lock the counter
{
Flush();
EventCounterPayload result = new EventCounterPayload();
result.Name = _name;
result.Count = _count;
result.Mean = _sum / _count;
result.StandardDeviation = (float)Math.Sqrt(_sumSquared / _count - _sum * _sum / _count / _count);
if (0 < _count)
{
result.Mean = _sum / _count;
result.StandardDeviation = (float)Math.Sqrt(_sumSquared / _count - _sum * _sum / _count / _count);
}
else
{
result.Mean = 0;
result.StandardDeviation = 0;
}
result.Min = _min;
result.Max = _max;
ResetStatistics();
@@ -169,11 +203,12 @@ namespace System.Diagnostics.Tracing
private void ResetStatistics()
{
Debug.Assert(Monitor.IsEntered(MyLock));
_count = 0;
_sum = 0;
_sumSquared = 0;
_min = 0;
_max = 0;
_min = float.PositiveInfinity;
_max = float.NegativeInfinity;
}
#endregion // Statistics Calculation
@@ -228,30 +263,50 @@ namespace System.Diagnostics.Tracing
#endregion // Implementation of the IEnumerable interface
}
internal class EventCounterGroup : IDisposable
internal class EventCounterGroup
{
private readonly EventSource _eventSource;
private readonly int _eventSourceIndex;
private readonly List<EventCounter> _eventCounters;
internal EventCounterGroup(EventSource eventSource, int eventSourceIndex)
internal EventCounterGroup(EventSource eventSource)
{
_eventSource = eventSource;
_eventSourceIndex = eventSourceIndex;
_eventCounters = new List<EventCounter>();
RegisterCommandCallback();
}
private void Add(EventCounter eventCounter)
internal void Add(EventCounter eventCounter)
{
_eventCounters.Add(eventCounter);
lock (this) // Lock the EventCounterGroup
_eventCounters.Add(eventCounter);
}
internal void Remove(EventCounter eventCounter)
{
lock (this) // Lock the EventCounterGroup
_eventCounters.Remove(eventCounter);
}
#region EventSource Command Processing
private void RegisterCommandCallback()
{
#if SUPPORTS_EVENTCOMMANDEXECUTED
// Old destktop runtimes don't have this
#if NO_EVENTCOMMANDEXECUTED_SUPPORT
// We could not build against the API that had the EventCommandExecuted but maybe it is there are runtime.
// use reflection to try to get it.
System.Reflection.MethodInfo method = typeof(EventSource).GetMethod("add_EventCommandExecuted");
if (method != null)
{
method.Invoke(_eventSource, new object[] { (EventHandler<EventCommandEventArgs>)OnEventSourceCommand });
}
else
{
string msg = "EventCounterError: Old Runtime that does not support EventSource.EventCommandExecuted. EventCounters not Supported";
_eventSource.Write(msg);
Debug.WriteLine(msg);
}
#else
_eventSource.EventCommandExecuted += OnEventSourceCommand;
#endif
}
@@ -264,7 +319,15 @@ namespace System.Diagnostics.Tracing
float value;
if (e.Arguments.TryGetValue("EventCounterIntervalSec", out valueStr) && float.TryParse(valueStr, out value))
{
EnableTimer(value);
// Recursion through EventSource callbacks possible. When we enable the timer
// we synchonously issue a EventSource.Write event, which in turn can call back
// to user code (in an EventListener) while holding this lock. This is dangerous
// because it mean this code might inadvertantly participate in a lock loop.
// The scenario seems very unlikely so we ignore that problem for now.
lock (this) // Lock the EventCounterGroup
{
EnableTimer(value);
}
}
}
}
@@ -273,42 +336,42 @@ namespace System.Diagnostics.Tracing
#region Global EventCounterGroup Array management
private static EventCounterGroup[] s_eventCounterGroups;
internal static void AddEventCounter(EventSource eventSource, EventCounter eventCounter)
{
int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource);
EventCounterGroup.EnsureEventSourceIndexAvailable(eventSourceIndex);
EventCounterGroup eventCounterGroup = GetEventCounterGroup(eventSource);
eventCounterGroup.Add(eventCounter);
}
// We need eventCounters to 'attach' themselves to a particular EventSource.
// this table provides the mapping from EventSource -> EventCounterGroup
// which represents this 'attached' information.
private static WeakReference<EventCounterGroup>[] s_eventCounterGroups;
private static readonly object s_eventCounterGroupsLock = new object();
private static void EnsureEventSourceIndexAvailable(int eventSourceIndex)
{
Debug.Assert(Monitor.IsEntered(s_eventCounterGroupsLock));
if (EventCounterGroup.s_eventCounterGroups == null)
{
EventCounterGroup.s_eventCounterGroups = new EventCounterGroup[eventSourceIndex + 1];
EventCounterGroup.s_eventCounterGroups = new WeakReference<EventCounterGroup>[eventSourceIndex + 1];
}
else if (eventSourceIndex >= EventCounterGroup.s_eventCounterGroups.Length)
{
EventCounterGroup[] newEventCounterGroups = new EventCounterGroup[eventSourceIndex + 1];
WeakReference<EventCounterGroup>[] newEventCounterGroups = new WeakReference<EventCounterGroup>[eventSourceIndex + 1];
Array.Copy(EventCounterGroup.s_eventCounterGroups, 0, newEventCounterGroups, 0, EventCounterGroup.s_eventCounterGroups.Length);
EventCounterGroup.s_eventCounterGroups = newEventCounterGroups;
}
}
private static EventCounterGroup GetEventCounterGroup(EventSource eventSource)
internal static EventCounterGroup GetEventCounterGroup(EventSource eventSource)
{
int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource);
EventCounterGroup result = EventCounterGroup.s_eventCounterGroups[eventSourceIndex];
if (result == null)
lock (s_eventCounterGroupsLock)
{
result = new EventCounterGroup(eventSource, eventSourceIndex);
EventCounterGroup.s_eventCounterGroups[eventSourceIndex] = result;
int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource);
EnsureEventSourceIndexAvailable(eventSourceIndex);
WeakReference<EventCounterGroup> weakRef = EventCounterGroup.s_eventCounterGroups[eventSourceIndex];
EventCounterGroup ret = null;
if (weakRef == null || !weakRef.TryGetTarget(out ret))
{
ret = new EventCounterGroup(eventSource);
EventCounterGroup.s_eventCounterGroups[eventSourceIndex] = new WeakReference<EventCounterGroup>(ret);
}
return ret;
}
return result;
}
#endregion // Global EventCounterGroup Array management
@@ -319,57 +382,69 @@ namespace System.Diagnostics.Tracing
private int _pollingIntervalInMilliseconds;
private Timer _pollingTimer;
private void DisposeTimer()
{
Debug.Assert(Monitor.IsEntered(this));
if (_pollingTimer != null)
{
_pollingTimer.Dispose();
_pollingTimer = null;
}
}
private void EnableTimer(float pollingIntervalInSeconds)
{
if (pollingIntervalInSeconds == 0)
Debug.Assert(Monitor.IsEntered(this));
if (pollingIntervalInSeconds <= 0)
{
if (_pollingTimer != null)
{
_pollingTimer.Dispose();
_pollingTimer = null;
}
DisposeTimer();
_pollingIntervalInMilliseconds = 0;
}
else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds < _pollingIntervalInMilliseconds)
else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds * 1000 < _pollingIntervalInMilliseconds)
{
Debug.WriteLine("Polling interval changed at " + DateTime.UtcNow.ToString("mm.ss.ffffff"));
_pollingIntervalInMilliseconds = (int)(pollingIntervalInSeconds * 1000);
if (_pollingTimer != null)
{
_pollingTimer.Dispose();
_pollingTimer = null;
}
_timeStampSinceCollectionStarted = DateTime.Now;
DisposeTimer();
_timeStampSinceCollectionStarted = DateTime.UtcNow;
_pollingTimer = new Timer(OnTimer, null, _pollingIntervalInMilliseconds, _pollingIntervalInMilliseconds);
}
// Always fire the timer event (so you see everything up to this time).
OnTimer(null);
}
private void OnTimer(object state)
{
if (_eventSource.IsEnabled())
Debug.WriteLine("Timer fired at " + DateTime.UtcNow.ToString("mm.ss.ffffff"));
lock (this) // Lock the EventCounterGroup
{
DateTime now = DateTime.Now;
TimeSpan elapsed = now - _timeStampSinceCollectionStarted;
lock (_pollingTimer)
if (_eventSource.IsEnabled())
{
DateTime now = DateTime.UtcNow;
TimeSpan elapsed = now - _timeStampSinceCollectionStarted;
foreach (var eventCounter in _eventCounters)
{
EventCounterPayload payload = eventCounter.GetEventCounterPayload();
payload.IntervalSec = (float)elapsed.TotalSeconds;
_eventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new { Payload = payload });
_eventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new PayloadType(payload));
}
_timeStampSinceCollectionStarted = now;
}
else
{
DisposeTimer();
}
}
else
{
_pollingTimer.Dispose();
_pollingTimer = null;
EventCounterGroup.s_eventCounterGroups[_eventSourceIndex] = null;
}
}
/// <summary>
/// This is the payload that is sent in the with EventSource.Write
/// </summary>
[EventData]
class PayloadType
{
public PayloadType(EventCounterPayload payload) { Payload = payload; }
public EventCounterPayload Payload { get; set; }
}
#region PCL timer hack
@@ -409,43 +484,15 @@ namespace System.Diagnostics.Tracing
#endregion // Timer Processing
#region Implementation of the IDisposable interface
private bool _disposed = false;
public void Dispose()
{
Dispose(true);
}
protected virtual void Dispose(bool disposing)
{
if (_disposed)
{
return;
}
if (disposing)
{
if (_pollingTimer != null)
{
_pollingTimer.Dispose();
_pollingTimer = null;
}
}
_disposed = true;
}
#endregion // Implementation of the IDisposable interface
}
// This class a work-around because .NET V4.6.2 did not make EventSourceIndex public (it was only protected)
// We make this helper class to get around that protection. We want V4.6.3 to make this public at which
// point this class is no longer needed and can be removed.
internal class EventListenerHelper : EventListener {
internal class EventListenerHelper : EventListener
{
public new static int EventSourceIndex(EventSource eventSource) { return EventListener.EventSourceIndex(eventSource); }
protected override void OnEventWritten(EventWrittenEventArgs eventData) { } // override abstact methods to keep compiler happy
protected override void OnEventWritten(EventWrittenEventArgs eventData) { } // override abstract methods to keep compiler happy
}
#endregion // internal supporting classes

View File

@@ -6,6 +6,7 @@ using System.Diagnostics.Tracing;
using Xunit;
using System;
using System.Collections.Generic;
using System.IO;
namespace BasicEventSourceTests
{
@@ -18,6 +19,24 @@ namespace BasicEventSourceTests
/// </summary>
public static class EventTestHarness
{
/// <summary>
/// LogWriteLine will dump its output into a string that will be appended to any exception
/// that happened during a test the harness is running.
/// </summary>
/// <param name="format"></param>
/// <param name="arg"></param>
public static void LogWriteLine(string format, params object[] arg)
{
if (_log == null)
return;
_log.Write("{0:mm:ss.fff} : ", DateTime.UtcNow);
_log.WriteLine(format, arg);
}
// Use to log things in the test itself if needed
private static StringWriter _log = null;
/// <summary>
/// Runs a series of tests 'tests' using the listener (either an ETWListener or an EventListenerListener) on
/// an EventSource 'source' passing it the filter parameters=options (by default source turn on completely
@@ -66,6 +85,8 @@ namespace BasicEventSourceTests
currentTest = tests[testNumber];
Assert.Equal(currentTest.Name, data.PayloadValue(0, "name"));
expectedTestNumber++;
_log = new StringWriter();
LogWriteLine("STARTING Sub-Test {0}", currentTest.Name);
}
else
{
@@ -77,6 +98,7 @@ namespace BasicEventSourceTests
}
else
{
LogWriteLine("Received Event {0}", data);
// If expectedTestNumber is 0 then this is before the first test
// If expectedTestNumber is count then it is after the last test
Assert.NotNull(currentTest);
@@ -85,29 +107,60 @@ namespace BasicEventSourceTests
};
// Run the tests. collecting and validating the results.
using (TestHarnessEventSource testHarnessEventSource = new TestHarnessEventSource())
try
{
// Turn on the test EventSource.
listener.EventSourceSynchronousEnable(source, options);
// And the harnesses's EventSource.
listener.EventSourceSynchronousEnable(testHarnessEventSource);
// Generate events for all the tests, surrounded by events that tell us we are starting a test.
int testNumber = 0;
foreach (var test in tests)
using (TestHarnessEventSource testHarnessEventSource = new TestHarnessEventSource())
{
testHarnessEventSource.StartTest(test.Name, testNumber);
test.EventGenerator();
testNumber++;
// Turn on the test EventSource.
listener.EventSourceSynchronousEnable(source, options);
// And the harnesses's EventSource.
listener.EventSourceSynchronousEnable(testHarnessEventSource);
// Generate events for all the tests, surrounded by events that tell us we are starting a test.
int testNumber = 0;
foreach (var test in tests)
{
testHarnessEventSource.StartTest(test.Name, testNumber);
test.EventGenerator();
testNumber++;
}
testHarnessEventSource.StartTest("", testNumber); // Empty test marks the end of testing.
// Disable the listeners.
listener.EventSourceCommand(source.Name, EventCommand.Disable);
listener.EventSourceCommand(testHarnessEventSource.Name, EventCommand.Disable);
// Send something that should be ignored.
testHarnessEventSource.IgnoreEvent();
}
testHarnessEventSource.StartTest("", testNumber); // Empty test marks the end of testing.
}
catch (Exception e)
{
if (e is EventSourceException)
e = e.InnerException;
LogWriteLine("Exception thrown: {0}", e.Message);
// Disable the listeners.
listener.EventSourceCommand(source.Name, EventCommand.Disable);
listener.EventSourceCommand(testHarnessEventSource.Name, EventCommand.Disable);
var exceptionText = new StringWriter();
exceptionText.WriteLine("Error Detected in EventTestHarness.RunTest");
if (currentTest != null)
exceptionText.WriteLine("FAILURE IN SUBTEST: \"{0}\"", currentTest.Name);
// Send something that should be ignored.
testHarnessEventSource.IgnoreEvent();
exceptionText.WriteLine("************* EXCEPTION INFO ***************");
exceptionText.WriteLine(e.ToString());
exceptionText.WriteLine("*********** END EXCEPTION INFO *************");
if (_log != null)
{
exceptionText.WriteLine("************* LOGGING MESSAGES ***************");
exceptionText.WriteLine(_log.ToString());
exceptionText.WriteLine("*********** END LOGGING MESSAGES *************");
}
exceptionText.WriteLine("Version of Runtime {0}", Environment.Version);
exceptionText.WriteLine("Version of OS {0}", Environment.OSVersion);
exceptionText.WriteLine("**********************************************");
throw new EventTestHarnessException(exceptionText.ToString(), e);
}
listener.Dispose(); // Indicate we are done listening. For the ETW file based cases, we do all the processing here
@@ -116,6 +169,11 @@ namespace BasicEventSourceTests
Assert.Equal(expectedTestNumber, tests.Count);
}
public class EventTestHarnessException : Exception
{
public EventTestHarnessException(string message, Exception exception) : base(message, exception) { }
}
/// <summary>
/// This eventSource I use to emit events to separate tests from each other.
/// </summary>

View File

@@ -42,7 +42,7 @@ namespace BasicEventSourceTests
}
}
internal void EnableTimer(EventSource eventSource, int pollingTime)
internal void EnableTimer(EventSource eventSource, double pollingTime)
{
FilteringOptions options = new FilteringOptions();
options.Args = new Dictionary<string, string>();
@@ -84,9 +84,29 @@ namespace BasicEventSourceTests
public abstract int PayloadCount { get; }
public virtual string PayloadString(int propertyIndex, string propertyName)
{
return PayloadValue(propertyIndex, propertyName).ToString();
var obj = PayloadValue(propertyIndex, propertyName);
var asDict = obj as IDictionary<string, object>;
if (asDict != null)
{
StringBuilder sb = new StringBuilder();
sb.Append("{");
bool first = true;
foreach (var key in asDict.Keys)
{
if (!first)
sb.Append(",");
first = false;
var value = asDict[key];
sb.Append(key).Append(":").Append(value != null ? value.ToString() : "NULL");
}
sb.Append("}");
return sb.ToString();
}
if (obj != null)
return obj.ToString();
return "";
}
public abstract IEnumerable<string> PayloadNames { get; }
public abstract IList<string> PayloadNames { get; }
#if DEBUG
/// <summary>
@@ -240,7 +260,7 @@ namespace BasicEventSourceTests
return _data.PayloadString(propertyIndex);
}
public override int PayloadCount { get { return _data.PayloadNames.Length; } }
public override IEnumerable<string> PayloadNames { get { return _data.PayloadNames; } }
public override IList<string> PayloadNames { get { return _data.PayloadNames; } }
#region private
internal EtwEvent(TraceEvent data) { _data = data.Clone(); }
@@ -262,33 +282,33 @@ namespace BasicEventSourceTests
private Action<EventSource> _onEventSourceCreated;
#if FEATURE_ETLEVENTS
public event EventHandler<EventSourceCreatedEventArgs> EventSourceCreated
public event EventHandler<EventSourceCreatedEventArgs> EventSourceCreated
{
add
{
if (this._listener != null)
this._listener.EventSourceCreated += value;
}
this._listener.EventSourceCreated += value;
}
remove
{
if (this._listener != null)
this._listener.EventSourceCreated -= value;
}
}
this._listener.EventSourceCreated -= value;
}
}
public event EventHandler<EventWrittenEventArgs> EventWritten
{
add
{
if (this._listener != null)
this._listener.EventWritten += value;
this._listener.EventWritten += value;
}
remove
{
if (this._listener != null)
this._listener.EventWritten -= value;
}
}
}
}
#endif
public EventListenerListener(bool useEventsToListen = false)
@@ -297,7 +317,7 @@ namespace BasicEventSourceTests
if (useEventsToListen)
{
_listener = new HelperEventListener(null);
_listener.EventSourceCreated += (sender, eventSourceCreatedEventArgs)
_listener.EventSourceCreated += (sender, eventSourceCreatedEventArgs)
=> _onEventSourceCreated?.Invoke(eventSourceCreatedEventArgs.EventSource);
_listener.EventWritten += mListenerEventWritten;
}
@@ -310,6 +330,7 @@ namespace BasicEventSourceTests
public override void Dispose()
{
EventTestHarness.LogWriteLine("Disposing Listener");
_listener.Dispose();
}
@@ -325,6 +346,8 @@ namespace BasicEventSourceTests
public override void EventSourceCommand(string eventSourceName, EventCommand command, FilteringOptions options = null)
{
EventTestHarness.LogWriteLine("Sending command {0} to EventSource {1} Options {2}", eventSourceName, command, options);
if (options == null)
options = new FilteringOptions();
@@ -372,7 +395,7 @@ namespace BasicEventSourceTests
{
#if FEATURE_ETLEVENTS
// OnEventWritten is abstract in netfx <= 461
base.OnEventWritten(eventData);
base.OnEventWritten(eventData);
#endif
_forwardTo?.OnEvent?.Invoke(new EventListenerEvent(eventData));
}
@@ -391,7 +414,7 @@ namespace BasicEventSourceTests
public override string EventName { get { return _data.EventName; } }
public override IEnumerable<string> PayloadNames { get { return _data.PayloadNames; } }
public override IList<string> PayloadNames { get { return _data.PayloadNames; } }
public override int PayloadCount
{

View File

@@ -3,7 +3,7 @@
// See the LICENSE file in the project root for more information.
using System.Diagnostics.Tracing;
#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue #4864.
#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue https://github.com/dotnet/corefx/issues/4864
using Microsoft.Diagnostics.Tracing.Session;
#endif
using Xunit;
@@ -18,7 +18,6 @@ using System.Threading.Tasks;
namespace BasicEventSourceTests
{
#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue #4864.
public class TestEventCounter
{
private sealed class MyEventSource : EventSource
@@ -44,6 +43,8 @@ namespace BasicEventSourceTests
}
[Fact]
[SkipOnTargetFramework(TargetFrameworkMonikers.NetFramework, reason: "https://github.com/dotnet/corefx/issues/23661")]
[ActiveIssue("https://github.com/dotnet/corefx/issues/22791", TargetFrameworkMonikers.UapAot)]
public void Test_Write_Metric_EventListener()
{
using (var listener = new EventListenerListener())
@@ -52,130 +53,266 @@ namespace BasicEventSourceTests
}
}
#if USE_ETW
[Fact]
public void Test_Write_Metric_ETW()
{
using (var listener = new EtwListener())
{
Test_Write_Metric(listener);
}
}
#endif
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",
tests.Add(new SubTest("EventCounter: Log 1 event, explicit poll at end",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(37);
Thread.Sleep(1500); // Sleep for 1.5 seconds
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)
{
Assert.Equal(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37);
// 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 event in single period",
tests.Add(new SubTest("EventCounter: Log 2 events, explicit poll at end",
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);
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", 1, 37, 0, 37, 37);
ValidateSingleEventCounter(evts[2], "Request", 1, 25, 0, 25, 25);
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 2 different events in a period",
tests.Add(new SubTest("EventCounter: Log 3 events in two polling periods (explicit polling)",
delegate ()
{
listener.EnableTimer(logger, 1); /* Poll every 1 s */
logger.Request(25);
listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */
logger.Request(5);
logger.Request(10);
logger.Error();
Thread.Sleep(1500); // Sleep for 1.5 seconds
listener.EnableTimer(logger, 0);
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(2, evts.Count);
ValidateSingleEventCounter(evts[0], "Request", 1, 25, 0, 25, 25);
ValidateSingleEventCounter(evts[1], "Error", 1, 1, 0, 1, 1);
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 guarentee (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 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;
}
EventTestHarness.LogWriteLine("Validating: Count={0} RequestSum={1:n3} TimeSum={2:n3} ", evts.Count, requestSum, timeSum);
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 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 shoudl 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: {Thread.CurrentThread.ManagedThreadId}");
// 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 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");
}));
/*************************************************************************/
#if FEATURE_EVENTCOUNTER_DISPOSE
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);
}));
#endif
/*************************************************************************/
EventTestHarness.RunTests(tests, listener, logger);
}
TestUtilities.CheckNoEventSourcesRunning("Stop");
}
private static void ValidateSingleEventCounter(Event evt, string counterName, int count, float sum, float sumSquared, float min, float max)
// Thread.Sleep has proven unreliable, sometime sleeping much shorter than it should.
// This makes sure it at least sleeps 'msec' at a miniumum.
private static void Sleep(int minMSec)
{
object payload = ValidateEventHeaderAndGetPayload(evt);
var payloadContent = payload as IDictionary<string, object>;
Assert.NotNull(payloadContent);
ValidateEventCounter(counterName, count, sum, sumSquared, min, max, payloadContent);
var startTime = DateTime.UtcNow;
for (; ; )
{
DateTime endTime = DateTime.UtcNow;
double delta = (endTime - startTime).TotalMilliseconds;
if (delta >= minMSec)
break;
Thread.Sleep(1);
}
}
private static object ValidateEventHeaderAndGetPayload(Event evt)
private static void ValidateSingleEventCounter(Event evt, string counterName, int count, float mean, float standardDeviation, float min, float max)
{
ValidateEventCounter(counterName, count, mean, standardDeviation, min, max, ValidateEventHeaderAndGetPayload(evt));
}
private static IDictionary<string, object> ValidateEventHeaderAndGetPayload(Event evt)
{
Assert.Equal("EventCounters", evt.EventName);
List<string> payloadNames = evt.PayloadNames.ToList();
Assert.Equal(1, payloadNames.Count);
Assert.Equal("Payload", payloadNames[0]);
object rawPayload = evt.PayloadValue(0, "Payload");
return rawPayload;
Assert.Equal(1, evt.PayloadCount);
Assert.NotNull(evt.PayloadNames);
Assert.Equal(1, evt.PayloadNames.Count);
Assert.Equal("Payload", evt.PayloadNames[0]);
var ret = (IDictionary<string, object>)evt.PayloadValue(0, "Payload");
Assert.NotNull(ret);
return ret;
}
private static void ValidateEventCounter(string counterName, int count, float mean, float standardDeviation, float min, float max, IDictionary<string, object> payloadContent)
{
var payloadContentValue = new List<KeyValuePair<string, object>>();
foreach (var payloadContentEntry in payloadContent)
Assert.Equal(counterName, (string)payloadContent["Name"]);
Assert.Equal(count, (int)payloadContent["Count"]);
if (count != 0)
{
payloadContentValue.Add(payloadContentEntry);
Assert.Equal(mean, (float)payloadContent["Mean"]);
Assert.Equal(standardDeviation, (float)payloadContent["StandardDeviation"]);
}
Assert.Equal(7, payloadContentValue.Count);
ValidatePayloadEntry("Name", counterName, payloadContentValue[0]);
ValidatePayloadEntry("Mean", mean, payloadContentValue[1]);
ValidatePayloadEntry("StandardDeviation", standardDeviation, payloadContentValue[2]);
ValidatePayloadEntry("Count", count, payloadContentValue[3]);
ValidatePayloadEntry("Min", min, payloadContentValue[4]);
ValidatePayloadEntry("Max", max, payloadContentValue[5]);
}
private static void ValidatePayloadEntry(string name, object value, KeyValuePair<string, object> payloadEntry)
{
Assert.Equal(name, payloadEntry.Key);
Assert.Equal(value, payloadEntry.Value);
Assert.Equal(min, (float)payloadContent["Min"]);
Assert.Equal(max, (float)payloadContent["Max"]);
}
}
#endif //USE_ETW
}

View File

@@ -4,6 +4,7 @@
<PropertyGroup>
<ProjectGuid>{7E0E1B11-FF70-461E-99F7-C0AF252C0C60}</ProjectGuid>
<DefineConstants Condition="'$(TargetGroup)' == 'netcoreapp'">$(DefineConstants);FEATURE_ETLEVENTS</DefineConstants>
<DefineConstants Condition="'$(TargetGroup)' == 'netcoreapp'">$(DefineConstants);FEATURE_EVENTCOUNTER_DISPOSE</DefineConstants>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
</PropertyGroup>
<PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'netcoreapp-Debug|AnyCPU'" />
@@ -36,9 +37,6 @@
<Compile Include="CustomEventSources\SimpleEventSource.cs" />
<Compile Include="CustomEventSources\UseAbstractEventSource.cs" />
<Compile Include="CustomEventSources\UseInterfaceEventSource.cs" />
<Compile Include="$(CommonTestPath)\System\PlatformDetection.cs">
<Link>CommonTest\System\PlatformDetection.cs</Link>
</Compile>
</ItemGroup>
<ItemGroup>
<EmbeddedResource Include="Resources\$(AssemblyName).rd.xml" />