Fix a race and inefficiency in Microsoft-Diagnostics-DiagnosticSource (dotnet/corefx...
authorVance Morrison <vancem@microsoft.com>
Fri, 8 Mar 2019 19:27:52 +0000 (11:27 -0800)
committerGitHub <noreply@github.com>
Fri, 8 Mar 2019 19:27:52 +0000 (11:27 -0800)
* Fix a race and inefficiency in Microsoft-Diagnostics-DiagnosticSource

There is a bridge from DiagnosticSource to EventSoruce called Microsoft-Diagnostics-DiagnosticSource.
This bridge take the data object payload and derializes it int EventSource events.
There was a cache that kept  the type and it cooresponding serialization transform of the last object, which were not atomic and thus could be confused if code was executed concurrently.

In this cache is per EXPLICITLY filtered events, and works well for that case.  If however the transform is implicit, many events can share the same cache slot, and the cache becomes very ineffective.

To fix this we keep the existing one element cache, but we only set it once (which keeps things simple but avoids races and covers the explicitly filtered case), and add a lazily created ConcurrentDictionary for the 'many envent' case.

Also fixes some unrelate test issues (avoided using the same DiagnosticListner names so that tests don't interact when run concurrently),   Fixed issue were a test fails under the debugger (because the debugger turns on Microsoft-Diagnostics-DiagnosticSource which interfers with the test).

I did walk new code to insure that we at least had code coverage for the new code over our set of tests.

* Review feedback.

Basically rather than tolerate races, change to code to remove them.
This makes the code less error prone.

* Fix more nits.

* fix whitespace

* comment and use lambda so c# caches it.

* fix typo

* add in deleted line

Commit migrated from https://github.com/dotnet/corefx/commit/a8cef502cd74aabb209cb9ad7a1e2a5bc1612459

src/libraries/System.Diagnostics.DiagnosticSource/src/System.Diagnostics.DiagnosticSource.csproj
src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/DiagnosticSourceEventSource.cs
src/libraries/System.Diagnostics.DiagnosticSource/tests/DiagnosticSourceEventSourceBridgeTests.cs
src/libraries/System.Diagnostics.DiagnosticSource/tests/DiagnosticSourceTests.cs

index d79905a..0453c81 100644 (file)
@@ -46,6 +46,7 @@
   </ItemGroup>
   <ItemGroup Condition="'$(TargetGroup)' != 'netfx'">
     <Reference Include="System.Collections" />
+    <Reference Include="System.Collections.Concurrent" />
     <Reference Include="System.Diagnostics.Debug" />
     <Reference Include="System.Diagnostics.Tracing" />
     <Reference Include="System.Reflection" />
index ee907a6..4d6a881 100644 (file)
@@ -1,11 +1,13 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 // See the LICENSE file in the project root for more information.
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics.Tracing;
 using System.Reflection;
 using System.Runtime.CompilerServices;
 using System.Text;
+using System.Threading;
 
 namespace System.Diagnostics
 {
@@ -644,26 +646,43 @@ namespace System.Diagnostics
                 {
                     if (!_noImplicitTransforms)
                     {
+                        // given the type, fetch the implicit transforms for that type and put it in the implicitTransforms variable.  
                         Type argType = args.GetType();
-                        if (_expectedArgType != argType)
+                        TransformSpec implicitTransforms;
+
+                        // First check the one-element cache _firstImplicitTransformsEntry
+                        ImplicitTransformEntry cacheEntry = _firstImplicitTransformsEntry;
+                        if (cacheEntry != null && cacheEntry.Type == argType)
+                        {
+                            implicitTransforms = cacheEntry.Transforms;     // Yeah we hit the cache.  
+                        }
+                        else if (cacheEntry == null)
                         {
-                            // Figure out the default properties to send on to EventSource.  These are all string or primitive properties.  
-                            _implicitTransforms = null;
-                            TransformSpec newSerializableArgs = null;
-                            TypeInfo curTypeInfo = argType.GetTypeInfo();
-                            foreach (var property in curTypeInfo.DeclaredProperties)
+                            // _firstImplicitTransformsEntry is empty, we should fill it.  
+                            // Note that it is OK that two threads may race and both call MakeImplicitTransforms on their own
+                            // (that is we don't expect exactly once initialization of _firstImplicitTransformsEntry)    
+                            implicitTransforms = MakeImplicitTransforms(argType);
+                            Interlocked.CompareExchange(ref _firstImplicitTransformsEntry, 
+                                new ImplicitTransformEntry() { Type = argType, Transforms = implicitTransforms }, null);
+                        }
+                        else
+                        {
+                            // This should only happen when you are wildcarding your events (reasonably rare).   
+                            // In that case you will probably need many types
+                            // Note currently we don't limit the cache size, but it is limited by the number of 
+                            // distinct types of objects passed to DiagnosticSource.Write.  
+                            if (_implicitTransformsTable == null)
                             {
-                                var propertyType = property.PropertyType;
-                                newSerializableArgs = new TransformSpec(property.Name, 0, property.Name.Length, newSerializableArgs);
+                                Interlocked.CompareExchange(ref _implicitTransformsTable,
+                                    new ConcurrentDictionary<Type, TransformSpec>(1, 8), null);
                             }
-                            _expectedArgType = argType;
-                            _implicitTransforms = Reverse(newSerializableArgs);
+                            implicitTransforms = _implicitTransformsTable.GetOrAdd(argType, type => MakeImplicitTransforms(type));
                         }
 
-                        // Fetch all the fields that are already serializable
-                        if (_implicitTransforms != null)
+                        // implicitTransformas now fetched from cache or constructed, use it to Fetch all the implicit fields.  
+                        if (implicitTransforms != null)
                         {
-                            for (var serializableArg = _implicitTransforms; serializableArg != null; serializableArg = serializableArg.Next)
+                            for (TransformSpec serializableArg = implicitTransforms; serializableArg != null; serializableArg = serializableArg.Next)
                                 outputArgs.Add(serializableArg.Morph(args));
                         }
                     }
@@ -684,6 +703,20 @@ namespace System.Diagnostics
             public FilterAndTransform Next;
 
             #region private
+            // Given a type generate all the the implicit transforms for type (that is for every field 
+            // generate the spec that fetches it).  
+            private static TransformSpec MakeImplicitTransforms(Type type)
+            {
+                TransformSpec newSerializableArgs = null;
+                TypeInfo curTypeInfo = type.GetTypeInfo();
+                foreach (PropertyInfo property in curTypeInfo.DeclaredProperties)
+                {
+                    Type propertyType = property.PropertyType;
+                    newSerializableArgs = new TransformSpec(property.Name, 0, property.Name.Length, newSerializableArgs);
+                }
+                return Reverse(newSerializableArgs);
+            }
+
             // Reverses a linked list (of TransformSpecs) in place.    
             private static TransformSpec Reverse(TransformSpec list)
             {
@@ -700,14 +733,22 @@ namespace System.Diagnostics
 
             private IDisposable _diagnosticsListenersSubscription; // This is our subscription that listens for new Diagnostic source to appear. 
             private Subscriptions _liveSubscriptions;              // These are the subscriptions that we are currently forwarding to the EventSource.
-            private bool _noImplicitTransforms;                    // Listener can say they don't want implicit transforms.  
-            private Type _expectedArgType;                         // This is the type where 'implicitTransforms is built for'
-            private TransformSpec _implicitTransforms;             // payload to include because the DiagnosticSource's object fields are already serializable 
+            private bool _noImplicitTransforms;                    // Listener can say they don't want implicit transforms.
+            private ImplicitTransformEntry _firstImplicitTransformsEntry; // The transform for _firstImplicitFieldsType
+            private ConcurrentDictionary<Type, TransformSpec> _implicitTransformsTable; // If there is more than one object type for an implicit transform, they go here.   
             private TransformSpec _explicitTransforms;             // payload to include because the user explicitly indicated how to fetch the field.  
             private DiagnosticSourceEventSource _eventSource;      // Where the data is written to.  
             #endregion
         }
 
+        // This olds one the implicit transform for one type of object.  
+        // We remember this type-transform pair in the _firstImplicitTransformsEntry cache.  
+        internal class ImplicitTransformEntry
+        {
+            public Type Type;
+            public TransformSpec Transforms;
+        }
+
         /// <summary>
         /// Transform spec represents a string that describes how to extract a piece of data from
         /// the DiagnosticSource payload.   An example string is OUTSTR=EVENT_VALUE.PROP1.PROP2.PROP3
index 172a77e..80d3fa2 100644 (file)
@@ -13,6 +13,23 @@ namespace System.Diagnostics.Tests
     //Complex types are not supported on EventSource for .NET 4.5
     public class DiagnosticSourceEventSourceBridgeTests : RemoteExecutorTestBase
     {
+        // To avoid interactions between tests when they are run in parallel, we run all these tests in their 
+        // own sub-process using RemoteInvoke()  However this makes it very inconvinient to debug the test.   
+        // By seting this #if to true you stub out RemoteInvoke and the code will run in-proc which is useful 
+        // in debugging.
+#if false    
+        class NullDispose : IDisposable
+        {
+            public void Dispose()
+            {
+            }
+        }
+        static IDisposable RemoteInvoke(Action a)
+        {
+            a();
+            return new NullDispose();
+        }
+#endif 
         /// <summary>
         /// Tests the basic functionality of turning on specific EventSources and specifying 
         /// the events you want.
@@ -102,7 +119,7 @@ namespace System.Diagnostics.Tests
         /// Test that things work properly for Linux newline conventions. 
         /// </summary>
         [Fact]
-        [SkipOnTargetFramework(TargetFrameworkMonikers.UapAot,"This is linux specific test")]
+        [SkipOnTargetFramework(TargetFrameworkMonikers.UapAot, "This is linux specific test")]
         public void LinuxNewLineConventions()
         {
             RemoteInvoke(() =>
@@ -267,6 +284,34 @@ namespace System.Diagnostics.Tests
                     eventSourceListener.ResetEventCountAndLastEvent();
 
                     /***************************************************************************************/
+                    // Emit an event with the same schema as the first event.   (uses first-event cache)
+                    val = new MyClass() { };
+                    if (diagnosticSourceListener.IsEnabled("TestEvent1"))
+                        diagnosticSourceListener.Write("TestEvent1", new { propStr = "hiThere", propInt = 5, cls = val });
+
+                    Assert.Equal(1, eventSourceListener.EventCount); // Exactly one more event has been emitted.
+                    Assert.Equal("TestWildCardEventNameSource", eventSourceListener.LastEvent.SourceName);
+                    Assert.Equal("TestEvent1", eventSourceListener.LastEvent.EventName);
+                    Assert.Equal(3, eventSourceListener.LastEvent.Arguments.Count);
+                    Assert.Equal(val.GetType().FullName, eventSourceListener.LastEvent.Arguments["cls"]);  // ToString on cls is the class name
+                    Assert.Equal("hiThere", eventSourceListener.LastEvent.Arguments["propStr"]);
+                    Assert.Equal("5", eventSourceListener.LastEvent.Arguments["propInt"]);
+                    eventSourceListener.ResetEventCountAndLastEvent();
+
+                    /***************************************************************************************/
+                    // Emit an event with the same schema as the second event.  (uses dictionary cache)
+                    if (diagnosticSourceListener.IsEnabled("TestEvent1"))
+                        diagnosticSourceListener.Write("TestEvent1", new { propStr2 = "hi3", cls = val });
+
+                    Assert.Equal(1, eventSourceListener.EventCount); // Exactly one more event has been emitted.
+                    Assert.Equal("TestWildCardEventNameSource", eventSourceListener.LastEvent.SourceName);
+                    Assert.Equal("TestEvent1", eventSourceListener.LastEvent.EventName);
+                    Assert.Equal(2, eventSourceListener.LastEvent.Arguments.Count);
+                    Assert.Equal(val.GetType().FullName, eventSourceListener.LastEvent.Arguments["cls"]);  // ToString on cls is the class name
+                    Assert.Equal("hi3", eventSourceListener.LastEvent.Arguments["propStr2"]);
+                    eventSourceListener.ResetEventCountAndLastEvent();
+
+                    /***************************************************************************************/
                     // Emit an event from another diagnostic source with the same event name.  
                     // It will be filtered out.  
                     using (var diagnosticSourceListener2 = new DiagnosticListener("TestWildCardEventNameSource2"))
@@ -546,6 +591,20 @@ namespace System.Diagnostics.Tests
                 using (var aspNetCoreSource = new DiagnosticListener("Microsoft.AspNetCore"))
                 using (var entityFrameworkCoreSource = new DiagnosticListener("Microsoft.EntityFrameworkCore"))
                 {
+                    // Sadly we have a problem where if something else has turned on Microsoft-Diagnostics-DiagnosticSource then
+                    // its keywords are ORed with our and because the shortcuts require that IgnoreShortCutKeywords is OFF 
+                    // Something outside this test (the debugger seems to do this), will cause the test to fail.  
+                    // Currently we simply give up in that case (but it really is a deeper problem. 
+                    var IgnoreShortCutKeywords = (EventKeywords)0x0800;
+                    foreach (var eventSource in EventSource.GetSources())
+                    {
+                        if (eventSource.Name == "Microsoft-Diagnostics-DiagnosticSource")
+                        {
+                            if (eventSource.IsEnabled(EventLevel.Informational, IgnoreShortCutKeywords))
+                                return; // Don't do the testing.  
+                        }
+                    }
+
                     // These are from DiagnosticSourceEventListener.  
                     var Messages = (EventKeywords)0x1;
                     var Events = (EventKeywords)0x2;
@@ -669,7 +728,7 @@ namespace System.Diagnostics.Tests
                             }
                             ce.Signal();
                         })
-                        {  IsBackground = true }.Start();
+                        { IsBackground = true }.Start();
                     }
                     ce.Wait();
                 }
@@ -712,7 +771,7 @@ namespace System.Diagnostics.Tests
 
         public int EventCount;
         public DiagnosticSourceEvent LastEvent;
-#if DEBUG 
+#if DEBUG
         // Here just for debugging.  Lets you see the last 3 events that were sent.  
         public DiagnosticSourceEvent SecondLast;
         public DiagnosticSourceEvent ThirdLast;
@@ -725,7 +784,7 @@ namespace System.Diagnostics.Tests
         {
             EventCount = 0;
             LastEvent = null;
-#if DEBUG 
+#if DEBUG
             SecondLast = null;
             ThirdLast = null;
 #endif
@@ -736,13 +795,13 @@ namespace System.Diagnostics.Tests
         /// </summary>
         public Predicate<DiagnosticSourceEvent> Filter;
 
-#region private 
+        #region private 
         private void UpdateLastEvent(DiagnosticSourceEvent anEvent)
         {
             if (Filter != null && !Filter(anEvent))
                 return;
 
-#if DEBUG 
+#if DEBUG
             ThirdLast = SecondLast;
             SecondLast = LastEvent;
 #endif
@@ -750,7 +809,7 @@ namespace System.Diagnostics.Tests
             EventCount++;
             LastEvent = anEvent;
         }
-#endregion
+        #endregion
     }
 
     /// <summary>
index d3977d5..464c4e6 100644 (file)
@@ -22,7 +22,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void IntPayload()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingIntPayload"))
             {
                 DiagnosticSource source = listener;
                 var result = new List<KeyValuePair<string, object>>();
@@ -48,7 +48,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void StructPayload()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingStructPayload"))
             {
                 DiagnosticSource source = listener;
                 var result = new List<KeyValuePair<string, object>>();
@@ -76,7 +76,7 @@ namespace System.Diagnostics.Tests
         {
             var result = new List<KeyValuePair<string, object>>();
             var observer = new ObserverToList<TelemData>(result);
-            var listener = new DiagnosticListener("MyListener");
+            var listener = new DiagnosticListener("TestingCompleted");
             var subscription = listener.Subscribe(observer);
 
             listener.Write("IntPayload", 5);
@@ -105,7 +105,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void BasicIsEnabled()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingBasicIsEnabled"))
             {
                 DiagnosticSource source = listener;
                 var result = new List<KeyValuePair<string, object>>();
@@ -122,7 +122,7 @@ namespace System.Diagnostics.Tests
                     return name == "StructPayload";
                 };
 
-                Assert.False(listener.IsEnabled());
+                // Assert.False(listener.IsEnabled());  Since other things might turn on all DiagnosticSources, we can't ever test that it is not enabled. 
                 using (listener.Subscribe(new ObserverToList<TelemData>(result), predicate))
                 {
                     Assert.False(source.IsEnabled("Uninteresting"));
@@ -142,7 +142,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void IsEnabledMultipleArgs()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingIsEnabledMultipleArgs"))
             {
                 DiagnosticSource source = listener;
                 var result = new List<KeyValuePair<string, object>>();
@@ -174,7 +174,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void MultiSubscriber()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingMultiSubscriber"))
             {
                 DiagnosticSource source = listener;
                 var subscriber1Result = new List<KeyValuePair<string, object>>();
@@ -545,7 +545,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void DoubleDisposeOfListener()
         {
-            var listener = new DiagnosticListener("MyListener");
+            var listener = new DiagnosticListener("TestingDoubleDisposeOfListener");
             int completionCount = 0;
 
             IDisposable subscription = listener.Subscribe(MakeObserver<KeyValuePair<string, object>>(_ => { }, () => completionCount++));
@@ -603,7 +603,7 @@ namespace System.Diagnostics.Tests
         [Fact]
         public void SubscribeWithNullPredicate()
         {
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingSubscribeWithNullPredicate"))
             {
                 Predicate<string> predicate = null;
                 using (listener.Subscribe(new ObserverToList<TelemData>(new List<KeyValuePair<string, object>>()), predicate))
@@ -615,7 +615,7 @@ namespace System.Diagnostics.Tests
                 }
             }
 
-            using (DiagnosticListener listener = new DiagnosticListener("Testing"))
+            using (DiagnosticListener listener = new DiagnosticListener("TestingSubscribeWithNullPredicate"))
             {
                 DiagnosticSource source = listener;
                 Func<string, object, object, bool> predicate = null;