From 91c31af4b27dbe3b13fb252c5e099aa7494df9e5 Mon Sep 17 00:00:00 2001 From: David Mason Date: Tue, 17 Nov 2015 13:35:32 -0800 Subject: [PATCH] Porting the source from the nuget package of EventSource to the coreclr branch. This includes many bug fixes. --- .../System/Diagnostics/Eventing/ActivityTracker.cs | 194 +++++++++--- .../System/Diagnostics/Eventing/EventProvider.cs | 119 ++++--- .../src/System/Diagnostics/Eventing/EventSource.cs | 341 +++++++++++++++------ .../Eventing/TraceLogging/DataCollector.cs | 8 + .../Eventing/TraceLogging/EventFieldAttribute.cs | 1 + .../Eventing/TraceLogging/SimpleTypeInfos.cs | 9 + 6 files changed, 498 insertions(+), 174 deletions(-) diff --git a/src/mscorlib/src/System/Diagnostics/Eventing/ActivityTracker.cs b/src/mscorlib/src/System/Diagnostics/Eventing/ActivityTracker.cs index 637a607..5d90253 100644 --- a/src/mscorlib/src/System/Diagnostics/Eventing/ActivityTracker.cs +++ b/src/mscorlib/src/System/Diagnostics/Eventing/ActivityTracker.cs @@ -4,8 +4,6 @@ using System; using System.Diagnostics; using System.Threading; -using System.Threading.Tasks; - #if !ES_BUILD_AGAINST_DOTNET_V35 using Contract = System.Diagnostics.Contracts.Contract; #else @@ -14,15 +12,16 @@ using Contract = Microsoft.Diagnostics.Contracts.Internal.Contract; #if ES_BUILD_STANDALONE namespace Microsoft.Diagnostics.Tracing -#else +#else +using System.Threading.Tasks; namespace System.Diagnostics.Tracing #endif { /// - /// Tracks activities. This is meant to be a singledon (accessed by the ActivityTracer.Instance static property) + /// Tracks activities. This is meant to be a singleton (accessed by the ActivityTracer.Instance static property) /// /// Logically this is simply holds the m_current variable that holds the async local that holds the current ActivityInfo - /// An ActivityInfo is represents a actvity (which knows its creator and thus knows its path). + /// An ActivityInfo is represents a activity (which knows its creator and thus knows its path). /// /// Most of the magic is in the async local (it gets copied to new tasks) /// @@ -58,7 +57,21 @@ namespace System.Diagnostics.Tracing public void OnStart(string providerName, string activityName, int task, ref Guid activityId, ref Guid relatedActivityId, EventActivityOptions options) { if (m_current == null) // We are not enabled - return; + { + // We used to rely on the TPL provider turning us on, but that has the disadvantage that you don't get Start-Stop tracking + // until you use Tasks for the first time (which you may never do). Thus we change it to pull rather tan push for whether + // we are enabled. + if (m_checkedForEnable) + return; + m_checkedForEnable = true; +#if ES_BUILD_STANDALONE + Enable(); // Enable it unconditionally. +#else + if (System.Threading.Tasks.TplEtwProvider.Log.IsEnabled(EventLevel.Informational, System.Threading.Tasks.TplEtwProvider.Keywords.TasksFlowActivityIds)) + Enable(); +#endif + } + Contract.Assert((options & EventActivityOptions.Disable) == 0); @@ -102,11 +115,11 @@ namespace System.Diagnostics.Tracing else id = Interlocked.Increment(ref currentActivity.m_lastChildID); - // Remember the previous ID so we can log it - relatedActivityId = currentActivity != null ? currentActivity.ActivityId : Guid.Empty; + // The previous ID is my 'causer' and becomes my related activity ID + relatedActivityId = EventSource.CurrentThreadActivityId; // Add to the list of started but not stopped activities. - ActivityInfo newActivity = new ActivityInfo(fullActivityName, id, currentActivity, options); + ActivityInfo newActivity = new ActivityInfo(fullActivityName, id, currentActivity, relatedActivityId, options); m_current.Value = newActivity; // Remember the current ID so we can log it @@ -121,7 +134,7 @@ namespace System.Diagnostics.Tracing /// /// Called when a work item stops. The activity name = providerName + activityName without 'Stop' suffix. - /// It updates CurrentActivityId to track this fact. The Stop event associated with stop should log the ActivityID associated with the event. + /// It updates m_current variable to track this fact. The Stop event associated with stop should log the ActivityID associated with the event. /// /// If activity tracing is not on, then activityId and relatedActivityId are not set /// @@ -153,7 +166,7 @@ namespace System.Diagnostics.Tracing if (activityToStop == null) { activityId = Guid.Empty; - // Basically could not find matching start. + // TODO add some logging about this. Basically could not find matching start. if (etwLog.Debug) etwLog.DebugFacilityMessage("OnStopRET", "Fail"); return; @@ -195,7 +208,7 @@ namespace System.Diagnostics.Tracing m_current.Value = newCurrentActivity; - if (etwLog.Debug) + if (etwLog.Debug) { etwLog.DebugFacilityMessage("OnStopRetActivityState", ActivityInfo.LiveActivities(newCurrentActivity)); etwLog.DebugFacilityMessage("OnStopRet", activityId.ToString()); @@ -265,24 +278,25 @@ namespace System.Diagnostics.Tracing // ******************************************************************************* /// - /// An ActivityInfo repesents a particular activity. It is almost read-only the only + /// An ActivityInfo represents a particular activity. It is almost read-only. The only /// fields that change after creation are /// m_lastChildID - used to generate unique IDs for the children activities and for the most part can be ignored. /// m_stopped - indicates that this activity is dead - /// This read-only ness is important because an activity's m_creator chain forms the + /// This read-only-ness is important because an activity's m_creator chain forms the /// 'Path of creation' for the activity (which is also its unique ID) but is also used as /// the 'list of live parents' which indicate of those ancestors, which are alive (if they /// are not marked dead they are alive). /// private class ActivityInfo { - public ActivityInfo(string name, long uniqueId, ActivityInfo creator, EventActivityOptions options) + public ActivityInfo(string name, long uniqueId, ActivityInfo creator, Guid activityIDToRestore, EventActivityOptions options) { m_name = name; m_eventOptions = options; m_creator = creator; m_uniqueId = uniqueId; m_level = creator != null ? creator.m_level + 1 : 0; + m_activityIdToRestore = activityIDToRestore; // Create a nice GUID that encodes the chain of activities that started this one. CreateActivityPathGuid(out m_guid, out m_activityPathGuidOffset); @@ -299,7 +313,7 @@ namespace System.Diagnostics.Tracing public static string Path(ActivityInfo activityInfo) { if (activityInfo == null) - return(""); + return (""); return Path(activityInfo.m_creator) + "/" + activityInfo.m_uniqueId; } @@ -333,10 +347,10 @@ namespace System.Diagnostics.Tracing /// (rooted in an activity that predates activity tracking. /// /// We wish to encode this path in the Guid to the extent that we can. Many of the paths have - /// many small numbers in them and we take advatage of this in the encoding to output as long + /// many small numbers in them and we take advantage of this in the encoding to output as long /// a path in the GUID as possible. /// - /// Because of the possiblility of GUID collistion, we only use 96 of the 128 bits of the GUID + /// Because of the possibility of GUID collision, we only use 96 of the 128 bits of the GUID /// for encoding the path. The last 32 bits are a simple checksum (and random number) that /// identifies this as using the convention defined here. /// @@ -359,11 +373,16 @@ namespace System.Diagnostics.Tracing } else { + // TODO FIXME - differentiate between AD inside PCL + int appDomainID = 0; +#if !ES_BUILD_STANDALONE + appDomainID = System.Threading.Thread.GetDomainID(); +#endif // We start with the appdomain number to make this unique among appdomains. - activityPathGuidOffsetStart = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint) System.Threading.Thread.GetDomainID()); + activityPathGuidOffsetStart = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint)appDomainID); } - activityPathGuidOffset = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint) m_uniqueId); + activityPathGuidOffset = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint)m_uniqueId); // If the path does not fit, Make a GUID by incrementing rather than as a path, keeping as much of the path as possible @@ -374,19 +393,19 @@ namespace System.Diagnostics.Tracing /// /// If we can't fit the activity Path into the GUID we come here. What we do is simply - /// generate a 4 byte number (s_nextOverflowId). Then look for an anscesor that has + /// generate a 4 byte number (s_nextOverflowId). Then look for an ancestor that has /// sufficient space for this ID. By doing this, we preserve the fact that this activity /// is a child (of unknown depth) from that ancestor. /// [System.Security.SecurityCritical] private unsafe void CreateOverflowGuid(Guid* outPtr) { - // Seach backwards for an ancestor that has sufficient space to put the ID. - for(ActivityInfo ancestor = m_creator; ancestor != null; ancestor = ancestor.m_creator) + // Search backwards for an ancestor that has sufficient space to put the ID. + for (ActivityInfo ancestor = m_creator; ancestor != null; ancestor = ancestor.m_creator) { if (ancestor.m_activityPathGuidOffset <= 10) // we need at least 2 bytes. { - uint id = (uint) Interlocked.Increment(ref ancestor.m_lastChildID); // Get a unique ID + uint id = unchecked((uint)Interlocked.Increment(ref ancestor.m_lastChildID)); // Get a unique ID // Try to put the ID into the GUID *outPtr = ancestor.m_guid; int endId = AddIdToGuid(outPtr, ancestor.m_activityPathGuidOffset, id, true); @@ -399,8 +418,8 @@ namespace System.Diagnostics.Tracing } /// - /// The encoding for a list of numbers used to make Activity Guids. Basically - /// we operate on nibbles (which are nice becase they show up as hex digits). The + /// The encoding for a list of numbers used to make Activity GUIDs. Basically + /// we operate on nibbles (which are nice because they show up as hex digits). The /// list is ended with a end nibble (0) and depending on the nibble value (Below) /// the value is either encoded into nibble itself or it can spill over into the /// bytes that follow. @@ -411,18 +430,18 @@ namespace System.Diagnostics.Tracing LastImmediateValue = 0xA, PrefixCode = 0xB, // all the 'long' encodings go here. If the next nibble is MultiByte1-4 - // than this is a 'overflow' id. Unlike the hierarchitcal IDs these are - // allocated densly but don't tell you anything about nesting. we use + // than this is a 'overflow' id. Unlike the hierarchical IDs these are + // allocated densely but don't tell you anything about nesting. we use // these when we run out of space in the GUID to store the path. MultiByte1 = 0xC, // 1 byte follows. If this Nibble is in the high bits, it the high bits of the number are stored in the low nibble. // commented out because the code does not explicitly reference the names (but they are logically defined). - // MultiByte2 = 0xD, // 2 bytes follow (we don't bother with the nibble optimzation) - // MultiByte3 = 0xE, // 3 bytes follow (we don't bother with the nibble optimzation) - // MultiByte4 = 0xF, // 4 bytes follow (we don't bother with the nibble optimzation) + // MultiByte2 = 0xD, // 2 bytes follow (we don't bother with the nibble optimization) + // MultiByte3 = 0xE, // 3 bytes follow (we don't bother with the nibble optimization) + // MultiByte4 = 0xF, // 4 bytes follow (we don't bother with the nibble optimization) } - /// Add the acivity id 'id' to the output Guid 'outPtr' starting at the offset 'whereToAddId' + /// Add the activity id 'id' to the output Guid 'outPtr' starting at the offset 'whereToAddId' /// Thus if this number is 6 that is where 'id' will be added. This will return 13 (12 /// is the maximum number of bytes that fit in a GUID) if the path did not fit. /// If 'overflow' is true, then the number is encoded as an 'overflow number (which has a @@ -462,7 +481,7 @@ namespace System.Diagnostics.Tracing // Do we have an odd nibble? If so flush it or use it for the 12 byte case. if (ptr < endPtr && *ptr != 0) { - // If the value < 4096 we can use the nibble we are otherwise just outputing as padding. + // If the value < 4096 we can use the nibble we are otherwise just outputting as padding. if (id < 4096) { // Indicate this is a 1 byte multicode with 4 high order bits in the lower nibble. @@ -473,7 +492,7 @@ namespace System.Diagnostics.Tracing } // Write out the bytes. - while(0 < len) + while (0 < len) { if (endPtr <= ptr) { @@ -517,13 +536,14 @@ namespace System.Diagnostics.Tracing readonly internal string m_name; // The name used in the 'start' and 'stop' APIs to help match up readonly long m_uniqueId; // a small number that makes this activity unique among its siblings - internal readonly Guid m_guid; // Activity Guid, it is bascially an encoding of the Path() (see CreateActivityPathGuid) + internal readonly Guid m_guid; // Activity Guid, it is basically an encoding of the Path() (see CreateActivityPathGuid) internal readonly int m_activityPathGuidOffset; // Keeps track of where in m_guid the causality path stops (used to generated child GUIDs) internal readonly int m_level; // current depth of the Path() of the activity (used to keep recursion under control) readonly internal EventActivityOptions m_eventOptions; // Options passed to start. internal long m_lastChildID; // used to create a unique ID for my children activities internal int m_stopped; // This work item has stopped readonly internal ActivityInfo m_creator; // My parent (creator). Forms the Path() for the activity. + readonly internal Guid m_activityIdToRestore; // The Guid to restore after a stop. #endregion } @@ -532,26 +552,50 @@ namespace System.Diagnostics.Tracing // with m_current.ActivityID void ActivityChanging(AsyncLocalValueChangedArgs args) { - if (args.PreviousValue == args.CurrentValue) + ActivityInfo cur = args.CurrentValue; + ActivityInfo prev = args.PreviousValue; + + // Are we popping off a value? (we have a prev, and it creator is cur) + // Then check if we should use the GUID at the time of the start event + if (prev != null && prev.m_creator == cur) + { + // If the saved activity ID is not the same as the creator activity + // that takes precedence (it means someone explicitly did a SetActivityID) + // Set it to that and get out + if (cur == null || prev.m_activityIdToRestore != cur.ActivityId) + { + EventSource.SetCurrentThreadActivityId(prev.m_activityIdToRestore); return; + } + } - if (args.CurrentValue != null) + // OK we did not have an explicit SetActivityID set. Then we should be + // setting the activity to current ActivityInfo. However that activity + // might be dead, in which case we should skip it, so we never set + // the ID to dead things. + while (cur != null) { - // Allow subsequent activities inside this thread to automatically get the current activity ID. - EventSource.SetCurrentThreadActivityId(args.CurrentValue.ActivityId); + // We found a live activity (typically the first time), set it to that. + if (cur.m_stopped == 0) + { + EventSource.SetCurrentThreadActivityId(cur.ActivityId); + return; + } + cur = cur.m_creator; } - else - EventSource.SetCurrentThreadActivityId(Guid.Empty); + // we can get here if there is no information on our activity stack (everything is dead) + // currently we do nothing, as that seems better than setting to Guid.Emtpy. } /// - /// Async local variables have the propery that the are automatically copied whenever a task is created and used + /// Async local variables have the property that the are automatically copied whenever a task is created and used /// while that task is running. Thus m_current 'flows' to any task that is caused by the current thread that /// last set it. /// /// This variable points a a linked list that represents all Activities that have started but have not stopped. /// AsyncLocal m_current; + bool m_checkedForEnable; // Singleton private static ActivityTracker s_activityTrackerInstance = new ActivityTracker(); @@ -563,4 +607,70 @@ namespace System.Diagnostics.Tracing #endregion } + +#if ES_BUILD_STANDALONE + /******************************** SUPPORT *****************************/ + /// + /// This is supplied by the framework. It is has the semantics that the value is copied to any new Tasks that is created + /// by the current task. Thus all causally related code gets this value. Note that reads and writes to this VARIABLE + /// (not what it points it) to this does not need to be protected by locks because it is inherently thread local (you always + /// only get your thread local copy which means that you never have races. + /// + /// + [EventSource(Name="Microsoft.Tasks.Nuget")] + internal class TplEtwProvider : EventSource + { + public class Keywords + { + public const EventKeywords Debug = (EventKeywords) 1; + } + + public static TplEtwProvider Log = new TplEtwProvider(); + public bool Debug { get { return IsEnabled(EventLevel.Verbose, Keywords.Debug); } } + + public void DebugFacilityMessage(string Facility, string Message) { WriteEvent(1, Facility, Message); } + public void DebugFacilityMessage1(string Facility, string Message, string Arg) { WriteEvent(2, Facility, Message, Arg); } + public void SetActivityId(Guid Id) { WriteEvent(3, Id); } + } +#endif + +#if ES_BUILD_AGAINST_DOTNET_V35 || ES_BUILD_PCL || NO_ASYNC_LOCAL + + internal sealed class AsyncLocalValueChangedArgs + { + public AsyncLocalValueChangedArgs() + { + } + + public T PreviousValue { get { return default(T); } } + public T CurrentValue { get { return default(T); } } + + } + + internal sealed class AsyncLocal + { + public AsyncLocal() + { + } + + public AsyncLocal(Action> valueChangedHandler) + { + + } + + public T Value + { + get + { + object obj = null; // TODO FIX + return (obj == null) ? default(T) : (T)obj; + } + set + { + // TODO FIX + } + } + } +#endif + } diff --git a/src/mscorlib/src/System/Diagnostics/Eventing/EventProvider.cs b/src/mscorlib/src/System/Diagnostics/Eventing/EventProvider.cs index c2c2906..057d2d5 100644 --- a/src/mscorlib/src/System/Diagnostics/Eventing/EventProvider.cs +++ b/src/mscorlib/src/System/Diagnostics/Eventing/EventProvider.cs @@ -107,28 +107,13 @@ namespace System.Diagnostics.Tracing Other = 5, }; - // - // - // - /// - /// Constructs a new EventProvider. This causes the class to be registered with the OS and - /// if an ETW controller turns on the logging then logging will start. - /// - /// The GUID that identifies this provider to the system. - [System.Security.SecurityCritical] -#pragma warning disable 618 - [PermissionSet(SecurityAction.Demand, Unrestricted = true)] -#pragma warning restore 618 - [SuppressMessage("Microsoft.Naming", "CA1720:IdentifiersShouldNotContainTypeNames", MessageId = "guid")] - protected EventProvider(Guid providerGuid) - { - m_providerId = providerGuid; + // Because callbacks happen on registration, and we need the callbacks for those setup + // we can't call Register in the constructor. // - // Register the ProviderId with ETW - // - Register(providerGuid); - } - + // Note that EventProvider should ONLY be used by EventSource. In particular because + // it registers a callback from native code you MUST dispose it BEFORE shutdown, otherwise + // you may get native callbacks during shutdown when we have destroyed the delegate. + // EventSource has special logic to do this, no one else should be calling EventProvider. internal EventProvider() { } @@ -249,6 +234,7 @@ namespace System.Diagnostics.Tracing // // // + // TODO Check return code from UnsafeNativeMethods.ManifestEtw.EventUnregister [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA1806:DoNotIgnoreMethodResults", MessageId = "Microsoft.Win32.UnsafeNativeMethods.ManifestEtw.EventUnregister(System.Int64)"), System.Security.SecurityCritical] private unsafe void Deregister() { @@ -281,13 +267,11 @@ namespace System.Diagnostics.Tracing { // This is an optional callback API. We will therefore ignore any failures that happen as a // result of turning on this provider as to not crash the app. - // EventSource has code to validate whther initialization it expected to occur actually occurred + // EventSource has code to validate whether initialization it expected to occur actually occurred try { ControllerCommand command = ControllerCommand.Update; IDictionary args = null; - byte[] data; - int keyIndex; bool skipFinalOnControllerCommand = false; if (controlCode == UnsafeNativeMethods.ManifestEtw.EVENT_CONTROL_CODE_ENABLE_PROVIDER) { @@ -296,6 +280,12 @@ namespace System.Diagnostics.Tracing m_anyKeywordMask = anyKeyword; m_allKeywordMask = allKeyword; + // ES_SESSION_INFO is a marker for additional places we #ifdeffed out to remove + // references to EnumerateTraceGuidsEx. This symbol is actually not used because + // today we use FEATURE_ACTIVITYSAMPLING to determine if this code is there or not. + // However we put it in the #if so that we don't lose the fact that this feature + // switch is at least partially independent of FEATURE_ACTIVITYSAMPLING + List> sessionsChanged = GetSessions(); foreach (var session in sessionsChanged) { @@ -312,6 +302,8 @@ namespace System.Diagnostics.Tracing filterData = null; // read filter data only when a session is being *added* + byte[] data; + int keyIndex; if (bEnabling && GetDataFromController(etwSessionId, filterData, out command, out data, out keyIndex)) { @@ -348,7 +340,7 @@ namespace System.Diagnostics.Tracing command = ControllerCommand.SendManifest; } else - return; // per spec you ignore commands you don't recognise. + return; // per spec you ignore commands you don't recognize. if (!skipFinalOnControllerCommand) OnControllerCommand(command, args, 0, 0); @@ -398,7 +390,7 @@ namespace System.Diagnostics.Tracing // (present in the m_liveSessions but not in the new liveSessionList) if (m_liveSessions != null) { - foreach(SessionInfo s in m_liveSessions) + foreach (SessionInfo s in m_liveSessions) { int idx; if ((idx = IndexOfSessionInList(liveSessionList, s.etwSessionId)) < 0 || @@ -446,12 +438,12 @@ namespace System.Diagnostics.Tracing if (bitcount(sessionIdBitMask) == 1) { // activity-tracing-aware etw session - sessionList.Add(new SessionInfo(bitindex(sessionIdBitMask)+1, etwSessionId)); + sessionList.Add(new SessionInfo(bitindex(sessionIdBitMask) + 1, etwSessionId)); } else { // legacy etw session - sessionList.Add(new SessionInfo(bitcount((uint)SessionMask.All)+1, etwSessionId)); + sessionList.Add(new SessionInfo(bitcount((uint)SessionMask.All) + 1, etwSessionId)); } } @@ -463,6 +455,15 @@ namespace System.Diagnostics.Tracing [System.Security.SecurityCritical] private unsafe void GetSessionInfo(Action action) { + // We wish the EventSource package to be legal for Windows Store applications. + // Currently EnumerateTraceGuidsEx is not an allowed API, so we avoid its use here + // and use the information in the registry instead. This means that ETW controllers + // that do not publish their intent to the registry (basically all controllers EXCEPT + // TraceEventSesion) will not work properly + + // However the framework version of EventSource DOES have ES_SESSION_INFO defined and thus + // does not have this issue. +#if ES_SESSION_INFO int buffSize = 256; // An initial guess that probably works most of the time. byte* buffer; for (; ; ) @@ -501,6 +502,49 @@ namespace System.Diagnostics.Tracing var structBase = (byte*)providerInstance; providerInstance = (UnsafeNativeMethods.ManifestEtw.TRACE_PROVIDER_INSTANCE_INFO*)&structBase[providerInstance->NextOffset]; } +#else +#if !ES_BUILD_PCL // TODO command arguments don't work on PCL builds... + // Determine our session from what is in the registry. + string regKey = @"\Microsoft\Windows\CurrentVersion\Winevt\Publishers\{" + m_providerId + "}"; + if (System.Runtime.InteropServices.Marshal.SizeOf(typeof(IntPtr)) == 8) + regKey = @"Software" + @"\Wow6432Node" + regKey; + else + regKey = @"Software" + regKey; + + var key = Microsoft.Win32.Registry.LocalMachine.OpenSubKey(regKey); + if (key != null) + { + foreach (string valueName in key.GetValueNames()) + { + if (valueName.StartsWith("ControllerData_Session_")) + { + string strId = valueName.Substring(23); // strip of the ControllerData_Session_ + int etwSessionId; + if (int.TryParse(strId, out etwSessionId)) + { + // we need to assert this permission for partial trust scenarios + (new RegistryPermission(RegistryPermissionAccess.Read, regKey)).Assert(); + var data = key.GetValue(valueName) as byte[]; + if (data != null) + { + var dataAsString = System.Text.Encoding.UTF8.GetString(data); + int keywordIdx = dataAsString.IndexOf("EtwSessionKeyword"); + if (0 <= keywordIdx) + { + int startIdx = keywordIdx + 18; + int endIdx = dataAsString.IndexOf('\0', startIdx); + string keywordBitString = dataAsString.Substring(startIdx, endIdx-startIdx); + int keywordBit; + if (0 < endIdx && int.TryParse(keywordBitString, out keywordBit)) + action(etwSessionId, 1L << keywordBit); + } + } + } + } + } + } +#endif +#endif } /// @@ -563,7 +607,7 @@ namespace System.Diagnostics.Tracing data = new byte[filterData->Size]; Marshal.Copy((IntPtr)filterData->Ptr, data, 0, data.Length); } - command = (ControllerCommand) filterData->Type; + command = (ControllerCommand)filterData->Type; return true; } @@ -618,11 +662,6 @@ namespace System.Diagnostics.Tracing return false; } - // There's a small window of time in EventSource code where m_provider is non-null but the - // m_regHandle has not been set yet. This method allows EventSource to check if this is the case... - internal bool IsValid() - { return m_regHandle != 0; } - [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Design", "CA1024:UsePropertiesWhereAppropriate")] public static WriteEventErrorCode GetLastWriteEventError() { @@ -887,6 +926,9 @@ namespace System.Diagnostics.Tracing /// /// Event Descriptor for this event. /// + /// + /// A pointer to the activity ID GUID to log + /// /// /// childActivityID is marked as 'related' to the current activity ID. /// @@ -979,7 +1021,7 @@ namespace System.Diagnostics.Tracing } } - // update argCount based on ctual number of arguments written to 'userData' + // update argCount based on actual number of arguments written to 'userData' argCount = (int)(userDataPtr - userData); if (totalEventSize > s_traceEventMaximumSize) @@ -1092,6 +1134,9 @@ namespace System.Diagnostics.Tracing /// /// Event Descriptor for this event. /// + /// + /// A pointer to the activity ID to log + /// /// /// If this event is generating a child activity (WriteEventTransfer related activity) this is child activity /// This can be null for events that do not generate a child activity. @@ -1174,11 +1219,11 @@ namespace System.Diagnostics.Tracing return status; } - static int[] nibblebits = {0, 1, 1, 2, 1, 2, 2, 3, 1, 2, 2, 3, 2, 3, 3, 4}; + static int[] nibblebits = { 0, 1, 1, 2, 1, 2, 2, 3, 1, 2, 2, 3, 2, 3, 3, 4 }; private static int bitcount(uint n) { int count = 0; - for(; n != 0; n = n >> 4) + for (; n != 0; n = n >> 4) count += nibblebits[n & 0x0f]; return count; } diff --git a/src/mscorlib/src/System/Diagnostics/Eventing/EventSource.cs b/src/mscorlib/src/System/Diagnostics/Eventing/EventSource.cs index 80a7a47..793a7f4 100644 --- a/src/mscorlib/src/System/Diagnostics/Eventing/EventSource.cs +++ b/src/mscorlib/src/System/Diagnostics/Eventing/EventSource.cs @@ -1055,28 +1055,17 @@ namespace System.Diagnostics.Tracing { if (m_eventSourceEnabled) { - EventSource.EventData* descrs = stackalloc EventSource.EventData[2]; - if (arg1 == null || arg1.Length == 0) + if (arg1 == null) arg1 = new byte[0]; + int blobSize = arg1.Length; + fixed (byte* blob = &arg1[0]) { - int blobSize = 0; + EventSource.EventData* descrs = stackalloc EventSource.EventData[2]; descrs[0].DataPointer = (IntPtr)(&blobSize); descrs[0].Size = 4; - descrs[1].DataPointer = (IntPtr)(&blobSize); // valid address instead of empty content - descrs[1].Size = 0; + descrs[1].DataPointer = (IntPtr)blob; + descrs[1].Size = blobSize; WriteEventCore(eventId, 2, descrs); } - else - { - int blobSize = arg1.Length; - fixed (byte* blob = &arg1[0]) - { - descrs[0].DataPointer = (IntPtr)(&blobSize); - descrs[0].Size = 4; - descrs[1].DataPointer = (IntPtr)blob; - descrs[1].Size = blobSize; - WriteEventCore(eventId, 2, descrs); - } - } } } @@ -1086,30 +1075,19 @@ namespace System.Diagnostics.Tracing { if (m_eventSourceEnabled) { - EventSource.EventData* descrs = stackalloc EventSource.EventData[3]; - descrs[0].DataPointer = (IntPtr)(&arg1); - descrs[0].Size = 8; - if (arg2 == null || arg2.Length == 0) + if (arg2 == null) arg2 = new byte[0]; + int blobSize = arg2.Length; + fixed (byte* blob = &arg2[0]) { - int blobSize = 0; + EventSource.EventData* descrs = stackalloc EventSource.EventData[3]; + descrs[0].DataPointer = (IntPtr)(&arg1); + descrs[0].Size = 8; descrs[1].DataPointer = (IntPtr)(&blobSize); descrs[1].Size = 4; - descrs[2].DataPointer = (IntPtr)(&blobSize); // valid address instead of empty contents - descrs[2].Size = 0; + descrs[2].DataPointer = (IntPtr)blob; + descrs[2].Size = blobSize; WriteEventCore(eventId, 3, descrs); } - else - { - int blobSize = arg2.Length; - fixed (byte* blob = &arg2[0]) - { - descrs[1].DataPointer = (IntPtr)(&blobSize); - descrs[1].Size = 4; - descrs[2].DataPointer = (IntPtr)blob; - descrs[2].Size = blobSize; - WriteEventCore(eventId, 3, descrs); - } - } } } @@ -1307,6 +1285,7 @@ namespace System.Diagnostics.Tracing } long origKwd = unchecked((long)((ulong)m_eventData[eventId].Descriptor.Keywords & ~(SessionMask.All.ToEventKeywords()))); + // TODO: activity ID support EventSourceOptions opt = new EventSourceOptions { Keywords = (EventKeywords)unchecked((long)etwSessions.ToEventKeywords() | origKwd), @@ -1803,6 +1782,9 @@ namespace System.Diagnostics.Tracing [SecurityCritical] private unsafe object DecodeObject(int eventId, int parameterId, ref EventSource.EventData* data) { + // TODO FIX : We use reflection which in turn uses EventSource, right now we carefully avoid + // the recursion, but can we do this in a robust way? + IntPtr dataPointer = data->DataPointer; // advance to next EventData in array ++data; @@ -1896,6 +1878,7 @@ namespace System.Diagnostics.Tracing } else if (dataType == typeof(byte*)) { + // TODO: how do we want to handle this? For now we ignore it... return null; } else @@ -1906,6 +1889,9 @@ namespace System.Diagnostics.Tracing goto Again; } + // TODO FIX NOW Assuming that it is a string at this point is really likely to be fragile + // We should do something better. + // Everything else is marshaled as a string. // ETW strings are NULL-terminated, so marshal everything up to the first // null in the string. @@ -1936,8 +1922,24 @@ namespace System.Diagnostics.Tracing { Contract.Assert(m_eventData != null); // You must have initialized this if you enabled the source. if (childActivityID != null) + { ValidateEventOpcodeForTransfer(ref m_eventData[eventId]); + // If you use WriteEventWithRelatedActivityID you MUST declare the first argument to be a GUID + // with the name 'relatedActivityID, and NOT pass this argument to the WriteEvent method. + // During manifest creation we modify the ParameterInfo[] that we store to strip out any + // first parameter that is of type Guid and named "relatedActivityId." Thus, if you call + // WriteEventWithRelatedActivityID from a method that doesn't name its first parameter correctly + // we can end up in a state where the ParameterInfo[] doesn't have its first parameter stripped, + // and this leads to a mismatch between the number of arguments and the number of ParameterInfos, + // which would cause a cryptic IndexOutOfRangeException later if we don't catch it here. + if (!m_eventData[eventId].HasRelatedActivityID) + { + throw new ArgumentException(Environment.GetResourceString("EventSource_NoRelatedActivityId")); + } + } + + LogEventArgsMismatches(m_eventData[eventId].Parameters, args); #if FEATURE_MANAGED_ETW if (m_eventData[eventId].EnabledForETW) { @@ -2014,6 +2016,7 @@ namespace System.Diagnostics.Tracing } long origKwd = unchecked((long)((ulong)m_eventData[eventId].Descriptor.Keywords & ~(SessionMask.All.ToEventKeywords()))); + // TODO: activity ID support EventSourceOptions opt = new EventSourceOptions { Keywords = (EventKeywords)unchecked((long)(ulong)etwSessions | origKwd), @@ -2087,8 +2090,8 @@ namespace System.Diagnostics.Tracing if (eventTypes == null) { eventTypes = new TraceLoggingEventTypes(m_eventData[eventId].Name, - EventTags.None, - m_eventData[eventId].Parameters); + EventTags.None, + m_eventData[eventId].Parameters); Interlocked.CompareExchange(ref m_eventData[eventId].TraceLoggingEventTypes, eventTypes, null); } var eventData = new object[eventTypes.typeInfos.Length]; @@ -2099,6 +2102,45 @@ namespace System.Diagnostics.Tracing return eventData; } + /// + /// We expect that the arguments to the Event method and the arguments to WriteEvent match. This function + /// checks that they in fact match and logs a warning to the debugger if they don't. + /// + /// + /// + private void LogEventArgsMismatches(ParameterInfo[] infos, object[] args) + { +#if !ES_BUILD_PCL + // It would be nice to have this on PCL builds, but it would be pointless since there isn't support for + // writing to the debugger log on PCL. + bool typesMatch = args.Length == infos.Length; + + int i = 0; + while (typesMatch && i < args.Length) + { + Type pType = infos[i].ParameterType; + + // Checking to see if the Parameter types (from the Event method) match the supplied argument types. + // Fail if one of two things hold : either the argument type is not equal to the parameter type, or the + // argument is null and the parameter type is non-nullable. + if ((args[i] != null && (args[i].GetType() != pType)) + || (args[i] == null && (!(pType.IsGenericType && pType.GetGenericTypeDefinition() == typeof(Nullable<>)))) + ) + { + typesMatch = false; + break; + } + + ++i; + } + + if (!typesMatch) + { + System.Diagnostics.Debugger.Log(0, null, Environment.GetResourceString("EventSource_VarArgsParameterMismatch") + "\r\n"); + } +#endif //!ES_BUILD_PCL + } + [SecurityCritical] unsafe private void WriteToAllListeners(int eventId, Guid* childActivityID, int eventDataCount, EventSource.EventData* data) { @@ -2389,6 +2431,7 @@ namespace System.Diagnostics.Tracing { m_EventSourceExceptionRecurenceCount++; + // TODO Create variations of EventSourceException that indicate more information using the error code. switch (EventProvider.GetLastWriteEventError()) { case EventProvider.WriteEventErrorCode.EventTooBig: @@ -2425,7 +2468,8 @@ namespace System.Diagnostics.Tracing private void ValidateEventOpcodeForTransfer(ref EventMetadata eventData) { if ((EventOpcode)eventData.Descriptor.Opcode != EventOpcode.Send && - (EventOpcode)eventData.Descriptor.Opcode != EventOpcode.Receive) + (EventOpcode)eventData.Descriptor.Opcode != EventOpcode.Receive && + (EventOpcode)eventData.Descriptor.Opcode != EventOpcode.Start) { ThrowEventSourceException(); } @@ -2481,6 +2525,8 @@ namespace System.Diagnostics.Tracing public EventTags Tags; public bool EnabledForAnyListener; // true if any dispatcher has this event turned on public bool EnabledForETW; // is this event on for the OS ETW data dispatcher? + + public bool HasRelatedActivityID; // Set if the event method's first parameter is a Guid named 'relatedActivityId' #if !FEATURE_ACTIVITYSAMPLING #pragma warning disable 0649 #endif @@ -2490,7 +2536,7 @@ namespace System.Diagnostics.Tracing #endif public string Name; // the name of the event public string Message; // If the event has a message associated with it, this is it. - public ParameterInfo[] Parameters; + public ParameterInfo[] Parameters; // TODO can we remove? public TraceLoggingEventTypes TraceLoggingEventTypes; public EventActivityOptions ActivityOptions; @@ -2762,6 +2808,7 @@ namespace System.Diagnostics.Tracing { if (commandArgs.Command == EventCommand.SendManifest) { + // TODO: should we generate the manifest here if we hadn't already? if (m_rawManifest != null) SendManifest(m_rawManifest); } @@ -2980,6 +3027,7 @@ namespace System.Diagnostics.Tracing m_rawManifest = CreateManifestAndDescriptors(this.GetType(), Name, this); Contract.Assert(m_eventData != null); + // TODO Enforce singleton pattern foreach (WeakReference eventSourceRef in EventListener.s_EventSources) { EventSource eventSource = eventSourceRef.Target as EventSource; @@ -3304,7 +3352,7 @@ namespace System.Diagnostics.Tracing manifest.AddKeyword("Session0", (long)0x8000 << 32); } - if (eventSourceType.Name != "EventSource") + if (eventSourceType != typeof(EventSource)) { for (int i = 0; i < methods.Length; i++) { @@ -3418,7 +3466,7 @@ namespace System.Diagnostics.Tracing } } - RemoveFirstArgIfRelatedActivityId(ref args); + bool hasRelatedActivityID = RemoveFirstArgIfRelatedActivityId(ref args); if (!(source != null && source.SelfDescribingEvents)) { manifest.StartEvent(eventName, eventAttribute); @@ -3450,7 +3498,7 @@ namespace System.Diagnostics.Tracing // overwrite inline message with the localized message if (msg != null) eventAttribute.Message = msg; - AddEventDescriptor(ref eventData, eventName, eventAttribute, args); + AddEventDescriptor(ref eventData, eventName, eventAttribute, args, hasRelatedActivityID); } } } @@ -3515,7 +3563,7 @@ namespace System.Diagnostics.Tracing return bNeedsManifest ? res : null; } - private static void RemoveFirstArgIfRelatedActivityId(ref ParameterInfo[] args) + private static bool RemoveFirstArgIfRelatedActivityId(ref ParameterInfo[] args) { // If the first parameter is (case insensitive) 'relatedActivityId' then skip it. if (args.Length > 0 && args[0].ParameterType == typeof(Guid) && @@ -3524,7 +3572,11 @@ namespace System.Diagnostics.Tracing var newargs = new ParameterInfo[args.Length - 1]; Array.Copy(args, 1, newargs, 0, args.Length - 1); args = newargs; + + return true; } + + return false; } // adds a enumeration (keyword, opcode, task or channel) represented by 'staticField' @@ -3568,7 +3620,8 @@ namespace System.Diagnostics.Tracing // with the code:EventAttribute 'eventAttribute'. resourceManger may be null in which case we populate it // it is populated if we need to look up message resources private static void AddEventDescriptor(ref EventMetadata[] eventData, string eventName, - EventAttribute eventAttribute, ParameterInfo[] eventParameters) + EventAttribute eventAttribute, ParameterInfo[] eventParameters, + bool hasRelatedActivityID) { if (eventData == null || eventData.Length <= eventAttribute.EventId) { @@ -3595,6 +3648,7 @@ namespace System.Diagnostics.Tracing eventData[eventAttribute.EventId].Parameters = eventParameters; eventData[eventAttribute.EventId].Message = eventAttribute.Message; eventData[eventAttribute.EventId].ActivityOptions = eventAttribute.ActivityOptions; + eventData[eventAttribute.EventId].HasRelatedActivityID = hasRelatedActivityID; } // Helper used by code:CreateManifestAndDescriptors that trims the m_eventData array to the correct @@ -3615,7 +3669,7 @@ namespace System.Diagnostics.Tracing eventData = newValues; } } - + // Helper used by code:EventListener.AddEventSource and code:EventListener.EventListener // when a listener gets attached to a eventSource internal void AddListener(EventListener listener) @@ -3650,6 +3704,7 @@ namespace System.Diagnostics.Tracing } // We give a task to things if they don't have one. + // TODO this is moderately expensive (N*N). We probably should not even bother.... Contract.Assert(eventAttribute.Task != EventTask.None || eventAttribute.Opcode != EventOpcode.Info); for (int idx = 0; idx < eventData.Length; ++idx) { @@ -3700,7 +3755,7 @@ namespace System.Diagnostics.Tracing eventsByName = new Dictionary(); if (eventsByName.ContainsKey(evtName)) - manifest.ManifestError(Environment.GetResourceString("EventSource_EventNameReused", evtName)); + manifest.ManifestError(Environment.GetResourceString("EventSource_EventNameReused", evtName), true); eventsByName[evtName] = evtName; } @@ -4103,50 +4158,50 @@ namespace System.Diagnostics.Tracing /// public abstract class EventListener : IDisposable { + private event EventHandler _EventSourceCreated; + /// - /// Create a new EventListener in which all events start off turned off (use EnableEvents to turn - /// them on). + /// This event is raised whenever a new eventSource is 'attached' to the dispatcher. + /// This can happen for all existing EventSources when the EventListener is created + /// as well as for any EventSources that come into existence after the EventListener + /// has been created. + /// + /// These 'catch up' events are called during the construction of the EventListener. + /// Subclasses need to be prepared for that. + /// + /// In a multi-threaded environment, it is possible that 'EventSourceEventWrittenCallback' + /// events for a particular eventSource to occur BEFORE the EventSourceCreatedCallback is issued. /// - protected EventListener() - { - lock (EventListenersLock) + public event EventHandler EventSourceCreated + { + add { - // Disallow creating EventListener reentrancy. - if (s_CreatingListener) - throw new InvalidOperationException(Environment.GetResourceString("EventSource_ListenerCreatedInsideCallback")); - - try - { - s_CreatingListener = true; + CallBackForExistingEventSources(false, value); - // Add to list of listeners in the system, do this BEFORE firing the 'OnEventSourceCreated' so that - // Those added sources see this listener. - this.m_Next = s_Listeners; - s_Listeners = this; - - // Find all existing eventSources call OnEventSourceCreated to 'catchup' - // Note that we DO have reentrancy here because 'AddListener' calls out to user code (via OnEventSourceCreated callback) - // We tolerate this by iterating over a copy of the list here. New event sources will take care of adding listeners themselves - // EventSources are not guaranteed to be added at the end of the s_EventSource list -- We re-use slots when a new source - // is created. - WeakReference[] eventSourcesSnapshot = s_EventSources.ToArray(); + this._EventSourceCreated = (EventHandler)Delegate.Combine(_EventSourceCreated, value); + } + remove + { + this._EventSourceCreated = (EventHandler)Delegate.Remove(_EventSourceCreated, value); + } + } - for (int i = 0; i < eventSourcesSnapshot.Length; i++) - { - WeakReference eventSourceRef = eventSourcesSnapshot[i]; - EventSource eventSource = eventSourceRef.Target as EventSource; - if (eventSource != null) - eventSource.AddListener(this); // This will cause the OnEventSourceCreated callback to fire. - } + /// + /// This event is raised whenever an event has been written by a EventSource for which + /// the EventListener has enabled events. + /// + public event EventHandler EventWritten; - Validate(); - } - finally - { - s_CreatingListener = false; - } - } + /// + /// Create a new EventListener in which all events start off turned off (use EnableEvents to turn + /// them on). + /// + protected EventListener() + { + // This will cause the OnEventSourceCreated callback to fire. + CallBackForExistingEventSources(true, (obj, args) => args.EventSource.AddListener(this) ); } + /// /// Dispose should be called when the EventListener no longer desires 'OnEvent*' callbacks. Because /// there is an internal list of strong references to all EventListeners, calling 'Dispose' directly @@ -4284,12 +4339,31 @@ namespace System.Diagnostics.Tracing /// for a particular eventSource to occur BEFORE the OnEventSourceCreated is issued. /// /// - internal protected virtual void OnEventSourceCreated(EventSource eventSource) { } + internal protected virtual void OnEventSourceCreated(EventSource eventSource) + { + EventHandler callBack = this._EventSourceCreated; + if(callBack != null) + { + EventSourceCreatedEventArgs args = new EventSourceCreatedEventArgs(); + args.EventSource = eventSource; + callBack(this, args); + } + } + /// /// This method is called whenever an event has been written by a EventSource for which /// the EventListener has enabled events. /// - internal protected abstract void OnEventWritten(EventWrittenEventArgs eventData); + /// + internal protected virtual void OnEventWritten(EventWrittenEventArgs eventData) + { + EventHandler callBack = this.EventWritten; + if (callBack != null) + { + callBack(this, eventData); + } + } + #region private /// @@ -4363,11 +4437,14 @@ namespace System.Diagnostics.Tracing // See bug 724140 for more private static void DisposeOnShutdown(object sender, EventArgs e) { - foreach (var esRef in s_EventSources) + lock(EventListenersLock) { - EventSource es = esRef.Target as EventSource; - if (es != null) - es.Dispose(); + foreach (var esRef in s_EventSources) + { + EventSource es = esRef.Target as EventSource; + if (es != null) + es.Dispose(); + } } } @@ -4478,6 +4555,55 @@ namespace System.Diagnostics.Tracing } } + private void CallBackForExistingEventSources(bool addToListenersList, EventHandler callback) + { + lock (EventListenersLock) + { + // Disallow creating EventListener reentrancy. + if (s_CreatingListener) + throw new InvalidOperationException(Environment.GetResourceString("EventSource_ListenerCreatedInsideCallback")); + + try + { + s_CreatingListener = true; + + if (addToListenersList) + { + // Add to list of listeners in the system, do this BEFORE firing the 'OnEventSourceCreated' so that + // Those added sources see this listener. + this.m_Next = s_Listeners; + s_Listeners = this; + } + + // Find all existing eventSources call OnEventSourceCreated to 'catchup' + // Note that we DO have reentrancy here because 'AddListener' calls out to user code (via OnEventSourceCreated callback) + // We tolerate this by iterating over a copy of the list here. New event sources will take care of adding listeners themselves + // EventSources are not guaranteed to be added at the end of the s_EventSource list -- We re-use slots when a new source + // is created. + WeakReference[] eventSourcesSnapshot = s_EventSources.ToArray(); + + for (int i = 0; i < eventSourcesSnapshot.Length; i++) + { + WeakReference eventSourceRef = eventSourcesSnapshot[i]; + EventSource eventSource = eventSourceRef.Target as EventSource; + if (eventSource != null) + { + EventSourceCreatedEventArgs args = new EventSourceCreatedEventArgs(); + args.EventSource = eventSource; + callback(this, args); + } + } + + Validate(); + } + finally + { + s_CreatingListener = false; + } + } + + } + // Instance fields internal volatile EventListener m_Next; // These form a linked list in s_Listeners #if FEATURE_ACTIVITYSAMPLING @@ -4582,6 +4708,21 @@ namespace System.Diagnostics.Tracing } /// + /// EventSourceCreatedEventArgs is passed to + /// + public class EventSourceCreatedEventArgs : EventArgs + { + /// + /// The EventSource that is attaching to the listener. + /// + public EventSource EventSource + { + get; + internal set; + } + } + + /// /// EventWrittenEventArgs is passed to the user-provided override for /// when an event is fired. /// @@ -4930,6 +5071,7 @@ namespace System.Diagnostics.Tracing public NonEventAttribute() { } } + // FUTURE we may want to expose this at some point once we have a partner that can help us validate the design. #if FEATURE_MANAGED_ETW_CHANNELS /// /// EventChannelAttribute allows customizing channels supported by an EventSource. This attribute must be @@ -4978,6 +5120,9 @@ namespace System.Diagnostics.Tracing /// public string ImportChannel { get; set; } #endif + + // TODO: there is a convention that the name is the Provider/Type Should we provide an override? + // public string Name { get; set; } } /// @@ -5932,6 +6077,8 @@ namespace System.Diagnostics.Tracing name, ((EventChannel)value).ToString())); } + // TODO: validate there are no conflicting manifest exposed names (generally following the format "provider/type") + ulong kwd = GetChannelKeyword(chValue); if (channelTab == null) @@ -5959,7 +6106,7 @@ namespace System.Diagnostics.Tracing { if (this.channelTab == null) { - return Array.Empty(); + return new ulong[0]; } // We create an array indexed by the channel id for fast look up. @@ -6034,7 +6181,8 @@ namespace System.Diagnostics.Tracing } numParams++; templates.Append(" internal string Name { diff --git a/src/mscorlib/src/System/Diagnostics/Eventing/TraceLogging/SimpleTypeInfos.cs b/src/mscorlib/src/System/Diagnostics/Eventing/TraceLogging/SimpleTypeInfos.cs index 461ed76..d262bdb 100644 --- a/src/mscorlib/src/System/Diagnostics/Eventing/TraceLogging/SimpleTypeInfos.cs +++ b/src/mscorlib/src/System/Diagnostics/Eventing/TraceLogging/SimpleTypeInfos.cs @@ -836,6 +836,15 @@ namespace System.Diagnostics.Tracing { collector.AddBinary(value); } + + public override object GetData(object value) + { + object val = base.GetData(value); + if (null == val) + val = ""; + + return val; + } } /// -- 2.7.4