Use this not this: Logging / Event Tracing

For logging, we’d  like you to use Event Tracing for Windows (ETW) instead of creating your own.  There are several reasons:

  1. ETW is fast—probably faster than most custom solutions that are implemented as part of an app
  2. Good tools support with Xperf, Windows Performance Toolkit, and so on.
  3. Traces are stored in kernel buffer—any traces your app has written aren’t lost if your app terminates unexpectedly
  4. Your support staff can work with other support organizations, such as Microsoft CSS, seamlessly, because ETW is a common infrastructure

Dan Ruder has provided a sample C++ application covering how to add Event Tracing for Windows (Logging) to a Windows application and has also written an article on how to add Event Tracing for Windows to a C++ Application (copied below).

See Also

The following article, authored by Dan Ruder to compliment the aforementioned sample, covers how to add ETW to your app:

How to Add High-Performance Runtime Tracing to your Application

Applies To

Windows API programming for the following versions of Windows:

Client: Windows 7, Windows Vista

Server:  Windows Server 2008 R2, Windows Server 2008

Summary

This article explains how to use the Event Tracing for Windows (ETW) functions to add runtime trace logging to your application.  The ETW system provides high-speed logging that can be enabled and disabled dynamically without restarting the application.  This makes ETW useful for diagnosing application behavior without invasive debugging.  It can be used to:

  • Record how users interact with your application
  • Record resource consumption and release patterns
  • Record performance statistics
  • Create a history of operations to verify correct application behavior
  • Create a history to troubleshoot incorrect application behavior
  • Enable advanced end-to-end diagnostics across multiple software layers

 

This article will focus on the manifest-based ETW functions which are available starting in Windows Vista and Windows Server 2008.

Prerequisites

List of technologies and software that you need to understand or install in order to create and run this code.

  • Microsoft Windows 7 Software Development Kit

Solution

The design of the Event Tracing for Windows (ETW) API is that an application does not write the whole trace message at runtime; instead, it writes an event descriptor plus parameter data to a trace session which saves the data into a log.  Later, the trace log is processed by matching the event descriptors with a list of events in an XML manifest file and formatting message strings with event parameter data.  Therefore, the steps to use the ETW API in your application are:

  1. Design the trace events your application will report. 
  2. Create an event manifest to describe the event messages.
  3. Add tracing functions to your source code.
  4. Add the event manifest to your project.
  5. Build the project.

 

Please refer to the Test Case section of this article for information on how to create a trace log when your application runs.  This will enable you to test how your application logs trace messages. 

 

The following sections will explain how to add trace messages to your application.

Design the trace events your application will report

1. Create the event messsages.   Each message will become a single ETW event. Identify the operations your application should report, the message data it should record for each, and the intended audience for each.  The operations may be organized in different ways:

  • Abstraction Level (major & minor problem domain levels, implementation levels, etc)
  • Structure (application, component, subcomponent, module, function, etc)
  • Purpose (track resources, operations, module/feature usage, occurrences of events, measure performance, etc)
  • Severity (error, warning, informational, etc)
  • Any other strategy which suits your application and intended audiences

 

Each message can have a text string and 12 additional parameters, each having a variety of data types such as integers, pointer values, GUIDs, and strings.  The ETW system will add time/date stamps, thread IDs, and other values so you don’t need to supply these.

The ETW system defines four audiences who can listen for specific messages on different channels:

  • System administrators
  • Support staff
  • Analysis & monitoring tools
  • Developers of the application

 

2. Group the event messages by executable file that will log them.   Each executable file (.EXE or .DLL) in your application that logs events needs to have its own event manifest.  An event manifest is an XML file that describes the events produced by an executable and gets compiled into the executable.  The manifest is used to register the executable with the ETW system as a provider. 

3. Give each event an ID and optional tags.   Every event must have a unique integer identifier.  To make trace analysis easier, the ETW system defines the following optional tags that you can use to group events:

Tag

What it refers to

Examples

Id

Required

Uniquely identifies each event in the provider.

3 – BeginComputation

4 – FinishComputation

Channel

Optional

The target audience for the event

ProviderName/Admin

ProviderName/Operational

ProviderName/Analytic

ProviderName/Debug

Version

Optional

Version number of the event; allows you to change the format of your trace message data later.

1

Level

Optional

Severity or verbosity of the event

