Writing to Event Log — the right way

This one’s been on my mind for a long time. I know it’s very tempting to just use System.Diagnostics.EventLog.WriteEntry to write some string to the event log. But personally I never liked the fact that you write all that static text along with the variables like actual error messages etc. Why make your life harder analyzing events later on when there’s an easy way to fix that?

Instrumentation Manifests to the Rescue!

For a while now this has actually been quite easy, using instrumentation manifests. You can read more about it here: http://msdn.microsoft.com/en-us/library/windows/desktop/dd996930(v=vs.85).aspx. These manifests allow you to define events, templates for events, messages for events, even your own event channels (so you wouldn’t need to log into that crowded “Application” channel anymore) and a lot more. But let’s look at a little example.

<?xml version="1.0" encoding="utf-8"?>
<instrumentationManifest xsi:schemaLocation="http://schemas.microsoft.com/win/2004/08/events eventman.xsd" xmlns="http://schemas.microsoft.com/win/2004/08/events" xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xs="http://www.w3.org/2001/XMLSchema" xmlns:trace="http://schemas.microsoft.com/win/2004/08/events/trace">
    <instrumentation>
        <events>
            <provider name="MyService" guid="{DDB3FC6E-6CC4-4871-9F27-88C1B1F19BBA}" symbol="TheEventLog"
                      message="$(string.MyService.ProviderMessage)"
                      resourceFileName="MyService.Events.dll"
                      messageFileName="MyService.Events.dll"
                      parameterFileName="MyService.Events.dll">
                <events>
                    <event symbol="ServiceStarted" version="0" channel="Application"
                           value="1000" level="win:Informational"
                           message="$(string.MyService.event.1000.message)" />
                    <event symbol="ServiceStopped" version="0" channel="Application"
                           value="1001" level="win:Informational"
                           message="$(string.MyService.event.1001.message)"/>
                    <event symbol="ServiceConfigurationError" version="0" channel="Application"
                           value="1002" level="win:Error" template="ServiceException"
                           message="$(string.MyService.event.1002.message)"/>
                    <event symbol="ServiceUnhandledException" version="0" channel="Application"
                           value="1003" level="win:Error" template="ServiceException"
                           message="$(string.MyService.event.1003.message)"/>
                </events>
                <levels/>
                <channels>
                    <importChannel name="Application" chid="Application"/>
                </channels>
                <templates>
                    <template tid="ServiceException">
                        <data name="Exception" inType="win:UnicodeString" outType="xs:string"/>
                    </template>
                </templates>
            </provider>
        </events>
    </instrumentation>
    <localization>
        <resources culture="en-US">
            <stringTable>
                <string id="level.Informational" value="Information"/>
                <string id="level.Error" value="Error"/>
                <string id="channel.Application" value="Application"/>

                <string id="MyService.ProviderMessage"
                        value="My Windows Service"/>

                <string id="MyService.event.1000.message"
                        value="My Windows Service has started."/>
                <string id="MyService.event.1001.message"
                        value="My Windows Service has stopped."/>
                <string id="MyService.event.1002.message"
                        value="My Windows Service encountered a problem with its configuration. Please fix these issues and start the service again.:%n%n%1"/>
                <string id="MyService.event.1003.message"
                        value="My Windows Service encountered an unhandled exception:%n%n%1"/>
            </stringTable>
        </resources>
    </localization>
</instrumentationManifest>

Let’s start at the top. Lines 5-9 define some basic information about this instrumentation provider, like a name, a unique ID and a symbol (which will come in handy later). We can also define a friendly name for events logged this way (i.e. the event source). Let’s ignore the three xyzFileName attributes for now. On lines 11-22 we’re defining four events, some of them informational (like “the service started” or “the service stopped”), some are errors (e.g. configuration errors, or unhandled exceptions). If we wanted to define our own channel, we’d do so between lines 25 and 27. For now we’re just re-using (i.e. importing) the pre-defined “Application” channel.

