Alois Kraus

blog

  Home  |   Contact  |   Syndication    |   Login
  133 Posts | 8 Stories | 368 Comments | 162 Trackbacks

News



Archives

Post Categories

Programming

With Enterprise Library 6.0 which does only target .NET 4.5 we also have the power of semantic logging at our hands. The term semantic means that you do not log text messages but structured data aka objects which define specific actions in your application like startup, save, … which can be later more easily be parsed from that event stream. To make parsing and correlating activities easier is a noble goal in itself but there is a much bigger advantage when you embrace semantic logging with Enterprise Library. Now you can save your semantic logs to ETW (Event Tracing for Windows) and correlate your application activity with the system wide activities of all subsystems if you like. To pinpoint a bottleneck in disc IO, CPU, network in your or totally unrelated processes is now possible.

But what about .NET 4.0 or even .NET 3.5? You can write ETW events with these .NET versions as well but apparently no one did ever use it. The main issue with these earlier .NET versions is that you need to define an ETW manifest and register it in the system. Most .NET devs are unaware of ETW and did therefore not see the value of supporting this additional output channel. To create your own ETW manifest you need only to call ecmangen from the Windows SDK. I have created a simple manifest to route regular trace messages to ETW.

The Events section defines the logged data along with the defined task, keyword and other codes. The actual event data is defined in the Templates. For tracing there is not much structure except the timestamp, severity, message and the duration on method leave.

image

After you have defined the structure of your data now comes the nice part. You can generate C# or C++ code from the manifest directly! For this you need to call the

message compiler mc.exe. To create a static logger class in the namespace ApiChange.Tracing you can use:

mc -css ApiChange.Tracing ApiChangeTraces.man

There you have a source file named ApiChangeTraces.cs and a rc file which must be further converted to a true Win32 resource.

rc ApiChangeTraces.rc

will generate ApiChangeraces.res which can be consumed by any C# project where you can directly embed it.

image

That´s nearly it. The only thing left to do is to register the manifest to make Windows aware of your ETW events.

This is done with

wevtutil im ApiChangeTraces.man

To register a changed manifest again you first need to uninstall it with

wevutil um ApiChangeTraces.man before your can register it again.

One pesky thing does remain though. Your manifest does contain localizable resources so you need to write in your manifest! files the path to your executable before you can register the manifest successfully. At least environment variables are allowed. Your binary resources do not contain the manifest itself so you could in principle patch the manifest after installation of your application to the target path of your executable. Or you do copy your executable with the localized manifest resources to the configured location of the manifest.

<provider name="ApiChangeTracing" guid="{7D641D51-9BE4-4E27-A422-4832618146B5}" symbol="ApiChangeTracing" resourceFileName="%WINDIR%\Temp\SampleProvider.exe" messageFileName="%WINDIR%\Temp\SampleProvider.exe">

Now that we are ready to call into the generated code like this:

static void Main(string[] args)
{
  for(int i=0;i<int.MaxValue;i++)
  {
    Console.WriteLine("Writing round: {0}", i);
    ApiChangeTracing.EventWriteTraceMethodEnter(DateTime.Now.ToString(), "SampleProvider.Program", "Main");
    ApiChangeTracing.EventWriteTraceInfo(DateTime.Now.ToString(), "Info Message " + i);
    ApiChangeTracing.EventWriteTraceWarning(DateTime.Now.ToString(), "Warning message " + i);
    ApiChangeTracing.EventWriteTraceError(DateTime.Now.ToString(), "Error message " + i);
    ApiChangeTracing.EventWriteTraceException(DateTime.Now.ToString(), "exception message " + i);
    ApiChangeTracing.EventWriteTraceMethodLeave(DateTime.Now.ToString(), "SampleProvider.Program", "Main", 300);
    Thread.Sleep(1000);
  }
}

No I do not propose to use DateTime as time measurement mechanism in tracing with an accuracy below 15.6ms. I did use it only for demo purposes here. You can define in your manifest not only strings but also dates which do work as well. Unfortunately the Windows Performance Analyzer UI could not decode ETW dates so I did stick to strings. In theory you can wait with the registration of your ETW provider until you need to enable it. This can be useful if you do want to allow non admin deployments for your application.

I use xperf to start and stop logging which is part of the Windows 8 SDK (it does work with Windows Vista+) as Windows Performance Toolkit. This does also include the viewer wpa.exe.To start tracing you need not only to enable your provider but also the kernel trace with at least PROC_THREAD so the viewer can gather information which process and thread did log this ETW event.

xperf -start apisession -on ApiChangeTracing -on PROC_THREAD

xperf -stop apisession -stop -d recording.etl

image

Ok that is nice but why not log to a simple text file? Well there are mainly two reasons. Did you see the vertical blue bar in the graph and the highlighted trace statement? Every trace call you do log does show up in the timeline of your traced data. If you want to check why your system does behave so sluggish after your application has been started you can find out know. You can enable more kernel providers to trace e.g. every context switch, file IO, network IO request. If you want to even with call stacks. That does give you a holistic view of the system across all processes at once.

Did you say call stacks? What about my own trace messages? Do I get them as well? Yes that is the second reason why you should consider writing an ETW provider. Every ETW event that is written can capture its call stack if you want to. There is no need in managed code to call new StackTrace or something similar. Windows will take care with its own super fast stack walking. This does work out of the box for unmanaged code. Managed stack walks are a little trickier.

First we need to enable stack walking for our trace provider:

xperf -start apisession -on ApiChangeTracing:::'stack' -on PROC_THREAD+LOADER

To capture managed stack frames we need to enable a CLR ETW provider to capture method and module offsets.

