ETW Logging - TraceEventSession overwrites file

Question

I have an IIS application which uses TraceEventSession to capture ETW messages and forward them onto a log file: -

TraceEventSession _etwSession = new TraceEventSession(
   "MyEtwLog", @"C:\Logs\MyEtwLog.etl") { 100 };
_etwSession.EnableProvider(
   TraceEventProviders.GetEventSourceGuidFromName, "MyEtwLog"),
   TraceEventLevel.Always);

It is working fine, but for some reason every time I restart the app it overwrites the log file instead of appending to it. Any idea what I'm missing?

Thanks in advance

Answer 1

Disclaimer: I contribute to TraceEvent internally at Microsoft

You can append to an ETW file using EVENT_TRACE_FILE_APPEND_MODE, which TraceEvent doesn't support today. We could potentially add it, but I can see more problems with exposing the API than not.

TL;DR -- Full ETW sessions with their metadata are what is logged into each file, and each session can have different options, like clock resolution, for example which can cause subtle timestamp inaccuracies that may go under your radar and cause you grievance at some point.

Here's what I recommend. I've put in a sleep, but you'd put some logic to decide how to rotate the files (like keeping track when your IIS instance refreshes).

var _etwSession = new TraceEventSession("MyEtwLog", @"C:\Logs\MyEtwLog." + MyTimestamp + ".etl");
_etwSession.EnableProvider(new Guid("MyGuid"), TraceEventLevel.Always);

Thread.Sleep(1000 * 60);

_etwSession.SetFileName(@"C:\Logs\MyEtwLog" + timestamp + ".etl");

A little background:

ETW files are binary consumer data (your log messages), and then metadata provided by the ETW subsystem that every log message gets for free. Like ThreadID, logical processor number, whether it cam from kernel or user mode, and lastly but most importantly the timestamp, which is actually a value dependent on the processor frequency.

In addition to the above, ETW file "rundown", think of it like state of the operating system, is also flushed to the file at the beginning and end of the session.

And despite the fact the most consumers think ETW logs are like sort of plain logs, they are sort of kind of not. They are intimately tied to the time the trace was taken (remember ETW was used mostly for perf analysis by the Windows Kernel team in the beginning). Things have improved in the regard recently such that the file can be fully treated independently and for your purpose it may very well be.

But I can imagine many cases where appending to the same file is not a good idea.

Oh, and another big one. ETW files are read sequentially from beginning to end every single time. That is it'll keep growing and you can't read from it in the middle, at least not in a supported way :-)

And lastly you'll still not want to append, because imagine you write a log file foo.etl, then you go buy a spanking new processor and you append to this log file, all your timestamps collected in your previous session will be off by some number.

Answer 2

I do not think you are missing anything. There is no way to append to an existing file with TraceEventSession. Merging different files together with TraceEventSession.Merge is possible, but will only yield correct results if they are from the same machine, and it was not restarted in the mean time.

In the ETW API there is a way to append with the EVENT_TRACE_FILE_MODE_APPEND option if you want to do it outside of TraceEventSession, but it has limitations.