Event Templates

Event templates are particularly handy if you want to write parameters with your events. Lines 29-31 define a template which has exactly one parameter, which happens to be a unicode string. We’ll use it to store exceptions. We can define more than one parameter and there’s a lot of types to use, but I’ll let you explore those on your own. This template, as you can see, is referred to by the two events with IDs 1002 and 1003.

Resources

The localization gods are with us to. Our event and template definitions so far were abstract, no actual UI strings were contained. We can define those per language, as you can see starting line 37. In the resources element and its sub-elements, we define the actual strings we want to show, including any parameters. Parameters are numbered (1-based) and are referred to with %1, %2, %3 and so on. As you can see on lines 51 and 53, we’re defining the strings for the two error events with one parameter each (“%1”), to contain the exception message. If you want line breaks, you’ll achieve those with “%n”.

Compile, with some Sugar added

So now we have a fancy manifest, but what can we do with it? Well, eventually we want to log events using the definitions from this manifest, so let’s get to it. The Windows SDK comes with two very handy tools, MC.exe (the message compiler) and RC.exe (the resource compiler). We’ll use the first to compile the manifest — and generate some c# code as a side effect — then use the second to compile the output of the first into a resource which can be linked into an executable. The commands are as follows.

mc.exe -css MyService.Events manifest.man -r obj\Debug
rc.exe obj\Debug\manifest.rc

MC.exe was nice enough to generate a file called manifest.cs for us. That file contains some code that you can use to log every event you defined in the manifest. This is why it was so handy to define the events (and templates): depending on how many parameters an event’s template has, the generated methods will ask you to provide just as many (typed) values for those parameters. Isn’t that great?! You’ll also find the compiled manifest.res file in obj\Debug. You can link that into its own executable (or your main assembly too, if you wanted), as follows:

csc.exe /out:MyService.Events.dll /target:library /win32res:obj\Debug\manifest.res

And you have a satellite assembly which holds the manifest you’ve built! CSC will log a warning about missing source files (because you didn’t add any .cs files to be compiled) but so far that doesn’t hurt anyone. We could probably also use link.exe but so far the C# compiler does a nice enough job.

Use that generated Code

Remember the code that was generated for us by MC.exe? Let’s go ahead and use it.

// ...
TheEventLog.EventWriteServiceStarted();
// ...
TheEventLog.EventWriteServiceConfigurationError(exception.Message); // ... or log the entire exception, including stack traces.
// ...

Wasn’t that very easy?

Install the Event Provider

There’s still something missing though: we’ll need to install our instrumentation/event provider with the system. It’s similar to creating the event source (which in fact will happen automatically when installing the manifest). This will typically happen in your application’s/service’s installer, using a command line as follows. But before that, remember the xyzFileName attributes we talked about? These need to be updated to point to the full path of the MyService.Events.dll assembly we generated. Otherwise the following command is going to fail.

wevtutil.exe im path\to\my\manifest.man

From now on, when your app or service starts and logs those events, they’ll show up in the event viewer. For the two events we defined with parameters, the values of the parameters are essentially the only thing that’s stored along with the ID of the event. Likewise, they’ll be the only thing that’s going to be exported with the event — so the files with the exported events you’re going to ask your customers to send you are going to be a lot smaller and won’t contain the static part of the events you already know anyway!

To uninstall the manifest, just run this command:

wevtutil.exe um path\to\my\manifest.man

Both commands need to run elevated (particularly important to remember when writing your installer).

Next Steps

As a next step, you’ll probably want to add the manual steps of compiling the manifest linking into the satellite assembly to the project file as automated targets. I’ll likely write another post about that in the future too.

Summary

As you can see, writing a manifest, compiling it and using the generated code to write to the event log is quite easy. So no more excuses to write each event as one big string (which is can be a lot harder to analyze when they come back from your customers because you first need to parse the strings).

A Basic Framework for Using Performance Counters with .Net Applications

