Any reasons to not use WPP?

NTDEV
1

I am about to migrate some drivers from KdPrint to WPP tracing, and the results from my testing seem very promising. However, scanning through the OSR blog/forum, I have seen some negatives posts, such as:

WPP is and always has been a ridiculously complicated and fragile logging system

we still do want to keep a critical eye towards it because we were burdened by
using WPP Tracing before

Why? What are (were?) the problems with WPP?
Is it (still) true that OSR is using its own tracing package?

I already dug through the implementation of WPP, and I am aware of its overhead (which is not a problem for us). I also noticed that certain macros cannot be used with WPP.

Anything else?

2

Actually WPP may have less overhead that KdPrint: it is backed by the very optimized ETW trace buffering, and formatting is delayed to the consumer/viewer. It does not disable interrupts, and does not allocate sprintf buffer on stack.

Its main overhead occurs at design & writing time: you need to plan the trace macros, types, make sure that WPP stuff is correctly set up in the project (otherwise it won’t produce tmh files and the code just won’t compile).

OTOH, KdPrint is simple. You drop it in and it just works, always, with no additional instrumentation. This is great for ad-hoc debugging. Tracing is great for support. You invest into supportability, with luck, it may pay off.

WPP and KdPrint have a small common subset of capabilities: plain sprintf() formats and some filtering. Some people (me too) hacked up “hybrid” debug print wrappers that can work either via KdPrint or ETW/WPP or even both at once. Of course, some of WPP advantages are lost then.
But - as someone wrote here - simple beats complicated every day.

– pa

3

>Is it (still) true that OSR is using its own tracing package?

Yes, no, maybe.

The biggest problems with WPP tracing are historical. Over the years, compatibility among versions of tracing in kernel mode drivers has been “problematic” – and that’s putting the nicest possible spin on the topic. The tools and documentation (and the actual macros used for implementation) have also historically, ah, “sucked” would be a good term.

In recent years this has gotten better.

At OSR, we typically use DbgPrint for developing and debugging our projects. It’s up to the dev whether we actually code “DbgPrint” (in the appropriate conditional) in-line in the driver code or embed the DbgPrint statement in a macro with fancy categories and levels. But, no matter what, we always start with just good old DbgPrint. It’s fast, it’s easy, it’s predictable and you get to just sit in your debugger on your dev box and watch the spew arrive. Sort of like OutputDebugString for an app.

Of course, DbgPrint has issues as well. For one thing, it does no good at all for tracing issues that occur in the field. So, when we implement a project that is likely to benefit from in-field tracing to aid support, our typical approach is to convert the DbgPrint statements (or macros that invoke DbgPrint) to use WPP tracing before release.

The other issue with DbgPrint vs WPP Tracing is timing. DbgPrint output is something like synchronous (it’s not REALLY synchronous, the data goes to a circular buffer, but it *definitely* slows down code paths). I recently (like last week) was dealing with a driver for real-time control of an instrument that could repro a problem *very* quickly without DbgPrint enabled, but could *never* repro the problem with DbgPrint in use. To solve this, I simply converted the DbgPrint statements to WPP trace statements, ran TraceView on the target machine, and bingo! Repro in about one minute. When I get a minute, I’m going to write a blog post about how to quickly convert DbgPrint statements to WPP tracing.

In terms of the historical problems with WPP Tracing, compatibility seems to be good in Windows 7 and later. The docs and tools still pretty much suck, and there’s way too much “magic” involved… even with the nice, IDE integrated, build environment (which introduces its own “magic”).

So, there are trade-offs.

Here at OSR, we started off as being VERY bullish on WPP tracing. We were the first ones to introduce it to the third party development community, we were the first to document it, and we’re the guys who wrote TraceView (don’t hate on us for that, OK… it’s not like we’re proud and it’s not like we’re app developers).