WINEVENT_LEVEL_ERROR (2)

 

Keyword

Optional

Subcomponent of your application which produces the trace message

GUI

FileManager

MemoryManager

Task

Optional

Logical task or action that your application records

Drawing

AccessDataStore

 

Opcode

Optional

Specific command or sub-task that your application records

BeginPainting

EndPainting

Create an event manifest for your application

Once you have defined the events that your application will log, the next step is to create an XML event manifest file which describes each trace event.  The manifest will be compiled with the message compiler (mc.exe) to produce a header file and resource for use in your project source code.

1. Run the Manifest Generator (ecmangen.exe) tool from the Windows SDK.   This tool is located in the \bin directory where you installed the SDK.

2. Create a new event provider.   This step requires two actions:

  • First, select the “Events Section” node in the far left pane and then “New Provider” in the far right pane.
  • Second, give the provider a name, symbol, and GUID.  Set the Resources and Messages boxes to the full path where the application will be installed. Click “Save” in the far right pane.

3. Create a new template to define parameter types for each message that requires input parameters.   If multiple event messages have the same number and types of parameters, they can share the same template.  Add each parameter to the template, then save the template.  Do the same for all remaining templates. 

4. Define metadata used to tag events.   Create the valuesfor the levels, keywords, tasks, channels, and opcodes that will be used to tag events.  Create and save these in a similar manner as you created templates in step #3.

5. Create events by giving each a symbol, event ID, message text and template.   When you write the message text, use %1, %2, %3, …, %12 to specify the positions of each parameter.  Make sure the event template matches the format of the message text with parameters.  Assign any channels, levels, tasks, keywords, and opcodes which apply to the event.  Save the event.  Do the same for all remaining event messages your application will produce.

6. Save the event manifest to your project directory.   This will allow you to include the manifest file in the build process for your project.

Add event tracing functions to your source code

1. Compile the manifest.   Use the following command line to compile the manifest file and generate a header file which you will include in your project’s .cpp files (change “ProjectName” to the actual name of your project):

   mc -um ProjectName.man -h . -z ProjectName

The header file will contain wrapper functions which simplify how your application calls the ETW API functions to log events.

2. Add the event logging functions to your application.   The application must call the EventRegister function once before any other event functions.  Then, it will call EventWrite each time it reports an event.  Finally, it must call EventUnregister after it is done writing events.

While an application can call the EventRegister, EventWrite, and EventUnregister functions directly, it is easier to call the wrapper functions which were generated by the message compiler in the previous step.  The wrapper functions are named EventRegister<Provider Name> , EventUnregister<Provider Name> , and EventWrite<Event Symbol Name> .

The following example code shows how to call the EventRegister and EventUnregister wrapper functions at the beginning and ending of the main function:

#include <windows.h>

#include <evntprov.h>

#include <stdio.h>

#include <conio.h>

#include "EtwExample.h"

 

void * AllocateBuffer (SIZE_T byteLen);

void FreeBuffer (void * p);

 

int wmain (int argc, wchar_t *argv[])

{

   ULONG result;

   BYTE * pBuffer = NULL;

 

   // Register this program with the ETW system as a provider.

   result = EventRegisterEtwExample();  // MC.EXE generated wrapper

   wprintf (L"Press a key to exit\n");

   while (!_kbhit())

   {

      wprintf (L"Inside Loop\n");

     

      pBuffer = (BYTE *)AllocateBuffer (8);

 

      Sleep(300);

 

      FreeBuffer (pBuffer);

   }

 

   result = EventUnregisterEtwExample();  // MC.EXE generated wrapper

 

   return (0);

}

 

The following example code shows how to call the EventWrite wrapper function to log an event.  The wrapper function simplifies the work of building the event descriptor and event parameter data:

void * AllocateBuffer (SIZE_T byteLen)

{

   void * p = NULL;

 

   p = LocalAlloc (LPTR, byteLen);

 

   EventWriteBUFFER_ALLOCATED_EVENT(p, byteLen);  // MC.EXE generated wrapper  

   return (p);

}

Add the event manifest to your project

Develoment projects which use Event Tracing for Windows need to include the following build steps to ensure the event manifest file is compiled into the application.

1. Add a build step that compiles the manifest.   The manifest is compiled by the message compiler to produce a header file and resource file.  It is important for this build step to finish before the C++ compiler runs because your source code will include the header file so that it can report the events which are defined in the manifest. 