In my last post I promised to tell you more about the performance counters. So here we are: today I’m going to tell you about how to use the performance counter infrastructure offered by Windows in a .net application. On top of this I’m providing you with a basic framework that you can use to author performance counters through XML and then get the code to read/write the counters generated for you at build time. So let’s get started.

Some Basics

Before I go off to the code, here’s a little overview on performance counters in Windows. I’m sure if you’re reading this, you already know about Perfmon.exe, a nice little tool to look at various performance aspects of Windows machines. When plottig performance counters, you’re typically adding the counters you’re interested in. These counters are grouped in categories, for instance Processor or PhsyicalDisk. Each category can contain multiple counters, for instance Disk Read Bytes/sec or Disk Write Bytes/sec. And finally, each counter can have multiple instances, for instance in multi-processor machines, you’ll find one instance of the % Idle Time counter per processor.

What tools like Perfmon.exe do is to grab the values of the counters you selected every second (by default, but that can typically be changed) and record/plot the values. Your job here is to build performance counters that measure certain aspects of your application so these tools can help you in analyzing your performance. And that’s why you’re here, right?

Step 1: The XML Schema

In order to know what we talk about in the XML I announced, let me start with the XML schema. I use this mainly to make sure that what I have in the XML declaring the perf counters makes some sense and is legal input. And of course because Visual Studio tells you that something’s wrong when the schema is not adhered to.

<?xml version="1.0" encoding="utf-8"?>
<xs:schema targetNamespace="urn:Cymbeline.Diagnostics.PerfCounters"
           xmlns="urn:Cymbeline.Diagnostics.PerfCounters"
           xmlns:tns="urn:Cymbeline.Diagnostics.PerfCounters"
           xmlns:xs="http://www.w3.org/2001/XMLSchema"
           attributeFormDefault="unqualified"
           elementFormDefault="qualified">
  <xs:element name="PerfCounters">
    <xs:complexType>
      <xs:sequence>
        <xs:element name="Category" maxOccurs="unbounded">
          <xs:complexType>
            <xs:sequence>
              <xs:element name="Counter" maxOccurs="unbounded">
                <xs:complexType>
                  <xs:attribute name="Name" type="xs:string" use="required" />
                  <xs:attribute name="Symbol" type="tns:Symbol" use="required" />
                  <xs:attribute name="Type" use="required">
                    <xs:simpleType>
                      <xs:restriction base="xs:string">
                        <xs:enumeration value="NumberOfItems32" />
                        <xs:enumeration value="RateOfCountsPerSecond32" />
                        <xs:enumeration value="RawFraction" />
                      </xs:restriction>
                    </xs:simpleType>
                  </xs:attribute>
                  <xs:attribute name="Help" type="xs:string" use="required" />
                </xs:complexType>
              </xs:element>
            </xs:sequence>
            <xs:attribute name="Name" type="xs:string" use="required" />
            <xs:attribute name="Symbol" type="tns:Symbol" use="required" />
            <xs:attribute name="Help" type="xs:string" use="required" />
          </xs:complexType>
        </xs:element>
      </xs:sequence>
    </xs:complexType>
  </xs:element>
  <xs:simpleType name="Symbol">
    <xs:restriction base="xs:token">
      <xs:pattern value="[a-zA-Z_][\w_]*" />
    </xs:restriction>
  </xs:simpleType>
</xs:schema>

On lines 21 to 23 you find some enumeration values. These map to the values defined in the PerformanceCounterType Enumeration. This is also where you can add support for more performance counter types when you need it. The other elements and attributes are used to describe the category for the performance counters and the performance counters themselves, including the help text that will show up in Perfmon.exe and also including the symbol that you can use in the code to access the counter.

Step 2: Declaring the Performance Counters

Now let’s use the schema we built above. To give you an idea of the context, I’m providing here some of the XML I use to build the perf counters for my SMTP server.

