BizTalk Server 2013 R2: Instrumenting BAM Activity Tracking with ETW

Article
1/17/2024

Introduction

The BizTalk CAT Instrumentation Framework provides a reusable framework intended to help BizTalk developers enrich their solutions with high-performance instrumentation based on the Event Tracing for Windows (ETW) infrastructure. As a developer you can instrument your BizTalk artefact, WCF/WF component, or custom component (.NET) for purpose of logging, tracing or testing to observe the behavior. ETW allows you to log kernel or application events to a log file. An application can be seen in a broad view, meaning that a BizTalk solution containing custom pipeline components, mappings, and an orchestration can be logged from end to end. This can also be done using log4net or System.Diagnostics namespace. However, a team at Microsoft found out in their research that lead to building the framework that both log4net and System.Diagnostics did not deliver enough agility or acceptable performance. ETW infrastructure within the Microsoft OS provided a high-speed tracing facility and combined with a TracePovider in from the Microsoft.BizTalk.Diagnostics namespace in Microsoft.BizTalk.Tracing.dll are basically the main ingredients of the framework. The most important part within the framework is the ComponentTraceProvider class. This class is a wrapper around the TraceProvider providing various tracing methods for common methods you see in the Microsoft Event log like informational, warning, and exceptions. Besides these methods the team enriched the framework with support for tracing method calls, measuring durations using high-resolution timers and ability to correlate events using Guid-based tokens.

Scenario

The BizTalk CAT Instrumentation Framework can be used to instrument the following BizTalk artifacts:

Custom Pipeline Components
BizTalk Mapping
Orchestrations
Business Rules
BAM Activity Tracking Components

The following scenario demonstrates how to instrument a bam activity implementation in the BAM API sample found in the folder of the BizTalk Server SDK. This sample simulates a simple purchasing scenario. Purchase orders will be generated, processed and shipped. While this simulation application runs BAM activities will be created and updated for each order to reflect the details and disposition of each order and corresponding invoice. The BizTalk CAT Instrumentation Framework will be leveraged in the BAM Activity Tracking component i.e. simulation API.

http://i208.photobucket.com/albums/bb152/Steef-Jan/BAMApi%20Scenario_zps4bhaypse.png

Picture 1. BAM API scenario.

Prerequisites

To leverage ETW for BizTalk you will have to download the BizTalk CAT Instrumentation Framework v1.4 and build it locally on your machine with Visual Studio 2013. You will need to open the solution with Visual Studio 2013 to migrate to newer version of the .NET framework. To build the project the following code in class IcomponentTraceProvider needs to be commented out:

void TraceInfo(Func<string> expensiveDataProvider);

Next to the Instrumentation Framework you can download the BizTalk CAT Instrumentation Framework Controller , which is an easy-to-use GUI for the BizTalk CAT Instrumentation Framework. This will let you start and stop the traces and adjust filter options. It can easily enable real-time tracing to the Microsoft SysInternals DebugView (or other debuggers), or to a log file or to do both at the same time.

Instrumenting the simulation application (BAM API Sample)

The application can be instrumented using TraceManager.TrackingComponent, which was designed for the purpose of this BizTalk feature. The Tracemanager can be useful to test:

