Sorry for my short answer, but I’m glad I grabbed your interest in this
– It’s one topic I love to evangelize because of the time and energy
it’s saved me. The executive summary is that ETW is an option to
replace debug prints with minimal developer effort, minimal source code
changes, and automatic performance benefits. ETW also offers many
enhanced functionality options, once the initial conversion is
completed.
First, I found an MSDN site to start reading from:
http://msdn.microsoft.com/library/default.asp?url=/library/en-us/ddtools
/hh/ddtools/st_32pf.asp
In addition, there is a powerpoint from WinHEC 2003 at the following
page under “General Driver Information”, “Debugging and Diagnostics”,
named “Diagnostic Tracing with Event Tracing for Windows and TraceView”:
http://www.microsoft.com/whdc/winhec/pres03.mspx
The power point slide provides a great summary of what ETW is all about
and points to samples in the DDK, while the MSDN site provides a
step-by-step model to enabling tracing. The rest of this post is
exceptionally long, as I want to provide a very full answer to what’s so
great about ETW. (much of the below is taken from one of my internal
presentations to my group – NT storage.)
ReallyLongDescriptionOfETW
Does this sound familiar to you? You want a checked build, or even a
few DbgPrints in your driver - but you aren’t going to get it? You can’t
set up a debugger? You don’t want to give out your private symbols
file? You’re chasing a bug that goes away when you slow the system down
(“Heisenbug”)? There is a solution…
ETW is a low-overhead generic logging mechanism which can be directed to
many places. All retail builds of Windows since Windows 2000 include
Event Tracing for Windows (ETW), and it’s easy to change over from
DbgPrintEx, KdPrintEx, or almost any other function you are currently
using.
ETW was designed to address our main problems with previous “solutions”.
It allows you to ship binaries with logging code left in (IMAPI (cd
burning service & driver), Redbook, CDROM in XP all use this). It
allows single machine logging, without requiring a kernel debugger.
Tracing using ETW does not expose the static text strings in the
resulting binary trace (More information on this later). Finally, when
it’s not enabled, ETW uses minimal overhead.
Protecting your company’s IP is important. With current solutions, many
developers put function names and significant other information in debug
prints which simplifies reverse engineering. With ETW, all the static
portions of a debug print statement are moved to the private symbol
file. As an added bonus, the pre-processing phase also automatically
includes the function name, source file name, and line number for each
of the debug prints. Part of the logging architecture for ETW
automatically attaches a timestamp to each and every event (instance of
the debug print being called). So, you get lots of free information
with less overhead and less “information leakage”.
Converting to basic ETW usage is easy. The five steps are:
- add ‘#include “filename.tmh”’ to each source file.
- define a GUID and tracing levels for controlling tracing in your
driver. - add calls to WPP_INIT_TRACING() in DriverEntry (AddDevice if Win2k
support required). - add calls to WPP_CLEANUP() in DriverUnload (RemoveDevice if Win2k
support required). - add RUN_WPP statement to your sources file (use special template for
Win2k support).
<note: i will give more details at the end of this long mail.>
Once you’re up and running with the basic ETW, you can then extend to
using more advanced functionality, such as easy logging of supported
“extended” formats. The ones most useful are %!STATUS! (for NTSTATUS
codes), %!HRESULT! (for HRESULT codes), %!IPADDR!, %!guid!, and
%!WAITTIME!. Each of these pretty-prints the related items when viewing
the traces, which saves time tracking down what NTSTATUS 0xC0000305 is
(STATUS_COPY_PROTECTION_FAILURE).
Why else use ETW? If you convert your macros (or use a new one) to
enable LEVEL and FLAG selection, you can enable logging in a more
fine-tuned way. You can use ETW for both your user-mode and kernel-mode
components and get a single log with both of their events interleaved.
You can redirect to the kernel debugger (in XP and higher). As a side
benefit, it will find those cases where you mismatched the format string
and argument types.
The remaining question is “Where should I add tracing?” There is no
magic here, as it requires the same considerations as any other type of
debugging help. Conversion of existing debug prints/asserts to remove
static debug strings from you binaries is a good start. If you’re
providing a library, providing a good trace statement in every error
path is also a good idea as it provides excellent benefits to the client
with minimal overhead. Other areas known to have been traced:
* Configuration settings
* Operations that deviate from standard
* State changes – information and cause
* Public APIs – input and results
* Scavenging or cleanup operations
Of course, you should always avoid tracing anything where your trace
data may expose security or privacy data, or even where it may appear to
do so.
-----------------------------
In-depth conversion process
-----------------------------
This will presume that you are using a macro of the form
KdPrintEx((component, level, …)). Some notes will be provided for
where changes are needed to support other macros or functions.
Step #1 – Adding the new include file.
For each .C/.C++ file with a debug print, include (after all other
includes) a file called .tmh. This must be done for each file
with a debug print, but is suggested for all files. For example, if
your source file was named “foo.cpp”, then you’d include “foo.tmh”.
Step #2 – Define a GUID and trace levels
Use your favorite GUID generator. I use UUIDGEN.EXE or GUIDGEN.EXE.
Use this GUID in a new header file you include in all your .C files.
The contents should be simliar to:
#define WPP_CONTROL_GUIDS <br>
WPP_DEFINE_CONTROL_GUID(MyDriver,(aaaaaaaa,bbbb,cccc,dddd,eeeeeeeeffff),
<br> WPP_DEFINE_BIT(MyDriverError) /* bit 0 = 0x00000001 / <br> WPP_DEFINE_BIT(MyDriverWarning) / bit 1 = 0x00000002 / <br> WPP_DEFINE_BIT(RedbookDebugTrace) / bit 2 = 0x00000004 / <br> WPP_DEFINE_BIT(RedbookDebugInfo) / bit 3 = 0x00000008 / <br> WPP_DEFINE_BIT(RedbookDebugD04) / bit 4 = 0x00000010 */ <br> )
Step #3 – Add call to WPP_INIT_TRACING() in DriverEntry
Register for ETW in your DriverEntry() routine by calling
WPP_INIT_TRACING(DriverObject, RegistryPath). See MSDN for
documentation. If you require your driver to load on Windows 2000, you
must instead call WPP_INIT_TRACING(DeviceObject, RegistryPath) in you
AddDevice() routine. Because you cannot get trace statements from your
driver until this macro is called, it is highly suggested to call it at
the earliest possible time in your driver.
Step #4 – Add call to WPP_CLEANUP() in DriverUnload
Unregister from ETW in you DriverUnload() routine by calling
WPP_CLEANUP(DriverObject). This is the counterpart to what is done in
step 3. See MSDN for documentation. If you require your driver to load
on Windows 2000, you must instead call WPP_CLEANUP(DeviceObject) just
before you call DeleteDevice() on your device object. Because you
cannot get trace statements from your driver after this macro is called,
it is highly recommended to call it at the last possible time.
NOTE: If you fail to de-register, there are NO compile errors - you
will have an outstanding reference on your driver object, and subsequent
loads will fail, causing a reboot required prompt. Be careful here!
Step #5 – Add RUN_WPP statement to your source file.
This is actually the most complex part of the initial conversion
process. For most cases, simply adding the following lines will work:
RUN_WPP=$(SOURCES) -km -func:KdPrintEx((NULL, LEVEL, MSG, …))
Note that the above line uses the double-parenthesis. If your
macro/function doesn’t use double-parenthesis, just use
single-parenthesis above. Note
Now, the most-requested item I have had when describing this conversion
process:
---------------------------
Common compilation errors
---------------------------
errlog.c(86) : error C2065: ‘MyDriverDebugError’ : undeclared identifier
– See step #1 (including TMH file)
obj\i386\errlog.tmh() : error : Please define control model via
WPP_CONTROL_GUIDS or WPP_DEFAULT_CONTROL_GUID macros
obj\i386\errlog.tmh() : error : don’t forget to call WPP_INIT_TRACING
and WPP_CLEANUP in your main, DriverEntry or DllInit
– See step #2 (guid and flag generation)
BUILD: Linking z:\MyDriver directory
1>Linking Executable - obj\i386\MyDriver.sys for i386
1>pnp.obj() : error LNK2019: unresolved external symbol _WppCleanupKm@4
referenced in function _MyDriverUnload@4
1>obj\i386\MyDriver.sys() : error LNK1120: 1 unresolved externals
– See step #3 (WPP_INIT)
1>Compiling - errlog.c for i386
1>errlog.c(33) : error C1083: Cannot open include file: ‘errlog.tmh’: No
such file or directory
– See step #5 (RUN_WPP in sources)
------------
That’s it!
------------
Now load up TraceView (provided in recent DDKs) for the easiest way to
enable/disable/view tracing. Other tools allow for more options and/or
scripting, but TraceView is the best interactive tool I have found out
there.
------------------
Under the covers
------------------
How does ETW do it’s thing? It’s all based on the __annotation()
compiler item coupled with WMI tracing (which is fast but requires
significantly more developer time). Look at the macros and things in
the DDK’s tools\WppConfig\rev1 directory. I can’t claim to understand
it all, but it seems to work fairly well.
The RUN_WPP line causes the WPP preprocessor to run against the files
listed (typically $(SOURCES)). It goes in and changes any line with the
noted -func: into a macro based on the template in use (km-default.tpl
for kernel mode, km-w2k.tpl for win2k compatible kernel mode). As part
of this process, the static strings from each format are stored in the
TMH file as__annotation() marks so they go into the resulting private
symbol file. The remaining arguments are parse by the preprocessor into
WMI tracing events. Each tracing statement is surrounded by an if()
block which checks a globals (or two) added to your driver
automatically. The if() statement gives you the speed when tracing is
not enabled, the logging using WMI traces gives you speed when tracing
is enabled because the string isn’t formatted until it is viewed
(typically by another application/host at lower IRQL). KdPrint() and
similar have the machine running the code also formatting the strings
before displaying them. Insert some additional black magic, smoke, and
mirrors, and you have ETW.
------------
Conclusion
------------
The above text has not been reviewed by any tech writer or other party
at Microsoft, and everything above is my own personal opinion. I hope
it’s useful to you, but it may contain errors which make life harder for
you at times. If so, let me know and I’ll fix it in later postings
(since I’m keeping the above for later use).
Cheers,
.
-----Original Message-----
From: Daniel Luethi [mailto:xxxxx@psi.ch]
Sent: Wednesday, January 28, 2004 12:23 AM
Subject: Re: problems with DMA transfer with size > 4k
Henry,
First thank you for your answer. You’re mentioning Event Tracing for
Windows (ETW) as a usable tool. I’m not sure if this is a standard
windows service? Is it the Event Viewer which can be started in:
My Computer (Right Mouseclick)>Manage>ComputerManagement>System
Tools>Event Viewer> ?
I never used this tool, what is it good for? It seems to trace some more
or less important info, warnings and errors.
regards
Daniel
Henry Gabryjelski wrote:
> It’s great to hear you found the root cause of the problem. Debug
> prints which are formatted on the same system that is running the code
> are always going to affect perf. There are alternatives, however…
>
> Please allow me to suggest you look into the use of Event Tracing for
> Windows (ETW). It offers very quick conversion from any of your
> current macros/functions, and allows you to selectively enable tracing
> on FRE builds without causing major slowdowns when not enabled. I’ve
> used this for all my components since XP, and one or two of the ones
> in Windows 2000. This allows you to get logs from a customer without
> shipping a new binary to them, without using a debugger (although
> that’s an option too), and without the customer being able to decode
> the log (without you giving the magic decoder ring).
>
> ETW is only documented in the DDK currently (I couldn’t find it in
> MSDN, at least).
>
> .
>
> -----Original Message-----
> From: Daniel Luethi [mailto:xxxxx@psi.ch]
> Sent: Wednesday, January 21, 2004 11:46 PM
> Subject: Re: problems with DMA transfer with size > 4k
>
> Russ, Mats and Martin
>
> Thanks for your answers. After a careful look with the PCI snooper (we
> also use VMetro) I noticed where we loose so much time in the
transfer:
> The DbgPrints() commands which I used quite often to watch every step
> in the driver took really lots of time, I think about 10us each (on a
> 2GHz P4!). After changing DbgPrint() to KdPrint(()) the driver was
> free of debug prints if I build it in fre environment. The speed
> increase was
> dramatically: We reached 98MB/s (before 20MB/s)! The snooper showed us
> that the time between two bursts (one burst is actually one page:
> 1024DW, I think that’s the fastest way) decreased from previously
> 100us down to 12us (the PCI bus is 33MHz, 32Bit)!
> So, we’re now really satisfied with that speed, which is pretty close
> to the theoretical speed. Of course the time between two birsts where
> we have to load the PCI bus master card again with the new logical
> address, depends very much on the speed of the PC, but so far it looks
> good and the need of scatter/gather became less urgent!
> Actually the driver is now switched to scatter/gather in
> IoGetDmaAdapter(DevDescr…) kind of a single scatter/gather register.
> This way I can be sure the user buffer is not copied intermediately.
>
> Daniel
></note:>