<?xml version="1.0" encoding="utf-8" ?>
<PerfCounters xmlns="urn:Cymbeline.Diagnostics.PerfCounters">
  <Category Name="CymbeMail" Symbol="CymbeMail" Help="CymbeMail SMTP Server v1">
    <Counter Name="# Total Connections"
         Symbol="TotalConnections"
         Type="NumberOfItems32"
         Help="The total number of connections since the server was started." />
    <Counter Name="# Total Connections Refused"
         Symbol="TotalRefusedConnections"
         Type="NumberOfItems32"
         Help="The total number of connections refused since the server was started." />
    <Counter Name="# Total Connections with Errors"
         Symbol="TotalErroneousConnections"
         Type="NumberOfItems32"
         Help="The total number of connections which reported errors since the server was started." />
    <Counter Name="# Active Connections"
         Symbol="ActiveConnections"
         Type="NumberOfItems32"
         Help="The number of currently active connections." />
    <Counter Name="# Authorization Records"
         Symbol="AuthorizationRecords"
         Type="NumberOfItems32"
         Help="The number of authorization records currently kept in the server." />
    <Counter Name="# Connections/sec"
         Symbol="ConnectionsPerSec"
         Type="RateOfCountsPerSecond32"
         Help="The number of connections per second." />
    <Counter Name="# Refused Connections/sec"
         Symbol="RefusedConnectionsPerSec"
         Type="RateOfCountsPerSecond32"
         Help="The number of connections refused per second." />
  </Category>
</PerfCounters>

As you can see, I create seven perf counters, most of them ordinary counters that count the number of occurrences of a certain event (like when a client makes a connection to the server). I actually also use the NumberOfItems32 type to count the number of active connections — I basically increment the counter when a connection was established and decrement it when the connection is terminated. And I have a couple of counters which count the number of occurrences per second (the RateOfCountsPerSecond32 counter type). The good thing about these counters is that you don’t need to provide your own counter base (check out MSDN for more info on this, starting with the above mentioned PerformanceCounterType Enumeration).

Step 3: Building the XSLT to Generate Code

We already have our perf counters declared, so let’s generate some code from that XML. Using XSL stylesheets makes this very easy: We’ll use the XML as input and get c# code as output that we can simply include into our project. I won’t show the full XSLT here (it’s about 240 lines).

<?xml version="1.0" encoding="utf-8"?>
<xsl:stylesheet version="1.0"
        xmlns:xsl="http://www.w3.org/1999/XSL/Transform"
        xmlns:msxsl="urn:schemas-microsoft-com:xslt"
        xmlns:tns="urn:Cymbeline.Diagnostics.PerfCounters"
        exclude-result-prefixes="msxsl">
  <xsl:output method="text" indent="no"/>

  <xsl:param name="TargetNamespace" />
  <xsl:param name="TargetClassName" select="'PerfCounters'" />
  <xsl:param name="AccessModifier" select="'public'" />

  <xsl:template match="tns:PerfCounters">
    <xsl:if test="$TargetNamespace=''">
      <xsl:message terminate="yes">
        The Parameter 'TargetNamespace' is undefined.
      </xsl:message>
    </xsl:if>
    <!-- ... -->
  </xsl:template>

  <xsl:template match="tns:Counter" mode="Counter">
    <xsl:text>
      private static PerformanceCounter _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>;

      </xsl:text><xsl:value-of select="$AccessModifier"/><xsl:text> static PerformanceCounter </xsl:text><xsl:value-of select="@Symbol"/><xsl:text>
      {
        get
        {
          MakeSureCountersAreInitialized();
          return _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>;
        }
      }
</xsl:text>
  </xsl:template>

  <xsl:template match="tns:Counter[@Type='RawFraction']" mode="Counter">
    <xsl:text>
      private static PerformanceCounter _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>;

      </xsl:text><xsl:value-of select="$AccessModifier"/><xsl:text> static PerformanceCounter </xsl:text><xsl:value-of select="@Symbol"/><xsl:text>
      {
        get
        {
          MakeSureCountersAreInitialized();
          return _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>;
        }
      }

      private static PerformanceCounter _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>Base;

      </xsl:text><xsl:value-of select="$AccessModifier"/><xsl:text> static PerformanceCounter </xsl:text><xsl:value-of select="@Symbol"/><xsl:text>Base
      {
        get
        {
          MakeSureCountersAreInitialized();
          return _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>Base;
        }
      }