When we spent lots of quality time with WPP tracing, we learned to not only dislike it but to loathe it. We regretted ever introducing it to the community. We apologized. We stopped using it, and were quite loud about telling other people our opinions of it.

This all took place 10 years ago. Times change, really old OS versions are no longer necessarily part of the mix, and our opinion has to be revised.

Now we don’t hate WPP tracing anymore. Yes, we still think it’s got too much mystical monkey magic. Yes, we still think it’s cumbersome to implement. Yes, we still think the tools and the docs suck.

But it does work. And it appears to be reliable… at least on Win7 and later. And we DO use it when called for. But we do NOT view it as a substitute for DbgPrint for the driver development phase.

Peter
OSR
@OSRDrivers

4

Until recently there was really no reasonable support for always on tracing
with WPP - so if you needed tracing to resolve field issues that required
begging customer to repeat failures, which is pretty much an awful thing to
do. I stuck to an internal trace ring-buffer that was always enabled for
just this reason. Still fond of that approach but moving forward wpp’s
support for IFR seems reasonable now.

Mark Roddy

On Tue, Feb 23, 2016 at 9:15 AM, wrote:

> >Is it (still) true that OSR is using its own tracing package?
>
> Yes, no, maybe.
>
> The biggest problems with WPP tracing are historical. Over the years,
> compatibility among versions of tracing in kernel mode drivers has been
> “problematic” – and that’s putting the nicest possible spin on the topic.
> The tools and documentation (and the actual macros used for implementation)
> have also historically, ah, “sucked” would be a good term.
>
> In recent years this has gotten better.
>
> At OSR, we typically use DbgPrint for developing and debugging our
> projects. It’s up to the dev whether we actually code “DbgPrint” (in the
> appropriate conditional) in-line in the driver code or embed the DbgPrint
> statement in a macro with fancy categories and levels. But, no matter
> what, we always start with just good old DbgPrint. It’s fast, it’s easy,
> it’s predictable and you get to just sit in your debugger on your dev box
> and watch the spew arrive. Sort of like OutputDebugString for an app.
>
> Of course, DbgPrint has issues as well. For one thing, it does no good at
> all for tracing issues that occur in the field. So, when we implement a
> project that is likely to benefit from in-field tracing to aid support, our
> typical approach is to convert the DbgPrint statements (or macros that
> invoke DbgPrint) to use WPP tracing before release.
>
> The other issue with DbgPrint vs WPP Tracing is timing. DbgPrint output
> is something like synchronous (it’s not REALLY synchronous, the data goes
> to a circular buffer, but it definitely slows down code paths). I
> recently (like last week) was dealing with a driver for real-time control
> of an instrument that could repro a problem very quickly without DbgPrint
> enabled, but could never repro the problem with DbgPrint in use. To
> solve this, I simply converted the DbgPrint statements to WPP trace
> statements, ran TraceView on the target machine, and bingo! Repro in about
> one minute. When I get a minute, I’m going to write a blog post about how
> to quickly convert DbgPrint statements to WPP tracing.
>
> In terms of the historical problems with WPP Tracing, compatibility seems
> to be good in Windows 7 and later. The docs and tools still pretty much
> suck, and there’s way too much “magic” involved… even with the nice, IDE
> integrated, build environment (which introduces its own “magic”).
>
> So, there are trade-offs.
>
> Here at OSR, we started off as being VERY bullish on WPP tracing. We were
> the first ones to introduce it to the third party development community, we
> were the first to document it, and we’re the guys who wrote TraceView
> (don’t hate on us for that, OK… it’s not like we’re proud and it’s not
> like we’re app developers).
>
> When we spent lots of quality time with WPP tracing, we learned to not
> only dislike it but to loathe it. We regretted ever introducing it to the
> community. We apologized. We stopped using it, and were quite loud about
> telling other people our opinions of it.
>
> This all took place 10 years ago. Times change, really old OS versions
> are no longer necessarily part of the mix, and our opinion has to be
> revised.
>
> Now we don’t hate WPP tracing anymore. Yes, we still think it’s got too
> much mystical monkey magic. Yes, we still think it’s cumbersome to
> implement. Yes, we still think the tools and the docs suck.
>
> But it does work. And it appears to be reliable… at least on Win7 and
> later. And we DO use it when called for. But we do NOT view it as a
> substitute for DbgPrint for the driver development phase.
>
> Peter
> OSR
> @OSRDrivers
>
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list online at: <
> http://www.osronline.com/showlists.cfm?list=ntdev&gt;
>
> MONTHLY seminars on crash dump analysis, WDF, Windows internals and
> software drivers!
> Details at http:
>
> To unsubscribe, visit the List Server section of OSR Online at <
> http://www.osronline.com/page.cfm?name=ListServer&gt;
></http:>

