none
Instrumentation/Logging with Event Tracing for Windows (ETW) - Consuming trace files

    Pregunta

  • I've been looking at solutions to implementation logging/tracing within various Biztalk artifacts (orchestrations, custom pipeline components, etc) and came across a recent article on using Event Tracing for Windows along with a suggested framework to make use of it:

    https://blogs.msdn.com/b/asgisv/archive/2010/05/11/best-practices-for-instrumenting-high-performance-biztalk-solutions.aspx

    After a read through the article, seems like exactly what I'd like to accomplish so I did some testing with an orchestration and have run into a couple issues that I'm hoping someone here might have some experience with if they've also played with the framework from the Microsoft CAT team:

    1.) The framework source includes some batch files to get things going (StartTrace, StopTrace).  When StopTrace is run, it automatically converts the binary file into a text file (using tracefmt.exe).  I went ahead and added 2 warnings and an exception to my test orchestration in an expression shape:

    Microsoft.BizTalk.CAT.BestPractices.Framework.Instrumentation.TraceManager.WorkflowComponent.TraceError("Some error message here");
    Microsoft.BizTalk.CAT.BestPractices.Framework.Instrumentation.TraceManager.CustomComponent.TraceError("Some custom component error message here");
    Microsoft.BizTalk.CAT.BestPractices.Framework.Instrumentation.TraceManager.WorkflowComponent.TraceWarning("Some warning message here");

    The result text files contains the following entries:

    EventTrace
    [0]12B4.1F04::06/17/2010-10:41:06.750 [Event]:Some error message here
    [0]12B4.1F04::06/17/2010-10:41:06.751 [Event]:Some custom component error message here
    [0]12B4.1F04::06/17/2010-10:41:06.751 [Event]:Some warning message here

    Noticeably missing is the level of message (Error, Warning, Info, etc).  If I run DebugView simultaneously, I do see the levels there:

    [4788] ERROR: Some error message here
    [4788] ERROR: Some custom component error message here
    [4788] WARN: Some warning message here

    Anyone know if it's possible to get this information into the text dump files?  There's a "Default.tmf" file that get's used by tracefmt.exe, but it's not clear to me how it could/should be updated

    2.) Not sure how to make the message severity available, I thought I should create 2 different logs -- one for just errors and warnings running all the time, the other for all messages running on an as-needed basis manually.  So I made two calls to the StartTrace batch file:

    CALL StartTrace -log BtsAppErrors -level medium	
    CALL StartTrace -log BtsAppInfo -level high

    ("high" means includes a greater number of message categories, not higher severity)

    However, it seems that only the last run log ever gets events.  Above, the Info log will have all the events, the Errors none, including the Errors.  Is it possible to have the event messages going to two different logs?

    3.) Any recommendations on tools to visualize/view the binary log files?  It seems that Windows Event Viewer can open them, but there is essentially no data associated with the entries, so I'm assuming it's not quite in the correct format for Event Viewer.

    I realize this might be more ETW related than Biztalk, but I've seen a few recent mentions of the article above on this forum which makes me think a few folks might be using it.

    Thanks all,

    Kyle

    jueves, 17 de junio de 2010 16:36