</xsl:text>
  </xsl:template>

  <xsl:template match="tns:Counter" mode="InitCounter">
    <xsl:text>
        _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text> = new PerformanceCounter(
          CategoryName,
          "</xsl:text><xsl:value-of select="@Name"/><xsl:text>",
          false);
</xsl:text>
  </xsl:template>

  <xsl:template match="tns:Counter[@Type='RawFraction']" mode="InitCounter">
    <xsl:text>
        _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text> = new PerformanceCounter(
          CategoryName,
          "</xsl:text><xsl:value-of select="@Name"/><xsl:text>",
          false);

        _</xsl:text><xsl:value-of select="@Symbol"/><xsl:text>Base = new PerformanceCounter(
          CategoryName,
          "</xsl:text><xsl:value-of select="@Name"/><xsl:text> Base",
          false);
</xsl:text>
  </xsl:template>

  <xsl:template match="tns:Counter" mode="CreateCounter">
      <xsl:text>
      {
        CounterCreationData counter = new CounterCreationData();

        counter.CounterName = "</xsl:text><xsl:value-of select="@Name" /><xsl:text>";
        counter.CounterHelp = "</xsl:text><xsl:value-of select="@Help" /><xsl:text>";
        counter.CounterType = PerformanceCounterType.</xsl:text><xsl:value-of select="@Type" /><xsl:text>;

        counters.Add(counter);
      }
</xsl:text>
  </xsl:template>

  <xsl:template match="tns:Counter[@Type='RawFraction']" mode="CreateCounter">
      <xsl:text>
      {
        CounterCreationData counter = new CounterCreationData();

        counter.CounterName = "</xsl:text><xsl:value-of select="@Name" /><xsl:text>";
        counter.CounterHelp = "</xsl:text><xsl:value-of select="@Help" /><xsl:text>";
        counter.CounterType = PerformanceCounterType.</xsl:text><xsl:value-of select="@Type" /><xsl:text>;

        CounterCreationData counterBase = new CounterCreationData();

        counterBase.CounterName = "</xsl:text><xsl:value-of select="@Name" /><xsl:text> Base";
        counterBase.CounterHelp = "</xsl:text><xsl:value-of select="@Help" /><xsl:text>";
        counterBase.CounterType = PerformanceCounterType.RawBase;

        counters.AddRange(new CounterCreationData[]{counter, counterBase});
      }
</xsl:text>
  </xsl:template>

  <!-- ... -->
</xsl:stylesheet>

On lines 9 to 11 you’ll find the declaration for the parameters which you can use to change the namespace, the class name and the access modifiers (public vs internal really) for the generated classes.

Starting on lines 22 and 37 respectively, you find different templates for general counters and the RawFraction type counters. I use this to automatically generate the base counter so you won’t have to worry about it. You can do similar things for other counters which need a base counter. Then, starting on lines 63 and 72 respecctively, I initialize the counters, with specialization again for the RawFraction counter types. And starting on lines 86 and 100 respectively you’ll find the code to create and set the CounterCreationData which is used to register perf counters.

You can find the full code in the ZIP file linked to at the end of this post. With this we basically have all the tools we need to actually generate the code as part of the build. We just need to bring the pieces together.

Step 4: Bringing it Together aka Updating the Project

Well yes, I have silently assumed that you have a c# project (.csproj or any other project that is supported by MSBuild.exe) that you’re working on to update. All we need to do in the .csproj is to add the files we authored, then run the XSLT transformation and add the output .cs file to the list of source code files as well. And here’s how you can do that.