xperf -start ClrSession -on  e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x98:5 -f clr.etl -buffersize 128 -minbuffers 256 -maxbuffers 512

The ClrSession does enable the provider Microsoft-Windows-DotNETRuntime by its guid with the keywords

  • LoaderKeyword 0x8
  • JITKeyword 0x10
  • EndEnumerationKeyword 0x80

and the level 5 which means verbose. The rest is only the declaration of the file and buffer sizes to tore the events.

Now you can execute your use case.

After that you need to start another CLR session which does collect the missing pieces:

xperf -start ClrRundownSession -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x118:5+a669021c-c450-4609-a035-5af59af4df18:0x118:5 -f clr_DCend.etl -buffersize 128 -minbuffers 256 -maxbuffers 512

There we do add a second instance of the already running Microsoft-Windows-DotNETRuntime provider with

  • LoaderKeyword 0x8
  • JITKeyword 0x10
  • Not Documented 0x100

And the Microsoft-Windows-DotNETRuntimeRundown provider with

  • LoaderRundownKeyword 0x8
  • JitRundownKeyword 0x10
  • EndRundownKeyword 0x100

I am not sure why the 0x100 level in the DotNETRuntime provider is not documented.

Now we can stop and merge all open sessions into one to be able to correlate the traces and to store them in recording.etl

To create for NGenned assemblies the corresponding pdbs you need to do “set XPERF_CreateNGenPdbs=1”. That will trigger during the stopping of the session the creation of managed pdbs for all NGenned assemblies.

xperf -stop ClrSession ClrRundownSession apisession -stop -d recording.etl

You will notice that stopping and merging does take quite a while. The reason behind this is that xperf will (unlike logman) now create for all NGenned assemblies a matching pdb by calling NGen createpdb …. which does take a while when you have many NGenned assemblies. With .NET 4.5 this will happen much more frequently because of the automatic NGen feature where depending on its usage all often used assemblies are automatically NGenned. If you do not have set the _NT_SYMBOL_PATH environment variable xperf will create the pdbs in the folder C:\Symbols. If you have it set it will generate the pdbs in the first symbol download directory it does find.

Now you can view the generated traces with.

wpa recording.etl

You need to download the first time from Windows all kernel symbols. Later you can alter the symbol path to skip the time consuming search for symbols of your own modules. It does then suffice to configure

image

When you did all right then you can look at the call stacks of all trace calls.

image

That is a really nice thing. I admit that the manual steps are a bit involved but there is no one stopping you to automate these steps in a script to get full info at any time. As a matter of fact I did it for your and my convenience:

Record.cmd

@echo off
if "%1" EQU "-start" (
xperf -start ClrSession -on  e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x98:5 -f "%temp%\clr.etl" -buffersize 128 -minbuffers 256 -maxbuffers 512
xperf -start apisession -on ApiChangeTracing:::'stack' -on PROC_THREAD+LOADER
goto :Exit
)
if "%1" EQU "-stop" (
xperf -start ClrRundownSession -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x118:5+a669021c-c450-4609-a035-5af59af4df18:0x118:5 -f "%temp%\clr_DCend.etl" -buffersize 128 -minbuffers 256 -maxbuffers 512
set XPERF_CreateNGenPdbs=1
xperf -stop ClrSession ClrRundownSession apisession -stop -d "%temp%\combined.etl"
goto :Exit
)
if "%1" EQU "-view" (
wpa "%temp%\combined.etl"
goto :Exit
)

echo Usage:
echo Record.cmd -start or -stop  or -view
echo            -start Start a trace session
echo            -stop  Stop a trace session
echo            -view  View the collected traces

goto :Exit

:Exit

 

From this point on it is a small step to configure lightweight tracing by default and when you want to see more during an interesting use case you can even tracing dynamically. That does open a whole new world of possibilities. E.g. you can use this approach shown here to collect during performance regression tests profiling data with with your traces and all context switches and file IO. If you gather during all of your performance regression tests profiling data with very low impact it is much easier to diagnose sudden performance drops. You no longer need to repro the issue on two different baselines of your software. You can directly start analyzing the root cause of your performance issue. Perhaps it was SQL server hitting the disc, the virus scanner was active again or the defragmenter job was running. This way you can quickly check if the environment was not friendly during your test and the one random spike in your regression has a natural explanation.

So why wait for .NET 4.5 and Enterprise Library 6.0? You can take advantage of this stuff already today. You can also create your own parser to create custom views of the collected data. A very nice looking library is e.g. Linq to Traces which is used by SvcPerf to visualize WCF communication. Unfortunately this library does not give you call stacks yet. There is another library called TraceEvent which is used by PerfView which is able to generate the native images later. If you want to spare some time and collect only the data and you want to create the managed pdbs only when you really want to view the data you can create from this one a tool to do exactly that. It does also deal with the oddities of .NET 4.0 and 4.5 where are some differences how the managed pdbs are created.

posted on Sunday, June 2, 2013 4:34 AM

Feedback

# re: Semantic Tracing For .NET 4.0 6/3/2013 12:03 AM James Tryand
Or you could just use the event and logging commands from powershell.

# re: Semantic Tracing For .NET 4.0 6/3/2013 12:25 AM James Tryand
Just to be clear : man about_Eventlogs pretty much covers it.

# re: Semantic Tracing For .NET 4.0 6/3/2013 2:23 AM Alois Kraus
I am not sure if for every trace call I do want to start an extra powershell process. Whatever the benefit would be (are there any?) the performance would bring an application to a grinding halt. Tracing is not logging. As I mentioned earlier the intention of tracing is to follow your application flow which can cause a lot of trace events to be generated.

Post A Comment
Title:
Name:
Email:
Comment:
Verification: