There is a new release of QuickCounters up at http://codeplex.com/quickcounters.  Great new useability additions to the viewer application by Dave Comfort, as well as fewer priviliges required against remote servers.  See here for the quick tour…

I’ll be talking about using QuickCounters with BizTalk at tonight’s Minnesota BizTalk User Group meeting.  (Last night, I was presenting on using Scrum with Team Foundation Server at the Minnesota VSTS User Group – it’s been a busy week!)

Another release of QuickCounters is available - check it out! Improved WCF support, and enhancements to the viewer. You really have to play with the library a bit to realize what a huge benefit it can provide both to operations and performance test investments (for fairly little investment on your part...)

Our CodePlex home is here. Downloads and source code here.

Have you ever wanted to get real-time metrics on:  How many times has a particular orchestration executed on this node in the BizTalk group?  What does the average execution time for my pipeline component looking like?  How many instances of a particular orchestration are currently executing across the group, not including dehydrated instances?

Questions like this can be tough to answer - the built-in BizTalk counters are too coarse-grained, and Tracking & BAM are only partially useful here (particularly if you want high frequency samples.)  What you would like is the ability to get fine-grained "request metrics" on all of your BizTalk orchestrations and pipelines in a way that is simple to implement and easy to consume.

I've been leading an open source project called QuickCounters for quite some time now - though we've just recently moved into CodePlex.  It is a library that will be of interest to BizTalk developers - but it can be used in much broader settings.  I had a chance to present on this topic at the Twin Cities .NET Users Group (on 11/2/2006 - presentation here.)

QuickCounters is a .NET library which makes it extremely easy to implement the common, request-level performance counters that are interesting in just about any service you might write.  You can use this library to instrument  general .Net components, web services, BizTalk orchestrations, pipeline components, remoting interfaces, enterprise service components...you get the idea.  There is special support in the library for BizTalk and WCF scenarios, but it is quite easy to use in any case.

QuickCounters recognizes that the Windows Performance Counter technology that has been with us for some time is often still the best choice for providing (and consuming) detailed performance metrics.  QuickCounters also recognizes that for any given service request there are several metrics which turn out to be interesting for performance testing, operational health analysis, and historical trending. The idea with QuickCounters is to raise the level of abstraction from that of an individual performance counter up to the request itself, using a simple API.

Suppose you want to gather these metrics for each type of request in your system:

• Requests Started
• Requests Executing
• Requests Completed
• Requests Failed
• Request Execution Time
• Requests/Hour
• Requests/Min
• Requests/Sec

Although the .NET performance classes would give you a good start, it will still be a chunk of work.  With QuickCounters, you describe your requests in a simple xml format, and include a simple code snippet in each request implementation:

void SampleRequest()
{
   RequestType someRequest = RequestType.Attach("MyApplication","someRequest");
   someRequest.BeginRequest();

   try
   {
      // Do useful work...
      someRequest.SetComplete();
   }
   catch
   {
      someRequest.SetAbort();
      throw;
   }
}
        

After a quick "install" of the xml that describes your requests (via the included "QuickCounter viewer" utility) you are on your way.  You can see all eight metrics described above for all of your requests (which each become a Performance object) - in PerfMon, with MOM, or any other performance counter consumer. 

For a BizTalk orchestration, you will simply have a variable of type RequestType, which you will assign in an expression shape at the top of your orchestration via the static "RequestType.Attach" method, followed by a call to BeginRequest: 

quickCounterDemo = QuickCounters.RequestType.Attach(
    "QuickCounterDemo","demo",
    QuickCounterDemo(Microsoft.XLANGs.BaseTypes.InstanceId)); 
quickCounterDemo.BeginRequest();           

Successful completion should end with another expression shape that calls SetComplete, otherwise SetAbort.  (Full sample referenced below.)  And yes, the library understands that an orchestration's execution will often begin on one node in your BizTalk group and continue/complete on a different node. 

Of course, if you have many requests, and many nodes in your BizTalk group, it can be a hassle to add everything to PerfMon.  20 requests * 3 servers = 60 interactions with PerfMon's UI.  You might remember to save an .msc file, but you might not.  Here is where the QuickCounter viewer comes into play.  Since you've already written an xml file that describes your requests, just let the viewer know about that file -  and a comma separated list of servers you are running on:

(click)

(The viewer has benefitted substantially from John Thom's contributions...)

Now, the WCF support in the library is...amazing, and completely the result of contributions from Tomas Restrepo.  Keep an eye on his blog for a full discussion, but the bottom line is that creation of the simple xml format and all API calls (BeginRequest/SetComplete/SetAbort) are handled for you automatically simply by applying an attribute (or a behavior - your choice) to your WCF service implementation.  How cool is that?

Our CodePlex home is here.  Downloads and source code here.  Contributors here.

I expect we'll release about once a month or so for awhile - give it a spin and let us know what you think.  It is being used by some very large BizTalk projects (in production) with good success right now.

(Note - this work has been updated for log4net 1.2.9. See the 'Tools' download in the Deployment Framework)

Early on when working with BizTalk 2004, it might be tempting to view the ability to track orchestration events (and the use of the orchestration debugger) as a substitute for traditional diagnostic logging.;

After all, the orchestration debugger can tell you exactly how far you got in an orchestration, and what path through the workflow you took to get there

However, consider these limitations:

• The orchestration debugger is used either a) after the orchestration has completed or b) in conjunction with a breakpoint.  Neither of these choices is ideal, and only the latter gives you visibility into the intermediate values of variables/messages.
• Once an orchestration involves looping constructs, multiple orchestrations connected via messaging, etc. the orchestration debugger often loses quite a bit of diagnostic value.

Given this, it can be useful to integrate diagnostic logging into your orchestrations and the components they call.  If we are going to invest in this effort, we’d like to use something richer than the built-in System.Diagnostics.Trace/Debug infrastructure.

Log4net is an Apache-sponsored initiative within the “Apache Logging Services” project.  It provides a rich diagnostic infrastructure for .NET, with support for hierarchical logging and configuration, multiple logging targets, and support for logging context.

A recent article outlined the advantages of log4net over Microsoft’s Enterprise Instrumentation Framework (EIF), though Microsoft/Avanade will be revamping this logging infrastructure with the release of the Enterprise Template Library

Given that the log4net initiative has broad support at the API layer (i.e. log4j, log4PLSQL, etc.) and platform layer (including .NET CF) as well as the benefit of maturity, log4net seems like a very reasonable choice for instrumenting BizTalk 2004 applications.  (The Enterprise Template Library logging component will likely be a good choice as well when released.)

Following is a discussion of log4net itself, along with what is required to use it in a BizTalk 2004 setting.

Quick Insight into log4net 

Without diving immediately into the log4net API, let’s get a sense for what it can do.  What do we mean by hierarchical logging and configuration with multiple target support?

Suppose we have classes with these namespace-qualified names:

Each of these classes can obtain a logger specific to their class by declaring a static member as such:

Each class (MyClassA/MyClassB) can now emit trace with statements such as log.Info(“hello world”)> or log.Warn(“a potential problem…”).  Default log levels include: Debug, Info, Warn, Error, and Fatal (though these can be expanded.) 

The concept of “context” can be added to a stream of trace messages via NDC.Push(“some context”)/NDC.Pop or MDC.Set(“somekey”,”somevalue”).  (These class names are short for “Nested Diagnostic Context” and “Mapped Diagnostic Context” respectively.)  These can be extremely useful for multithreaded/multi-user applications, to distinguish the streams of related trace messages from each other.  This context can be optionally formatted into the associated tracing statements, as will be shown shortly.

If we want to turn on tracing at the ‘Error’ level by default, at the ‘Warn’ level for MyCompany, and at the ‘Debug’ level for MyClassA, we would simply configure as follows (notice the use of the namespace hierarchy):

This can be changed on-demand simply by changing the configuration file, which can be reloaded automatically without restarting the application.  This allows us to a) not be blinded by too much trace information and b) not impose undue server load by tracing, whereas a non-hierarchical approach only allows for one logging level for an entire application. 