<?xml version="1.0" encoding="utf-8"?>
<Project ToolsVersion="4.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003" DefaultTargets="Build">
  <!-- ... -->
  <ItemGroup>
    <PerfCounterXml Include="Diag\PerfCounters.xml">
      <OutputCs>Diag\PerfCounters.Generated.cs</OutputCs>
      <Parameters>
        <Parameter Name="TargetNamespace" Value="$(RootNamespace).Diag" />
      </Parameters>
      <SubType>Designer</SubType>
    </PerfCounterXml>
    <PerfCounterXslt Include="Diag\PerfCounters.xslt" />
    <Compile Include="Diag\PerfCounters.Generated.cs">
      <PerfCounters>true</PerfCounters>
      <AutoGen>true</AutoGen>
      <DependentUpon>PerfCounters.xml</DependentUpon>
    </Compile>
  </ItemGroup>
  <ItemGroup>
    <None Include="Diag\PerfCounters.xsd">
      <SubType>Designer</SubType>
    </None>
  </ItemGroup>
  <!-- XSL Transform for Perf Counters -->
  <Target Name="GeneratePerfCounters" BeforeTargets="BeforeBuild"
      Inputs="@(PerfCounterXml);@(PerfCounterXslt)"
      Outputs="@(PerfCounterXml->'%(OutputCs)')">
    <XslTransformation XmlInputPaths="@(PerfCounterXml)"
      XslInputPath="@(PerfCounterXslt)"
      OutputPaths="@(PerfCounterXml->'%(OutputCs)')"
      Parameters="@(PerfCounterXml->'%(Parameters)')" />
  </Target>
</Project>

Add lines 4 to 32 to the end of the project file and make sure the paths you’re using point to the places where you actually stored the files. On line 8 you can see that I’m passing the target namespace parameter (called out in step 3) by concatenating the assemblies default root namespace and “.Diag”. This way you can actually put this stuff into a .targets file that you can include in all of the projects which take advantage of this framework.

Starting on line 25 I defined the actual target which runs the XslTransformation task that comes with .net 4.0. I also declared the inputs as being the XML file and the XSLT file — this way, while experimenting with the XSLT, the code gets regenerated also if the XML file hasn’t changed, but the XSLT has.

Using the Generated Classes

So now you have pretty much all the code you need to use these performance counters of yours. All that’s left is actually writing the code which

  1. Installs the Performance Counters
  2. Updates the Performance Counters
  3. Uninstalls the Performance Counters

#1 and #3 would probably be used by your installer and #2 by your application at runtime. Incrementing and decrementing the counters is as easy as

PerfCounters.CymbeMail.ActiveConnections.Increment();
//...
PerfCounters.CymbeMail.ActiveConnections.Decrement();

Where PerfCounters is the name of the generated class which contains all the generated perf counters, CymbeMail is the name of the class for the category (the Symbol attribute, remember?) and ActiveConnections is of course the symbol name for the counter we’re modifying. Isn’t this simple?

As for setting things up (or removing them), the relevant piece of code gets generated for you, too. So all you need to do is actually call it, potentially from a small application that you run — as I mentioned before — from your installer.

// Setup the Performace Counters
PerfCounters.Setup();

// And for the Uninstaller:
// Remove the Performance Counters
PerfCounters.Remove();

Of course you’ll have to make sure that the version of the generated code that’s run by the uninstaller is the same version as the installer did run — else you may end up with stale categories / counters on the machine. But then again, if you’re installing through an MSI package, you get that for free … when done properly.

Summary

In just a few steps I have shown how you can build a framework to use performance counters in .Net applications. On top of it’s simplicity, it’s also quite easy to modify the framework and adapt it to your own needs or extend it to allow more performance counter types.

And finally, as promised, here’s the ZIP file which contains the relevant pieces. Please forgive me for not adding the .csproj file — that actually contains other relevant data that I didn’t want to share. Instead I added the generated c# code file for reference.

PerfCounters.zip (4.08kb)