5

Thank you all for your responses. I now feel comfortable adding WPP to my drivers without screwing anything up.

6

> there was really no reasonable support for always on tracing

with WPP

I am wondering what you mean by ‘always on’. Do you mean to be able to view the trace after the driver crashes? I believe your only option is to repro the bug with full memory dumps turned on, use non-paged trace buffers and then extract the trace using !wmitrace.

To collect traces that log errors during normal operation, I modified the installer to turn on tracing permanently (ring buffer, verbose logging turned off), so I expect our customers to simply send the etl file.

That said, do you have any experience with IFR? I see it links to WppRecorder.sys, so is it worth shipping a separate Windows 10 driver? The MSDN page highlights the ability to get a trace after a crash, but I can do that already with !wmitrace?

Will we be able to collect the IFR traces via WER?

7

xxxxx@osr.com wrote:

The other issue with DbgPrint vs WPP Tracing is timing. DbgPrint output is something like synchronous (it’s not REALLY synchronous, the data goes to a circular buffer, but it *definitely* slows down code paths). I recently (like last week) was dealing with a driver for real-time control of an instrument that could repro a problem *very* quickly without DbgPrint enabled, but could *never* repro the problem with DbgPrint in use. To solve this, I simply converted the DbgPrint statements to WPP trace statements, ran TraceView on the target machine, and bingo! Repro in about one minute. When I get a minute, I’m going to write a blog post about how to quickly convert DbgPrint statements to WPP tracing.

In terms of the historical problems with WPP Tracing, compatibility seems to be good in Windows 7 and later. The docs and tools still pretty much suck, and there’s way too much “magic” involved… even with the nice, IDE integrated, build environment (which introduces its own “magic”).

I’d like to +1 this point. I have certainly been able to get WPP
tracing to work. In fact, most of the drivers I write are compile-time
switchable – change one setting, and I switch between DbgPrintEx and
WPP. However, I almost always leave it at the DbgPrintEx setting,
because I don’t ever remember the recipe for looking at the WPP traces.
I end up fumbling for GUIDs and trying to scrape up the batch files and
magic spells that made it work before.

If someone has this down to a routine, I’d love to see a “from the
trenches” article showing the key points to make WPP tracing painless.
And I don’t mean setting up the .macros, I mean getting access to the
traces during debugging.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

8

On Tue, Feb 23, 2016 at 09:15:47AM -0500, xxxxx@osr.com wrote:

>Is it (still) true that OSR is using its own tracing package?

Yes, no, maybe.

The biggest problems with WPP tracing are historical. Over the years, compatibility among versions of tracing in kernel mode drivers has been “problematic” – and that’s putting the nicest possible spin on the topic. The tools and documentation (and the actual macros used for implementation) have also historically, ah, “sucked” would be a good term.

In recent years this has gotten better.

… snip …

The other issue with DbgPrint vs WPP Tracing is timing. DbgPrint output is something like synchronous (it’s not REALLY synchronous, the data goes to a circular buffer, but it *definitely* slows down code paths). I recently (like last week) was dealing with a driver for real-time control of an instrument that could repro a problem *very* quickly without DbgPrint enabled, but could *never* repro the problem with DbgPrint in use. To solve this, I simply converted the DbgPrint statements to WPP trace statements, ran TraceView on the target machine, and bingo! Repro in about one minute. When I get a minute, I’m going to write a blog post about how to quickly convert DbgPrint statements to WPP tracing.

^^ such a blog post would be awesome Peter.

-ml

9

> I don’t ever remember the recipe for looking at the WPP traces

I can share a few things I learned in the last two weeks:

As far as tools are concerned, I have settled on TraceView Plus. I tried Message Analyser, but could not make it work for realtime-tracing - for ETL files is works well. The SDK TraceView seems outdated. I neither use the command-line tools, nor the WinDbg trace extensions, which seem not really useful if you have more than a handful of messages.

!wmitrace is really cool though, as it allows you to extract traces from a memory dump, in case the traces have not been flushed to the disk. There is a great post here:
http://devproconnections.com/development/wpp-tracing-wmitrace-and-debugger

The tricky part is to locate the correct PDB file, which holds the WPP format information - an incorrect PDB results in a bunch of GUIDs displayed. For local tracing this is not really a problem, as the driver always matches the PDB. For analyzing ETL log files from a different computer, it’s a different story. Windows 10 works automatically, since the path to the PDB is stored in the driver/executable and then stored in the ETL file. So you want to ensure that each release build has a unique path. We include the build number in the path. If you set up a symbol server (which we already had in place), the proper PDB will be fetched automatically, which is really nice. I would definitely recommend doing this if you work in a team, as this is great for WinDbg, too. Unfortunately, most of our customers run Windows 7, so if you record an ETL file, the PDB will not be found automatically. It is probably a good idea to put the build number into the first trace statement as plain text, so that you know which PDB you need to drop on the trace. I am trying to automate this with a little script - I will post my solution once I find one.

10

> such a blog post would be awesome Peter.

Thanks for the encouragement, Mr. Larkin. I’ll make it happen. It’s so simple, it’s embarrassing.

Mr. Robert A made a couple of comments:

I have settled on TraceView Plus

What are the advantages of TraceView Plus over good old TraceView? I looked at the TraceView Plus web site the other day and found it uniquely uninformative. For US$120, I didn’t think I should need to guess.

The tricky part is to locate the correct PDB file

This is always the problem in debugging, right? Too bad there isn’t the same sort of integrated ability to handle PDBs from a symbol server (you can set up your own local one, of course) the way WinDbg does.

If you DO have a local symbol server set up, you *can* use the symchk utility to grab the right PDB from it… then feed that PDB into TraceView (or TraceViewPlus or whatever). It’s not fully automated, but it’s probably better than scratching your head and asking yourself “is THIS the right PDB, or is THAT the right PDB??”

Peter
OSR
@OSRDrivers

11

> What are the advantages of TraceView Plus
To be honest, I have not spent much time with TraceView, since I had TraceView Plus already on my PC.

Seems like they revamped their website, and now the manual is gone. Bummer!

you *can* use the symchk utility to grab the right PDB from it
I believe we are talking about different things. You mean finding the correct PDB for an executable. If you do have the driver, you don’t need symchk at all, as you can just simply drop the driver on TraceView Plus and it will find the PDB for you.

I was talking about being able to open *and format* an ETL file with a simple double click. Assume you have different drivers with different versions, things will get hairy. So I am thinking I somehow need to include a build string in the ETL file and use that to locate the matching PDB file. Since this does work beautifully on Win10, I was disappointed to see that a trace taken on Win7 requires some manual effort. Perhaps I am just a bit lazy…

Rob

12

My blog post on quick-and-dirty steps to turn your DbgPrints in WPP Tracing statements:

http:</http:>

Ah… IOW, “Given an ETL file, find the right PDB.”

Yes. Very annoying.

Peter
OSR
@OSRDrivers