In a Visual Studio project, define a Pre-Build Event in the project properties and add the following command:

   mc -um $(ProjectName).man -h $(ProjectDir)  -z $(ProjectName)

2. Add the generated header file to the project and source code.   This header will be named $(ProjectName).h.  This creates a project dependency so that the source code gets compiled each time the manifest is updated.

3. Add the generated resource script (.rc file) to the project.   This resource script will be named $(ProjectName).rc.

Test Case

Once you have added trace logging to your application, you can test how it logs messages by following these steps in an administrator console window:

 

  1. Install the manifest file with your application and register it as a provider:

 

wevtutil im EasyEtw.man

 

  1. Start a trace session; this can be done before or after your application has started.

 

logman start -ets EtwEx -p "EasyEtw" 0 0 -o tracelog.etl

 

  1. Run the application; the ETW system will capture the events.

 

EasyEtw.exe

 

  1. Stop the trace session; the application can stay running but events are no longer logged.

 

logman stop -ets EtwEx

 

  1. Analyze the resulting trace log by generating a report or running an analysis tool:

 

tracerpt -y project.etl  ; generates an XML file report

 

  1. Remove the manifest file when it’s no longer needed such as when the application is uninstalled:

 

wevtutil um project.man

Security considerations

Applications should not record personally-identifiable or sensitive information including, but not limited to:  passwords, driver’s licenses, or credit account information to a trace log.  Once this data is recorded to a log, it could be easily disclosed to unauthorized parties.  Although the default security of the ETW system allows only administrators to install providers and enable trace sessions, it likely will be passed to support teams and developers who are authorized to debug the application, but not authorized to see the data processed by the application.

Additional Resources

A bulleted list of hyperlinks to related content, such as API docs, feature or technology overviews, architectural guidance, other how-tos, KB articles, and/or code samples

Complete Code Listing

The following code listing contains a complete example prgram that shows how to call the Event Logging for Windows functions and the manifest file generated by the Manifest Generator (ecmangen.exe).

EasyEtw.cpp

/*---------------------------------------------------------------------------

Example application which shows how to the manifest-based Event Tracing for

Windows (ETW) API functions.

 

This application registers itself as an ETW provider named "EasyEtw" and then

calls two functions, AllocateBuffer() and FreeBuffer() that write events,

inside a loop until the user hits a key.

 

The message compiler (mc.exe) produces EtwExample.h, which contains constants

and wrapper functions to simplify how the application calls the ETW APIs. The

header is not shown here because it is auto-generated and contains more code

than is needed by this sample.

 

To run this example and enable the ETW system to capture events, follow these

steps from an administrator console window:

 

  1. Put EasyEtw.man in the same directory as EasyEtw.exe and register

     EasyEtw.man as a provider: 

 

     wevtutil im EasyEtw.man

 

  2. Start the trace logging session:

 

     logman start -ets EtwEx -p "EasyEtw" 0 0 -o tracelog.etl

 

  3. Run the application:

 

     EasyEtw.exe

 

  4. Stop the logging session:

 

     logman stop -ets EtwEx 

 

 

  5. Tracelog.etl will contain the trace in binary format.  Convert it to

     a human readable format such as CSV or XML:

 

     tracerpt -y project.etl            -- to generate an XML file report

     tracerpt -y -of CSV project.etl    -- to generate a CSV file report

 

  6. Remove the .man file as a provider when it's no longer needed, such as

     during application uninstall.

 

     wevtutil um project.man

 

Example code applies to:

  • Windows 7, Windows Vista
  • Windows Server 2008 R2, Windows Server 2008

---------------------------------------------------------------------------*/

#include <windows.h>

#include <evntprov.h>

#include <stdio.h>

#include <conio.h>

#include "EtwExample.h"

 

void * AllocateBuffer (SIZE_T byteLen);

void FreeBuffer (void * p);

 

int wmain (int argc, wchar_t *argv[])