Suppose it is desired to route all trace information (by default) to OutputDebugString, where a utility such as dbmon.exe or DebugView can be used to view it.  Suppose further it is desired to prefix our output with the date, thread Id, logging level, the name of the logger (i.e. MyCompany.MyDepartment.MyClassA), and the current context.  To do this with log4net, we would have our configuration file declare an “appender” of the appropriate type, and include a declaration of a “layout” as follows.  The “appender” is then referenced by a particular logger (or the root logger).

This might yield trace output as follows:

Again, the specifics of what additional information can be included in trace output can all be configured dynamically at runtime.  Note that other useful information such as method name, file name, line number, caller’s window identity can all be added with the PatternLayout class as well, though it is quite expensive (further adding value to the hierarchy concept!) 

Moreover, each element of the hierarchy can be directed to a different appender, or to multiple appenders.  Built in appenders include support for ADO.NET, .NET remoting, SMTP, files, rolling files, buffering, and the Event Log (among others.)  Because the Event Log is supported, there is no need to use a separate API to support such logging. 

Core log4net Concepts 

Without attempting to present a full tutorial (see this introduction for a more complete discussion), the core concepts in log4net include: 

Loggers: Use by code to emit trace output at various levels.

• Loggers are organized into hierarchies just like .NET namespaces (they don't have to correspond, but often should.)  Example: System is parent of System.Text, and an ancestor of System.Text.StringBuilder. 
  • It is typical to have the logger name equal to a fully-qualified class name. 
• Loggers are retrieved using a static method of LogManager, e.g. LogManager.GetLogger(someStringOrTypeName);
  • An ILog interface is returned with Debug, Info, Warn, Error, Fatal methods on it for tracing. 
• Logging level is generally inherited from the hierarchy, and be configured anywhere in the hierarchy. 
  • Rule: logging level is equal to first non-null value working UP the tree.
  • Predefined levels: DEBUG, INFO, WARN, ERROR, FATAL, ALL, OFF
  • Default level for root in hierarchy is DEBUG 

Appenders: An output destination for logging. 

• Built in: event log, asp.net trace, console, file, rolling file, smtp, etc.
• Appenders can optionally have "layouts" to specialize how formatting is done and add additional information (windows identity, source code info, context, thread id, timestamp, etc.) 
• Appenders are attached to a logger.  Log requests will go to a given logger's appender, as well as all appenders attached up the hierarchy (unless "additivity=false" at some level, in which case moving up hierarchy stops…) 

Filters: A given appender can apply a filter such that only log requests that match some criteria will actually be output.  Filters are applied sequentially.  Built-in filters include string match and regex match. 

Configurators: Classes which initialize the log4net environment.  Configuration is done either through assembly attributes that specify a config file, or an explicit call to specify a config file.  The config file can be a standard .net config file, or standalone.  Configuration is by default at the appdomain level, but can be finer-grained through the use of log4net "logging domains".

Using log4net with BizTalk 2004

There are a few challenges to using log4net in a BizTalk 2004 environment.  They can be summarized as follows: 

• Assembly-attribute-driven configuration won’t work because BizTalk 2004 does not appear to support the addition of custom attributes for BizTalk assemblies.  (And even if it did, this method would pose issues for BizTalk environments.)  
• Using the log4net configuration classes for configuration is problematic because there is no clear point at which to make the call.  (How does as an orchestration know if it is “first” and should initialize?  How does it know at any point in an orchestration whether the BizTalk service has been recently recycled, losing the log4net configuration?)  Moreover, there is not a good way to identify where the configuration file should be located.
• ILog-derived classes (log4net loggers) are not serializable “out-of-the-box”, making it difficult to use them in an orchestration setting.
• Log4net context-storage mechanisms are thread-relative, which isn’t workable for orchestrations, since orchestrations often a) dehydrate and then re-hydrate on a different thread and b) make use of parallel branches.  We’d like to correctly associate context such as the orchestration instance ID on a logger that is scoped to an orchestration. 

To address these challenges, I’ve created extensions to log4net that attempt to stay within log4net’s design intent.  These are housed in an assembly called “log4net.Ext.Serializable”.  (Update – these are now currently found in the “Extra Tools” download for the Deployment Framework – see the download links at the blog home page.)

