A few days ago I released v1.5 of the BRE Pipeline Framework on CodePlex.  One of the many new features available in the framework is ETW (Event Tracing for Windows) tracing based on the best practice guidance provided by the CAT team.  According to benchmark tests performed by the CAT team, ETW based tracing outperformed other methods of tracing such as System.Diagnostics, Log4Net, and Enterprise Library 5 based tracing by a factor of 24-580 times (see below results when performing the same trace statement 100,000 times across the different frameworks).

Benchmarks

The BRE Pipeline Framework now has ETW based tracing baked into the framework itself so you can see why the framework executed in the manner it did, and if any errors were encountered you can also see the entire stack trace for the given error.  This tracing information can even be gathered in production environments and should have a near negligible effect on the performance of your solution as long as you are making use of asynchronous trace listeners rather than synchronous ones such as DebugView.  My preferred method of capturing trace information is to use the CAT Instrumentation Framework Controller application (if you use this then you will need to ensure that you toggle on the pipeline component option before you turn on the trace) and to trace to a log file.

An example of trace information provided by the BRE Pipeline Framework is below (it is the entire trace output for one execution instance of the pipeline component that uses XML based facts to manipulate a message and to then apply a BizTalk map against the message).  Note that every trace statement for a given instance of a pipeline component will be accompanied by a GUID value for correlation purposes, so when you are tracing in a multi-threaded environment and you have many different threads processing messages with the BRE Pipeline Framework you should be able to group trace statements together based on the GUID (Excel’s text to columns feature does wonders here).  Also note that there is a timer provided in the “End” entry which measures the time between the “Start” and “End” entry.