Respuestas

  • Try using the xml output instead. This other article gives some helpful ETW context: http://msdn.microsoft.com/en-us/magazine/cc163437.aspx. It shows the level output in Xml format.

    At the end of the article it mentions using tracerpt to generate a browser readable file. Here is the tracerpt command-line syntax: http://technet.microsoft.com/en-us/library/cc732700(WS.10).aspx

    Thanks,


    If this answers your question, please use the "Answer" button to say so | Ben Cline
    viernes, 18 de junio de 2010 21:07
    Moderador
  • Ben,

    Thank you for the links.  I've read through them and was able to extract the binary log file as XML and upon further inspection, Windows Event Viewer in "XML View" appears to provide similar information for individual event records:

    <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    	<System>
    		<Provider />
    		<EventID>0</EventID>
    		<Version>0</Version>
    		<Level>0</Level>
    		<Task>0</Task>
    		<Opcode>14</Opcode>
    		<Keywords>0x0</Keywords>
    		<TimeCreated SystemTime="2010-06-15T15:56:35.998956500Z" />
    		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
    		<Execution ProcessID="4276" ThreadID="6496" ProcessorID="1" KernelTime="30" UserTime="135" />
    		<Channel />
    		<Computer />
    	</System>
    	<BinaryEventData>...binary data snipped...</BinaryEventData>
    	<ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
    		<EventGuid>{b4955bf0-3af1-4740-b475-99055d3fe9aa}</EventGuid>
    	</ExtendedTracingInfo>
    </Event>

     

    So I think that explains why I don't see alot of information in Event Viewer, there just isn't a lot, with my custom message encoded within BinaryEventData.  Anyways, I dug a bit further because my TraceProvider.TraceIn() calls (within the Microsoft.Biztalk.CAT.BestPractices.Framework project) WERE showing up with "TRACEIN: " event in the log file.  Sure enough, the definition for TraceError that I was using:

        /// <summary>
        /// Writes an error message to the trace. This method is provided for optimal performance when
        /// tracing simple messages which don't require a format string.
        /// </summary>
        /// <param name="message">A string containing the error message to be traced.</param>
        [DebuggerStepThrough()]
        public void TraceError(string message)
        {
    #if DEBUG
          // Write a formatted message into the active trace listeners such as DebugView.
          // This method will only be invoked in a DEBUG build. Once code is compiled in the RELEASE mode, this method call will be omited.
          DebugTimeTrace(FormatStringTraceErrorNoToken, message);
    #endif
          if (IsEnabled)
          {
            TraceMessage(EtwTraceLevel.Error, message);
          }
        }

    So, it's purposely written to not use any format string except to the write out to "active trace listeners such as DebugView" in a debug build, which I was using.  That explains the behavior I was seeing.  If I use the other overload, TraceError(string format, params object[] parameters) I can specify "ERROR: {0}" as the format string and get the behavior I was looking for... or more likely, I'll just update TraceError(string message) to always do the format because that's my desired behavior.

    Questions #1 (using the wrong overload of TraceError) and #3 (I can use Event Viewer and load the binary log) I'm good on then.  I'm still haven't researched #2 anymore where I was having difficultly capturing the same events to two log files, but that's not important to me anymore now that I know I can identify error/warning/info message records within one log file.

    Leonid,

    With regards to just using DebugView, my main hesitation there is based on the article (see post #1) that got me started looking into the Event Tracing for Windows stuff to begin with that gave an example of DebugView sucking 90% CPU during cases with a lot of application instrumentation.  Granted, I haven't actually tried it, so maybe it's not that terrible, I just got scared away ;).

    Thanks for the help all.

     

    • Editado Kyle Stittleburg lunes, 21 de junio de 2010 16:41 trying to make code like pretty
    • Marcado como respuesta Kyle Stittleburg lunes, 21 de junio de 2010 16:42
    lunes, 21 de junio de 2010 16:37

Todas las respuestas

  • Try using the xml output instead. This other article gives some helpful ETW context: http://msdn.microsoft.com/en-us/magazine/cc163437.aspx. It shows the level output in Xml format.

    At the end of the article it mentions using tracerpt to generate a browser readable file. Here is the tracerpt command-line syntax: http://technet.microsoft.com/en-us/library/cc732700(WS.10).aspx

    Thanks,


    If this answers your question, please use the "Answer" button to say so | Ben Cline
    viernes, 18 de junio de 2010 21:07
    Moderador
  • Hi Kyle,

    Maybe this is a suboptimal, but anyway, it is supereasy. :)

    The DebugView has an option to store the output to the file/files with good customizations (generating a list of trace files day per day etc., filters).


    Leonid Ganeline [BizTalk MVP] Biztalkien blog
    sábado, 19 de junio de 2010 18:37
    Moderador
  • Ben,

    Thank you for the links.  I've read through them and was able to extract the binary log file as XML and upon further inspection, Windows Event Viewer in "XML View" appears to provide similar information for individual event records:

    <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    	<System>
    		<Provider />
    		<EventID>0</EventID>
    		<Version>0</Version>
    		<Level>0</Level>
    		<Task>0</Task>
    		<Opcode>14</Opcode>
    		<Keywords>0x0</Keywords>
    		<TimeCreated SystemTime="2010-06-15T15:56:35.998956500Z" />
    		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
    		<Execution ProcessID="4276" ThreadID="6496" ProcessorID="1" KernelTime="30" UserTime="135" />
    		<Channel />
    		<Computer />
    	</System>
    	<BinaryEventData>...binary data snipped...</BinaryEventData>
    	<ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
    		<EventGuid>{b4955bf0-3af1-4740-b475-99055d3fe9aa}</EventGuid>
    	</ExtendedTracingInfo>
    </Event>

     

    So I think that explains why I don't see alot of information in Event Viewer, there just isn't a lot, with my custom message encoded within BinaryEventData.  Anyways, I dug a bit further because my TraceProvider.TraceIn() calls (within the Microsoft.Biztalk.CAT.BestPractices.Framework project) WERE showing up with "TRACEIN: " event in the log file.  Sure enough, the definition for TraceError that I was using:

        /// <summary>
        /// Writes an error message to the trace. This method is provided for optimal performance when
        /// tracing simple messages which don't require a format string.
        /// </summary>
        /// <param name="message">A string containing the error message to be traced.</param>
        [DebuggerStepThrough()]
        public void TraceError(string message)
        {
    #if DEBUG
          // Write a formatted message into the active trace listeners such as DebugView.
          // This method will only be invoked in a DEBUG build. Once code is compiled in the RELEASE mode, this method call will be omited.
          DebugTimeTrace(FormatStringTraceErrorNoToken, message);
    #endif
          if (IsEnabled)
          {
            TraceMessage(EtwTraceLevel.Error, message);
          }
        }

    So, it's purposely written to not use any format string except to the write out to "active trace listeners such as DebugView" in a debug build, which I was using.  That explains the behavior I was seeing.  If I use the other overload, TraceError(string format, params object[] parameters) I can specify "ERROR: {0}" as the format string and get the behavior I was looking for... or more likely, I'll just update TraceError(string message) to always do the format because that's my desired behavior.

    Questions #1 (using the wrong overload of TraceError) and #3 (I can use Event Viewer and load the binary log) I'm good on then.  I'm still haven't researched #2 anymore where I was having difficultly capturing the same events to two log files, but that's not important to me anymore now that I know I can identify error/warning/info message records within one log file.

    Leonid,

    With regards to just using DebugView, my main hesitation there is based on the article (see post #1) that got me started looking into the Event Tracing for Windows stuff to begin with that gave an example of DebugView sucking 90% CPU during cases with a lot of application instrumentation.  Granted, I haven't actually tried it, so maybe it's not that terrible, I just got scared away ;).

    Thanks for the help all.

     

    • Editado Kyle Stittleburg lunes, 21 de junio de 2010 16:41 trying to make code like pretty
    • Marcado como respuesta Kyle Stittleburg lunes, 21 de junio de 2010 16:42
    lunes, 21 de junio de 2010 16:37
  • Hi Kyle,

    The tracing framework doesn't currently write any lables into the ETW trace logs as we were going to figure out if we can leverage the TMF file and add lables on fly while the log files are being transformed into text. This has not as yet been done.

    Regarding the second question - this surely needs further investigation. Let me work on this and I will get back to you in due course.

    Thanks,
    Valery

    http://blogs.msdn.com/asgisv

    martes, 22 de junio de 2010 7:32
  • After checking Ben Cline1 's articles and others, I'm starting to see that you allways have to stop the listener in order to read traces.

    Am i right about that? If so, how is it possible to write to the event log using ETW knowing the whole point of which is on the fly logging?
    miércoles, 14 de julio de 2010 11:27
  • >> Noticeably missing is the level of message

    I'd say that's not the only thing noticably missing.  I'm just a newbie with this CAT Instrumentation Framework, but with the exception of TRACEIN and TRACEOUT, I don't see any assembly or BizTalk application names displayed for any of the events.  I'm lookin at these events using the CAT Instrumentation Framework Controller, and the "INFO" traces are completely devoid of any useful information about where they came from.  I can't imagine making good use of this in a QA or production environment where there are many applications all writing trace messages.

    Am I missing something fundamental?

    viernes, 01 de julio de 2011 18:10