The main classes defined are as follows: 

SLog: A serializable implementation of the ILog interface, to be used by orchestrations (or other components) for logging.  This class has an InstanceId property as well as a general properties collection that is carried with the logger itself.  (These can be made available in appender output via a PatternLayout class and the %P{yourpropname} format specifier.  Use %P{InstanceId} for the InstanceId.)  When deserialized, this class can detect an un-initialized state for log4net and recreate the correct configuration. 

SLogManager: To be used in place of log4net’s LogManager to dispense SLog classes.  This is the accepted way of dispensing custom loggers in log4net’s design. 

RegistryConfigurator: A class which consults a registry key for the location of a log4net config file, and creates the configuration in the specified “logging domain” using the log4net DomConfigurator class. 

Specifics for BizTalk 2004 Usage 

Using the assembly just discussed, the specifics of using log4net with a particular BizTalk project can be described as follows: 

• Get 1.2.0 Beta8 of log4net at log4net extension described above, as well as a full sample project if you like.  (Update – the current version of this sample will now always be found in the Deployment Framework sample – see download links at the blog home page.)
• If you are using NAnt to deploy your BizTalk solution, extend your customDeployTarget as shown below to create a registry key that will point to a log4net configuration file within your project’s root directory (whether on a developer desktop or an MSI base directory). (Handled for you in current rev of deployment framework.) Also, create a file with the log4net extension that corresponds to your solution name (i.e. BizTalkSample.log4net)
  <target name="customDeployTarget"> 
   <!-- Write registry key with location of our log4net configuration file.  This step is NOT needed in current rev of Deployment Framework… -->
   <exec program="cscript.exe" failonerror="true" commandline="/nologo ${deployTools}\WriteRegValue.vbs HKLM\SOFTWARE\${nant.project.name}\log4netConfig ${nant.project.basedir}\${nant.project.name}.log4net" />
</target>

• Orchestration assemblies should reference log4net.Ext.Serializable as well as log4net.dll, and declare a variable in each orchestration (perhaps named “logger”) of type log4net.Ext.Serializable.SLog.
• Orchestrations should begin (after an activating receive, if necessary) with an expression shape that looks like:
  logger = log4net.Ext.Serializable.SLogManager.GetLogger(@"BizTalkSample",log4net.helpers.CallersTypeName.Name);
logger.RegistryConfigurator();
logger.InstanceId = MyOrchName(Microsoft.XLANGs.BaseTypes.InstanceId);
logger.Debug("New request arrived...");


  Important: If an orchestration has parallel branches, you will want to declare multiple variables of type log4net.Ext.Serializable.SLog, assigning 2-n to the first one, as in:

  logger2 = logger;

  This prevents the need for synchronizing scopes.  (See this article for more.)&nbps;An alternative is to use scope-local logger variables that are initialized by assigning them to a global instance.

• At various points in your orchestration, simply make calls to logger.Debug/logger.Info/logger.Error, etc.  Rely on logger.Error for event log entries (with appropriate logger/appender configuration.)
• Use log4net with the components that your orchestration calls as well.  If those components are serializable, they will want to make use of SLogManager/SLog classes as well in non-static methods.  If you want context (such as the orchestration instance ID) to flow, it might be worthwhile to make an SLog-typed property visible on the class that the orchestration can set.  (This needs more thought.)

Using log4net with Paul Bunyan 

Paul Bunyan is a logging tool that has a very nice server-side buffering service as well as a great trace-viewing client that can connect to multiple servers simultaneously (a great plus for BizTalk groups!)  Although Paul Bunyan has its own API, we aren’t interested in it for purposes of this discussion.

A log4net appender can be easily written for Paul Bunyan, such that log output can be directed there.  Moreover, this appender can be made to explicitly recognize an InstanceId property carried with a log4net logging event, and map it to the “Context” concept within Paul Bunyan!  This allows for viewing the orchestration instance ID within a distinct, filterable column in the Paul Bunyan viewer as such:

(click)

Sample .log4net configuration File 

Note that types have to be referred to with fully-qualified names since log4net.dll is being deployed to and loaded from the GAC.