[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:TRACEIN: BREPipelineFramework.PipelineComponents.BREPipelineFrameworkComponent.TraceIn() => [4f8f4bd2-e1a1-4967-8f32-1952c156d527]
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:START -> 4f8f4bd2-e1a1-4967-8f32-1952c156d527
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - BRE Pipeline Framework pipeline component has started executing with an application context of Test_XmlFactsApplicationStage, an Instruction Execution Order of RulesExecution and an XML Facts Application Stage of BeforeInstructionExecution.
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - BRE Pipeline Framework pipeline component has an optional Instruction Loader policy paramater value set to BREPipelineFramework InstructionLoaderPolicy.
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - BRE Pipeline Framework pipeline component has an optional Execution policy paramater value set to BREPipelineFramework ExecutionPolicy.
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Inbound message body had a stream type of System.IO.FileStream
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Inbound message body stream was seekable so no need to wrap it
[2]1370.19B8::06/29/2014-15:49:21.801 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - No need to read stream as stream type does not match entries in StreamsToReadBeforeExecution parameter
[2]1370.19B8::06/29/2014-15:49:21.826 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Executing Policy BREPipelineFramework InstructionLoaderPolicy 1.1
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding TypedXMLDocument of type BREPipelineFramework.TestProject.Message to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.CachingMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.ContextMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.HelperMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.MessagePartMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.TypedXMLDocumentMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding MetaInstruction BREPipelineFramework.SampleInstructions.MetaInstructions.XMLTranslatorMetaInstructions to Execution Policy facts.
[2]1370.19B8::06/29/2014-15:49:21.829 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Executing Policy BREPipelineFramework ExecutionPolicy 1.1
[2]1370.19B8::06/29/2014-15:49:21.834 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding Instruction BREPipelineFramework.SampleInstructions.Instructions.TransformationInstruction to the Instruction collection with a key of 0.
[2]1370.19B8::06/29/2014-15:49:21.836 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding Instruction BREPipelineFramework.SampleInstructions.Instructions.ApplyTypedXMLDocumentInstruction to the Instruction collection with a key of 1.
[2]1370.19B8::06/29/2014-15:49:21.837 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Adding Instruction BREPipelineFramework.SampeInstructions.Instructions.MessageModificationInstructions to the Instruction collection with a key of 2.
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Applying typed XML document (overwriting current message body)
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Starting to execute all MetaInstructions.
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Executing instruction BREPipelineFramework.SampleInstructions.Instructions.TransformationInstruction.
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Applying transformation BREPipelineFramework.TestProject.Message1_To_Message2, BREPipelineFramework.TestProject, Version=1.0.0.0, Culture=neutral, PublicKeyToken=83eab0b166470ebc to the message
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Message is being transformed from message type http://BREPipelineFramework#Message to message type http://BREPipelineFramework.TestProject.Message2#Message2
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Executing instruction BREPipelineFramework.SampleInstructions.Instructions.ApplyTypedXMLDocumentInstruction.
[2]1370.19B8::06/29/2014-15:49:21.840 [Event]:4f8f4bd2-e1a1-4967-8f32-1952c156d527 - Executing instruction BREPipelineFramework.SampeInstructions.Instructions.MessageModificationInstructions.
[2]1370.19B8::06/29/2014-15:49:21.841 [Event]:END <- 4f8f4bd2-e1a1-4967-8f32-1952c156d527: 39ms
[2]1370.19B8::06/29/2014-15:49:21.841 [Event]:TRACEOUT: BREPipelineFramework.PipelineComponents.BREPipelineFrameworkComponent.Execute(...) = "4f8f4bd2-e1a1-4967-8f32-1952c156d527"

As you can see there is a lot of information provided. You can see all the configuration parameter values that were applied to the pipeline instance, you can see what type of stream the message was (I will discuss this in more detail in future blog posts since the type of stream does affect the behavior of the pipeline component), what BRE Policy including version number is being executed, when the TypedXMLDocument (based on XML facts) is applied to the message body stream, the type of transformation being applied including the source and destination message type, etc…. Phew!

Also of note is that if an exception was encountered during execution of the pipeline component then you would see the entire stack trace in the trace results, which can be really handy when diagnosing problems and when reporting it back to the CodePlex project team.

Also of equal importance is the fact that you can now execute your own custom trace statements from within your ExecutionPolicy BRE Policy by using the TraceInfo vocabulary definition in the BREPipelineInstructions.SampleInstructions.HelperInstructions vocabulary as per the below example.

Trace rule

The TraceInfo vocabulary definition can be used in rule conditions or actions (which would only be triggered if the conditions for that given rule all evaluated), and will accept any string value so you could potentially plug in the StringFormat or ConcatenateString type vocabulary definitions as a parameter into it if you want you trace out complex information.  You could even trace out results of XPATH statements (not recommended for high throughput environments or in applications which deal with large messages, in which case reading the stream is a big no-no) or the values of context properties if you wanted to.  The trace result will be accompanied by the same GUID as the rest of the trace information, and will also be of the pipeline component trace type, so you can easily correlate your custom trace statements to the out of the box trace statements for a given pipeline component execution instance.  An example trace result based on the above rule is below.

Trace result

Equally important to the tracing results is the debug tracing information for BRE Policy execution.  It is quite common for people to get put off from using the BRE because it is perceived to be difficult to debug when the rules execution does not provide the expected result.  The BRE Pipeline Framework solves this problem by providing BRE Policy tracing information when the pipeline component is configured appropriately.  The pipeline component has a parameter called TrackingFolder which you can set in Visual Studio for the pipeline or in the BizTalk Administration Console for a  given pipeline instance.

PipelineComponentConfiguraiton

By default the aforementioned parameter has a blank value, but if a valid folder location is provided then the framework will write out rules tracing information to the given directory.  What you will observe is that one file is written per BRE Policy that is executed, thus if you have specified an InstructionLoaderPolicy and an ExecutionPolicy BRE Policy then you will have two rules tracing files written per execution of the pipeline component.  The information contained within said files is the same info you would see if you were trying to test the policy from within the BRE composer (though in order to test a BRE Pipeline Framework policy you would need to write .NET fact creators so this is an easier way to get the tracing information).

The rules tracing file name will contain the name of the policy that was executed including the version number of the policy.  To make it easier to correlate rules tracing files to an execution instance of a pipeline component, the file name also contains the same GUID that is used in ETW tracing in the pipeline component.

TrackingFolder

Have a look at a snippet of the rules tracing information below.  You’ll notice that you can see the values used and results of each individual condition evaluation across all the rules in your policy which had corresponding facts asserted, and you can also see exactly which rules fired as well (i.e. the actions were triggered).  Not pictured but also conveyed are any facts that weren’t recognized.

CONDITION EVALUATION TEST (MATCH) 29/06/2014 5:03:52 p.m.
Rule Engine Instance Identifier: 4bb67d3e-0c76-49bb-945e-93cfbc3471e4
Ruleset Name: BREPipelineFramework ExecutionPolicy
Test Expression: True == BREPipelineFramework.SampleInstructions.MetaInstructions.HelperMetaInstructions.CheckIfStringExistsInMessage
Left Operand Value: True
Right Operand Value: True
Test Result: True

FACT ACTIVITY 29/06/2014 5:03:52 p.m.
Rule Engine Instance Identifier: 4bb67d3e-0c76-49bb-945e-93cfbc3471e4
Ruleset Name: BREPipelineFramework ExecutionPolicy
Operation: Assert
Object Type: BREPipelineFramework.SampleInstructions.MetaInstructions.MessagePartMetaInstructions
Object Instance Identifier: 38466885

FACT ACTIVITY 29/06/2014 5:03:52 p.m.
Rule Engine Instance Identifier: 4bb67d3e-0c76-49bb-945e-93cfbc3471e4
Ruleset Name: BREPipelineFramework ExecutionPolicy
Operation: Assert
Object Type: BREPipelineFramework.SampleInstructions.MetaInstructions.XMLTranslatorMetaInstructions
Object Instance Identifier: 10993679

RULE FIRED 29/06/2014 5:03:52 p.m.
Rule Engine Instance Identifier: 4bb67d3e-0c76-49bb-945e-93cfbc3471e4
Ruleset Name: BREPipelineFramework ExecutionPolicy
Rule Name: Test_TransformMessageVaildateSourceIfKnown
Conflict Resolution Criteria: 0

While the ETW tracing is production friendly as long as you are tracing to an asynchronous destination rather than a synchronous one like DebugView (of course, it’s fine to use this on a developer workstation), I can’t provide any assurances about the production friendliness of the rules tracing information.  In order to implement the rules tracing I have used the out of the box DebugTrackingInterceptor class provided by Microsoft, so whatever guidance applies to that will apply here too, I haven’t seen any guidance personally.  My recommendation is to only use it in production when necessary and to switch it back off when not required; the rules tracing is primarily intended to aid developers to get their rules right during development cycles.

I hope this blog post conveys to you how you can take advantage of instrumentation features in the BRE Pipeline Framework, and gives you a sense of security that this isn’t a framework that will leave you in the dark.  Look forward to many more blog posts within the next few weeks discussing new features in the BRE Pipeline Framework.