Nynaeve

One of the things that was changed around the Windows XP era or so in the driver development world was the introduction of the DbgPrintEx routine. This routine was introduced to combat the problem of debug spew from all sorts of different drivers running together by allowing debug prints to be filtered by a “component id”, which is supposed to be unique per class of driver. By allowing a user to filter which debug prints are being displayed by driver, on the host-side instead of the debugger side, a better debugging experience can be provided when the system is fairly “crowded” as far as debug prints go. This is especially common on checked builds of the operating system.

Additionally, DbgPrintEx provides an additional mechanism to filter output host-side – a severity level. The way the filtering system works is that each component has an associated set of allowed severity levels, such that only a message with a severity level that is “allowed” will actually be transmitted to the debugger when the DbgPrintEx call is made. This allows debug prints to be filtered on a (component, severity) basis, such that especially verbose debug prints can be turned off at runtime without requiring a rebuild or patching the binary on the fly (which might be a problem if the binary in question is the kernel itself and you’re running a 64-bit build). In order to edit the allowed severity of a component at runtime, you typically modify one of the nt!Kd_<component>_Mask global variables in the kernel with the debugger, setting the global corresponding to the desired component to the desired severity mask.

With respect to older drivers, the old DbgPrint call still works, but it is essentially repackaged into a DbgPrintEx call, with hardcoded (default) component and severity values. This means that you’ll still be able to get output from DbgPrint, but (obviously) you can’t take advantage of the extra host-side filtering. Host-side filtering is much preferable to .ofilter-style filtering (which occurs debugger-side), as debug prints that are transferred “over the wire” to the debugger incur a significant performance penalty – the system is essentially suspended while the transfer occurs, and if you have a large amount of debug print spew, this can quickly make the system unusably slow.

Windows Vista takes this whole mechanism one step further and turns off plain DbgPrint calls by default, by setting the default severity level for the DbgPrint-assigned component value such that DbgPrint calls are not transmitted to the debugger. This can be overridden at runtime by modifying Kd_DEFAULT_Mask, but it’s an extra step that must be taken (and one that may be confusing if you don’t know about the default behavior change in Vista, as your debug prints will seemingly just never work).

However, just because DbgPrintEx now provides a way to filter debug prints host-side, that doesn’t mean that you can just go and turn on all your debug prints for release builds by default. Among other things, it’s possible that someone else is using the same component id as your driver (remember, component ids are for classes of devices, such as “network driver”, or “video driver”). Furthermore, DbgPrintEx calls still do incur some overhead, even if they aren’t transmitted to the debugger on the other end (however as long as the debug print is masked off by the allowed severities mask for your component, the overhead is fairly minimal).

Still, the problem of limited component ids remains a significant enough one that you don’t want to turn on debug prints always, or if someone else with the same component id wants to debug their driver, they’ll have all of your debug print spew mixed in with their own.

Also, there is an option to turn on all debug prints, which can sometimes come in handy, and if every driver in the system has debug prints on by default, this often results in a lot of badness. This can be accomplished by specifying a global severity mask via the nt!Kd_WIN2000_Mask global, which is checked before any component specific masks. (If Kd_WIN2000_Mask allows the debug print, it is short-circuited to being allowed without considering component-specific masks. This makes things easier if you want to grab certain severities of debug print messages from many components at the same time, without having to go and manually poke around with severity levels on every component you’re intersted in.)

Unfortunately, this is already a problem on Vista RTM (even free builds) – there are a couple of in-box Microsoft drivers that are guilty of this sort of thing, making Kd_WIN2000_Mask less than useful on Vista. Specifically, cdrom.sys likes to print debug messages like this every second:

Will not retry; Sense/ASC/ASCQ of 02/3a/00

That’s hardly the worst of it, though. Try starting a manifested program on Vista with all debug print severities turned on in Kd_WIN2000_Mask and you’ll get pages of debug spew (no, I’m not kidding – try it with iexplore.exe and you’ll see what I mean). In that respect, shame on the SxS team for setting a bad example with polluting the world with debug prints that are useless to most of us (and to a lesser extent, cdrom.sys also gets a “black lump of coal”, so to speak). Maybe these two components will be fixed for Srv08 RTM or Vista SP1 RTM, if we’re lucky.

So, take this opportunity to check and make sure that none of your drivers ship with DbgPrints turned on by default – even if you do happen to use DbgPrintEx. Somebody who has to debug a problem on a computer with your driver is installed will be all the more happier as a result.

This entry was posted on Saturday, July 21st, 2007 at 7:00 am and is filed under Debugging, Windows. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.