{

   ULONG result;

   BYTE * pBuffer = NULL;

 

   // Register this program with the ETW system as a provider.

   result = EventRegisterEtwExample();  // MC.EXE generated wrapper.

 

   wprintf (L"Press a key to exit\n");

   while (!_kbhit())

   {

      wprintf (L"Inside Loop\n");

     

      pBuffer = (BYTE *)AllocateBuffer (8);

 

      Sleep(300);

 

      FreeBuffer (pBuffer);

   }

 

   result = EventUnregisterEtwExample();  // MC.EXE generated wrapper.

 

   return (0);

}

 

/*---------------------------------------------------------------------------

AllocateBuffer (byteLen)

 

Logs an event named "Allocate" to the EtwExample/Debug channel.

---------------------------------------------------------------------------*/

void * AllocateBuffer (SIZE_T byteLen)

{

   void * p = NULL;

 

   p = LocalAlloc (LPTR, byteLen);

 

   EventWriteBUFFER_ALLOCATED_EVENT(p, byteLen);  // MC.EXE generated wrapper.

   return (p);

}

 

/*---------------------------------------------------------------------------

FreeBuffer (p)

 

Logs an event named "Free" to the EtwExample/Debug channel.

---------------------------------------------------------------------------*/

void FreeBuffer (void * p)

{

   LocalFree (p);

   EventWriteBUFFER_FREED_EVENT(p);   // MC.EXE generated wrapper.

}

EasyEtw.man

<?xml version="1.0" encoding="UTF-16"?>

<instrumentationManifest xsi:schemaLocation="https://schemas.microsoft.com/win/2004/08/events eventman.xsd" xmlns="https://schemas.microsoft.com/win/2004/08/events" xmlns:win="https://manifests.microsoft.com/win/2004/08/windows/events" xmlns:xsi="https://www.w3.org/2001/XMLSchema-instance" xmlns:xs="https://www.w3.org/2001/XMLSchema" xmlns:trace="https://schemas.microsoft.com/win/2004/08/events/trace">

  <instrumentation>

    <events>

      <provider name="EtwExample" guid="{FE2625C1-C10D-452C-B813-A8703EA9D2BA}" symbol="ETW_EXAMPLE_PROVIDER" resourceFileName="c:\Temp\EtwExample\EtwExample.exe" messageFileName="c:\Temp\EtwExample\EtwExample.exe">

        <events>

          <event symbol="BUFFER_ALLOCATED_EVENT" value="1" version="1" channel="EtwExample/Debug" level="win:Informational" opcode="Allocate" template="BufferAllocate" keywords="BufferManager " message="$(string.EtwExample.event.1.message)">

          </event>

          <event symbol="BUFFER_FREED_EVENT" value="2" version="1" channel="EtwExample/Debug" level="win:Informational" opcode="Free" template="BufferFree" keywords="BufferManager " message="$(string.EtwExample.event.2.message)">

          </event>

        </events>

        <levels>

        </levels>

        <opcodes>

          <opcode name="Allocate" symbol="ALLOCATE_OPCODE" value="10">

          </opcode>

          <opcode name="Free" symbol="FREE_OPCODE" value="11">

          </opcode>

        </opcodes>

        <channels>

          <channel name="EtwExample/Debug" chid="EtwExample/Debug" symbol="DEBUG_CHANNEL" type="Debug" enabled="false">

          </channel>

          <channel name="EtwExample/Analytic" chid="EtwExample/Analytic" symbol="ANALYTIC_CHANNEL" type="Analytic" enabled="false">

          </channel>

        </channels>

        <keywords>

          <keyword name="BufferManager" symbol="BUFFER_MANAGER_KEYWORD" mask="0x800000000000">

          </keyword>

        </keywords>

        <templates>

          <template tid="BufferAllocate">

            <data name="BaseAddress" inType="win:Pointer" outType="win:HexInt64">

            </data>

            <data name="Length" inType="win:UInt64" outType="xs:unsignedLong">

            </data>

          </template>

          <template tid="BufferFree">

            <data name="BaseAddress" inType="win:Pointer" outType="win:HexInt64">

            </data>

          </template>

        </templates>

      </provider>

    </events>

  </instrumentation>

  <localization>

    <resources culture="en-US">

      <stringTable>

        <string id="level.Informational" value="Information">

        </string>

        <string id="EtwExample.event.2.message" value="Freed buffer with base address %1.">

        </string>

        <string id="EtwExample.event.1.message" value="Allocated buffer with base address %1 and length %2.">

        </string>

      </stringTable>

    </resources>

  </localization>

</instrumentationManifest>