Tracing calls in the tracking component using TraceIn and TraceOut;
Measuring the duration of the divers methods using the TraceStartScope and TraceEndScope, which will be demonstrated by code sample;
Tracing the internal state of the in this case custom BAM Activity, which could in turn assist with troubleshooting using TraceInfo;
Writing detailed information about a runtime exception using TraceError in case an error occurs.

        void RunOnce()
        {
            Random r=new Random((int)DateTime.Now.Ticks/int.Parse(Thread.CurrentThread.Name));
            int sleep=r.Next(Global.PoAppMinSleepTime,Global.PoAppMaxSleepTime);
            Thread.Sleep(sleep);
 
 
 
            // Generate Random PurchaseOrder as XML message
            int poid=ms_poCounter++;                
            string sPOxml="<PurchaseOrder PoID=\""+poid.ToString()+"\">\n";
            int product=r.Next(Global.Products.Length);
            sPOxml+="    <Product>"+Global.Products[product]+"</Product>\n";
            int discount=r.Next(Global.Discounts.Length);
            sPOxml+="    <Discount>"+Global.Discounts[discount]+"</Discount>\n";
            sPOxml+="    <Price>"+Global.Prices[product,discount]+"</Price>\n";
            sPOxml+="    <Address>"+r.Next(10000).ToString()+" "+r.Next(1000).ToString()+" Str</Address>\n";
            sPOxml+="</PurchaseOrder>\n";
 
            var callToken = TraceManager.TrackingComponent.TraceIn("BAMApiPo", poid);
            var scopedTraceStrated = TraceManager.TrackingComponent.TraceStartScope("BAMApiPo", callToken);
 
            XmlDocument xdPO=new XmlDocument();
            xdPO.LoadXml(sPOxml);
            XmlElement xePO=xdPO.DocumentElement;
            Console.WriteLine("New Purchase Order #"+xePO.GetAttribute("PoID")+" Received.");
            TraceManager.TrackingComponent.TraceInfo("New Purchase Order #" + xePO.GetAttribute("PoID") + " Received.");
 
#if Interceptor
            BAMInterceptor interceptor=Global.LoadInterceptor("BAMApiPo_interceptor.bin");
            interceptor.OnStep(Global.dataExtractor,"locNewPo",xePO,Global.es);
#else
            Global.es.BeginActivity("BAMApiPo",poid.ToString());
            Global.es.UpdateActivity("BAMApiPo",poid.ToString(),
                "Received",DateTime.UtcNow,
                "Product",xePO.SelectSingleNode("Product").InnerText,
                "Amount",xePO.SelectSingleNode("Price").InnerText);
#endif
 
            // Random Approval Decision             
            sleep=r.Next(Global.ApprovalMinTime,Global.ApprovalMaxTime);
            Thread.Sleep(sleep);
 
            int approve=r.Next(100);
            if (approve>Global.ApprovalPercent)
            {
                Console.WriteLine(xePO.GetAttribute("PoID")+" was Rejected.");
                TraceManager.TrackingComponent.TraceInfo(xePO.GetAttribute("PoID") + " was Rejected.");
 
#if Interceptor
                interceptor.OnStep(Global.dataExtractor,"locRejected",xePO,Global.es);
#else
                Global.es.UpdateActivity("BAMApiPo",poid.ToString(),
                    "Denied",DateTime.UtcNow);
#endif
                return;
            }
            Console.WriteLine(xePO.GetAttribute("PoID")+" was Approved.");
            TraceManager.TrackingComponent.TraceInfo(xePO.GetAttribute("PoID") + " was Approved.");
 
#if Interceptor
            interceptor.OnStep(Global.dataExtractor,"locApproved",xePO,Global.es);
#else
            Global.es.UpdateActivity("BAMApiPo",poid.ToString(),
                "Approved",DateTime.UtcNow);
#endif
 
            // Put the Package in the queue to be shipped
            sleep=r.Next(Global.PackagingMinTime,Global.PackagingMaxTime);
            Thread.Sleep(sleep);
            int packageNumber=r.Next(poid*10,(poid+1)*10);
 
            if (Global.ShipmentThreads>0)
            {
                XmlDocument xdShipment=new XmlDocument();
                string sShipXml="<Shipment ShipmentID=\"pkg#"+packageNumber.ToString()+"\"/>";
                xdShipment.LoadXml(sShipXml);
                XmlElement xeShipment=xdShipment.DocumentElement;
                XmlElement xeShipAddress=xdShipment.CreateElement("Address");
                XmlElement xePoAddress=(XmlElement)xePO.SelectSingleNode("Address");
                xeShipAddress.InnerText=xePoAddress.InnerText;
                xeShipment.AppendChild(xeShipAddress);
                 
                lock(ShipmentApplication.ShipPackages)
                {
                    ShipmentApplication.ShipPackages.Enqueue(xeShipment);
                }
            }
 
            // and register this PO to be included in some invoice
            if (Global.InvoiceThreads>0)
            {
                InvoiceApplication.PosToInvoice.Enqueue(xePO);
            }
 
            Console.WriteLine(xePO.GetAttribute("PoID")+
                " was shipped as pkg#"+packageNumber.ToString());
            TraceManager.TrackingComponent.TraceInfo(xePO.GetAttribute("PoID") + " was shipped as pkg#"  + packageNumber.ToString());
 
            TraceManager.TrackingComponent.TraceEndScope("BAMApiPo", scopedTraceStrated, callToken);
            TraceManager.TrackingComponent.TraceOut(callToken);
 
#if Interceptor
            interceptor.OnStep(Global.dataExtractor,"locPackaged",xePO,Global.es);
#else
            Global.es.UpdateActivity("BAMApiPo",poid.ToString(),
                "Packaged",DateTime.UtcNow);
            Global.es.EnableContinuation("BAMApiPo",poid.ToString(),"pkg#"+packageNumber.ToString());
            Global.es.EndActivity("BAMApiPo",poid.ToString());
#endif
        }

The BizTalk CAT Instrumentation Framework in action

To capture and review the behaviour of the BAM Activity Tracking, the BAM API simulation application will be started. Before starting the application the BizTalk CAT Instrumentation Framework Controller will be launched. The Business Activity Tracking component trace filter setting will be selected.

http://i208.photobucket.com/albums/bb152/Steef-Jan/BAM%20API%20CAT_zpsndiqghds.png

Picture 2. BizTalk CAT Instrumentation Controller.

DebugView will be launched and the application will be started. The debug trace will look like below in the DebugView:

http://i208.photobucket.com/albums/bb152/Steef-Jan/BAM%20API%20DebugView_zpskjo7gtto.png

Picture 3. DebugView capturing the traces.

When the text editor will be opened that the same trace information displayed in debugview can be found:

http://i208.photobucket.com/albums/bb152/Steef-Jan/BAM%20API%20Notepad_zps2xhhqj8p.png

Picture 4. Captured trace information in text editor notepad++.

Wrap up

This article demonstrated how to instrument BAM Activity Tracking with the BizTalk CAT Instrumentation Framework that levarages Event Tracing for Windows (ETW), which is able to trace the flow in a very performant way to a log file. ETW is suitable to be used with mappings, orchestrations, BRE and in this article the demonstrated BAM (API). Examples on how to instrument them is similar to this example. Various samples can be found online demonstrating that like the excellent blog post Best Practices for Instrumenting High Performance BizTalk Solutions written by the team that build the BizTalk CAT Instrumentation Framework. The BizTalk CAT Instrumentation Framework Controller can be seen as a add-on for the framework to stop/start traces and specify options for enabling debugview and a texteditor.

Share via