New line in WPP trace

NTDEV
21

The claim that WMI and WPP are incompatible is not true. There was some
problems in the past, but most of these have been fixed. As far as your
other claims, I have never encountered blocks missing. The only out of
order I have ever seen is the standard multi-threaded problems almost any
tracing has, where the ordering of two blocks can be switched.

–
Don Burn (MVP, Windows DDK)
Windows 2k/XP/2k3 Filesystem and Driver Consulting
http://www.windrvr.com
Remove StopSpam from the email to reply

wrote in message news:xxxxx@ntdev…
>I am someone who would quite like to exploit WPP in some of my drivers.
> Unfortunately I like to use WMI for other purposes. The WPP preprocessor
> assumes it is the sole user of WMI. So implementing WPP in my drivers is
> an
> awful lot of work, which I have not got around to doing yet. There is a
> useful
> OSR article which would help with this.
>
> So I am not a fan of WMI yet.
>
> In a driver a long time ago I used WPP to do some heavyweight tracing.
> From
> this I learned that lightweight WMI tracing (which WPP is) has a couple
> of
> problems to look out for.
> 1. Blocks can arrive out of order.
> 2. Blocks can go missing.
> The fault was partly with my user mode reading app (it sorted, obviously
> but I
> never managed to get all the blocks).
>
>

22

Quoting Don Burn :

> The claim that WMI and WPP are incompatible is not true. There was some
> problems in the past, but most of these have been fixed. As far as your
> other claims, I have never encountered blocks missing. The only out of
> order I have ever seen is the standard multi-threaded problems almost any
> tracing has, where the ordering of two blocks can be switched.
>

You are right I just added WPP to the driver I am currently working on it was
straight forward. In the past I did have some issue using a much older DDK.

As for the missing block problem. I said it could have been a problem with my
reading application. It was the first time I ever used event tracing and WMI
so it is entirely possible I did something stupid.

23

To clarify, the only time WPP gets in the path of WMI is on win2k where WPP registration occcured via IRPs. The WPP headers originally provided some dispatching code that didn’t account for every scenario, this has since been fixed. On XP and later, WPP registration is a direct call interface that does not perturb the driver’s WMI IRP processing path.

d

24

Yossi Leybovich wrote:

I can collect my traces by traceview or by dbgview with few simple
scripts and I don’t think it is nuisance.

Look, this argument over DbgPrint vs WPP is silly. It comes down to
personal preference. Don believes in WPP and finds it very useful.
That’s his right. Maxim believes in DbgPrint and finds WPP
unnecessarily complicated. That’s his right.

On my first KMDF project, I tried to embrace WPP, but I found myself
being more annoyed then delighted, and replaced them all with KdPrint.
I now regret that, and on the next project I’ll try harder for WPP.
That’s also MY right.

You’ll never convince someone to change, any more than you can convince
someone to change text editors. If you don’t realize that gvim is the
greatest editor in the world, then there’s clearly something wrong with
you. :wink:

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

25

Wow, it is not so often a simple new line can cause such excitement.

It wasn’t what we intended in the beginning, as we originally saw trace
events more as trace records to be sorted and easily intermixed from
different sources, I won’t give the big explanation but suffice to say
we already broke our own rules with some of the options like doing
hexdumps, and that was done by user request. I personally still try to
keep things ‘packaged’ on a single line as it does make the traces
easier to manipulate for me.

Anyway there is a way around the newline restriction that might act as a
workaround for folks who really want to have newlines and as far as I
know it works whether you are using WPP or not so it should be fine if
you swap between tracing/debug techniques for different builds. It
certainly works fine in printf statements.

DoTraceMessage(Noise, “Hello, \015\012 %s %d\n”, “World” , i);

Will give

[0]1668.19B4::02/15/2007-09:29:41.373 [docexample]Hello,
World 99

For those that do not remember \015\012 is CRLF in octal.

Anyway I am sure that is not a perfect solution for all, but it works
today and may be of use to some of you. I think it addresses the needs
of the original poster at the cost of a minor inconvenience.

As I said this is a workaround.

26

Hi All, I really appreciate all this feedback…

Any way I was made aware by Ian Service that there is a way to get the
new line into the format string all you have to do is include \015 and
that will create a new line

DoTraceMessage(ERROR, “this is error 1 %d \015 this is error2 %d”,
data, data2 );

Thanks

Jose Sua

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Yossi Leybovich
Sent: Wednesday, February 14, 2007 11:34 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

Hi

From my experience with WPP it is very helpful and powerful tool.
I use it not just for tracing but also to debug my code.
We wrote whole bunch of networking drivers that ran in 10Gbs and in
order to debug races and scenarios that happen when there is
traffic load I found it very helpful to use WPP (and I think it’s the
only way I can see output without loosing performance).

I can collect my traces by traceview or by dbgview with few simple
scripts and I don’t think it is nuisance.
It also enable us to debug problems on the client site without switching
any drivers.
(just send him script that collect the traces and let him ran his test)

I don’t think that event log is the right tool for tracing or debugging
specially not when you debug networking events in 10Gbs.

We use the same macros for chk version (that use DbgPrint ) and for fre
version that use WPP.
So we encounter few cases that WPP act differently from the regular
dbgprint

  1. is the removing of \n from the string format 0 I think MS should fix
    that (and that was the reason for that mail thread).
  2. us the WPP from with in macros
    for example:
    in the dbg print I have 2 macros
    DBG_PRINT(msg) —> print the msg
    DBG_EXIT() —> to trace exit from
    function (print “<=====”)
    II also create macro that print msg and exit function
    DBG_PRINT_EXIT(msg) ----> print the msg and that
    in new line print “<=====”
    I did not find any way to port this macro to WPP.
    Maybe there should be a way to ran preprocessor before the WPP
    preprocessor so one can use WPP from within macros.

Thanks
Yossi

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Maxim
S. Shatskih
Sent: Thursday, February 15, 2007 12:11 AM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] New line in WPP trace

> That’s silly. How does removing the newlines help with grepping in
> any way? Indeed, it now means that my output does not
match my input,
> so I cannot simply search for the exact string that I presented.

>From all these discussion on WPP on the forum I can conclude
the following:

  • WPP is a major nuisance which requires, after all, to pass
    your sources through some preprocessor before build.
    Installation nuisances also follow.
  • WPP reduces the developer productivity a lot and is a major
    issue generator.
  • so, for me, the solution of 2-screen code which calls
    IoAllocateErrorLogEntry/IoWriteErrorLogEntry is MUCH better.
  • the logging level can be adjusted by the DWORD bitmask in
    the registry.

Looks like such solution is by far better then WPP, which is
one another useless MS’s technology.

My opinion on MS is good, but they sometimes produce useless monsters.

–
Maxim Shatskih, Windows DDK MVP
StorageCraft Corporation
xxxxx@storagecraft.com
http://www.storagecraft.com

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

To unsubscribe, visit the List Server section of OSR Online
at http://www.osronline.com/page.cfm?name=ListServer

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

27

One of the advantages of TraceMessage vs DbgPrint which often times gets overlooked is perfomrnace. Unlike DbgPrint TraceMessage is not serialized, so if you are tracing to debug race conditions in your code you are a lot more likely to find them with WPP. Not to mention that doing “printf” expension is quite costly, and WPP delays it until post processing.
Alex

Date: Thu, 15 Feb 2007 09:36:43 -0800> From: xxxxx@probo.com> To: xxxxx@lists.osr.com> Subject: Re: [ntdev] New line in WPP trace> > Yossi Leybovich wrote:> > I can collect my traces by traceview or by dbgview with few simple> > scripts and I don’t think it is nuisance.> > > > Look, this argument over DbgPrint vs WPP is silly. It comes down to> personal preference. Don believes in WPP and finds it very useful. > That’s his right. Maxim believes in DbgPrint and finds WPP> unnecessarily complicated. That’s his right.> > On my first KMDF project, I tried to embrace WPP, but I found myself> being more annoyed then delighted, and replaced them all with KdPrint. > I now regret that, and on the next project I’ll try harder for WPP. > That’s also MY right.> > You’ll never convince someone to change, any more than you can convince> someone to change text editors. If you don’t realize that gvim is the> greatest editor in the world, then there’s clearly something wrong with> you. ;)> > – > Tim Roberts, xxxxx@probo.com> Providenza & Boekelheide, Inc.> > > —> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256\> > To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Get the new Windows Live Messenger!
http://get.live.com/messenger/overview

28

Ian Service wrote:

Anyway there is a way around the newline restriction that might act as a
workaround for folks who really want to have newlines and as far as I
know it works whether you are using WPP or not so it should be fine if
you swap between tracing/debug techniques for different builds. It
certainly works fine in printf statements.

DoTraceMessage(Noise, “Hello, \015\012 %s %d\n”, “World” , i);

Will give

[0]1668.19B4::02/15/2007-09:29:41.373 [docexample]Hello,
World 99

For those that do not remember \015\012 is CRLF in octal.

Remember that the escape codes are just conveniences for source code.
In the object code, there is absolutely no difference between \012,
\x0A, and \n. They all compile to a single byte with the hex value 0x0A.

If \015 works in this context, then so will \r (they are the same), but
I’d be surprised if WPP allowed \r but not \n.

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

29

> ----------

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, February 15, 2007 8:34 AM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

We wrote whole bunch of networking drivers that ran in 10Gbs and in
order to debug races and scenarios that happen when there is
traffic load I found it very helpful to use WPP (and I think it’s the
only way I can see output without loosing performance).

That’s the only reason why I still didn’t rejected the idea of using WPP completely. But is there a real difference? When traces are turned on, is there a difference between traditional approach when traces are printed via DbgPrint() and captured by DebugView and WPP captured some other way? In both cases there is an overhead which probably differs. Does anybody have some numbers?

Did you see any differences between both approaches when debugging races? This is the only area where my traces sometimes cause that problem can’t be reproduced (but in other cases problem can be reproduced only with traces :slight_smile:

I don’t think that event log is the right tool for tracing or debugging
specially not when you debug networking events in 10Gbs.

Sure, event log has quite different purpose.

Maybe there should be a way to ran preprocessor before the WPP
preprocessor so one can use WPP from within macros.

This is one of things which discourages me. Everything would be much easier if one can use standard preprocessor macros and just call a function which’d make trace. I also use special macros for function enter and leave. In addition to ==> and <== they indent/outdent output and compute time elapsed in the function/block. The whole idea with special preprocessor for traces is IMO flawed and shows too much power is harmful, sometimes.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

30

Michal,

I have seen as little as 5-10% overall degradation with tracing
turned on, with a heck of a lot more with DbgPrint. Since WPP saves the
binary values their is no conversion cost at the time of the trace.

–
Don Burn (MVP, Windows DDK)
Windows 2k/XP/2k3 Filesystem and Driver Consulting
http://www.windrvr.com
Remove StopSpam from the email to reply

“Michal Vodicka” wrote in message
news:xxxxx@ntdev…
> ----------
> From:
> xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com]
> on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, February 15, 2007 8:34 AM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] New line in WPP trace
>
> We wrote whole bunch of networking drivers that ran in 10Gbs and in
> order to debug races and scenarios that happen when there is
> traffic load I found it very helpful to use WPP (and I think it’s the
> only way I can see output without loosing performance).
>
That’s the only reason why I still didn’t rejected the idea of using WPP
completely. But is there a real difference? When traces are turned on, is
there a difference between traditional approach when traces are printed via
DbgPrint() and captured by DebugView and WPP captured some other way? In
both cases there is an overhead which probably differs. Does anybody have
some numbers?

Did you see any differences between both approaches when debugging races?
This is the only area where my traces sometimes cause that problem can’t
be reproduced (but in other cases problem can be reproduced only with
traces :slight_smile:

> I don’t think that event log is the right tool for tracing or debugging
> specially not when you debug networking events in 10Gbs.
>
Sure, event log has quite different purpose.

> Maybe there should be a way to ran preprocessor before the WPP
> preprocessor so one can use WPP from within macros.
>
This is one of things which discourages me. Everything would be much easier
if one can use standard preprocessor macros and just call a function
which’d make trace. I also use special macros for function enter and leave.
In addition to ==> and <== they indent/outdent output and compute time
elapsed in the function/block. The whole idea with special preprocessor for
traces is IMO flawed and shows too much power is harmful, sometimes.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

31

Yep sort of, it happens that \r does work with WPP, \015 by itself works
fine for WPP too.

However neither \015 or \r are suitable as a replacement for \n in a
printf statement, which is why I suggested \015\012 (\r of course is
suitable for other uses). WPP actually just disregards the \012 but the
\015 has the right effect. Leaving the \012 has no effect on WPP but
makes sure that if you use that statement in a printf form it works
correctly.

You can do \r\012 or \015\n or \r\n if you like but these look a little
odd to me (maybe \r\n looks ok?), using the numbers seemed to me to
convey better what was happening.

I tested them all, and remember what I said, this is a workaround to
help out.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Tim Roberts
Sent: Thursday, February 15, 2007 12:21 PM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] New line in WPP trace

Ian Service wrote:

Anyway there is a way around the newline restriction that might act as
a
workaround for folks who really want to have newlines and as far as I
know it works whether you are using WPP or not so it should be fine if
you swap between tracing/debug techniques for different builds. It
certainly works fine in printf statements.

DoTraceMessage(Noise, “Hello, \015\012 %s %d\n”, “World” , i);

Will give

[0]1668.19B4::02/15/2007-09:29:41.373 [docexample]Hello,
World 99

For those that do not remember \015\012 is CRLF in octal.

Remember that the escape codes are just conveniences for source code.
In the object code, there is absolutely no difference between \012,
\x0A, and \n. They all compile to a single byte with the hex value
0x0A.

If \015 works in this context, then so will \r (they are the same), but
I’d be surprised if WPP allowed \r but not \n.

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

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

32

DebugPrint from KernelMode even when consumed locally (via DebugView) can still be quite expensive. (QueryDebugFilterState, sprintf, raise IRQL, do callback, callback does some more work, etc…). TraceMessage is quite simpler and is non-blocking and non-spinning. I don’t have numbers for DebugPrint, but TraceMessage was under 2k cycles when I measured it.
Alex> Subject: RE: [ntdev] New line in WPP trace> Date: Thu, 15 Feb 2007 21:41:06 +0100> From: xxxxx@upek.com> To: xxxxx@lists.osr.com> > > ----------> > From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]> > Reply To: Windows System Software Devs Interest List> > Sent: Thursday, February 15, 2007 8:34 AM> > To: Windows System Software Devs Interest List> > Subject: RE: [ntdev] New line in WPP trace> > > > We wrote whole bunch of networking drivers that ran in 10Gbs and in> > order to debug races and scenarios that happen when there is > > traffic load I found it very helpful to use WPP (and I think it’s the> > only way I can see output without loosing performance).> > > That’s the only reason why I still didn’t rejected the idea of using WPP completely. But is there a real difference? When traces are turned on, is there a difference between traditional approach when traces are printed via DbgPrint() and captured by DebugView and WPP captured some other way? In both cases there is an overhead which probably differs. Does anybody have some numbers?> > Did you see any differences between both approaches when debugging races? This is the only area where my traces sometimes cause that problem can’t be reproduced (but in other cases problem can be reproduced only with traces :)> > > I don’t think that event log is the right tool for tracing or debugging> > specially not when you debug networking events in 10Gbs.> > > Sure, event log has quite different purpose.> > > Maybe there should be a way to ran preprocessor before the WPP> > preprocessor so one can use WPP from within macros.> > > This is one of things which discourages me. Everything would be much easier if one can use standard preprocessor macros and just call a function which’d make trace. I also use special macros for function enter and leave. In addition to ==> and <== they indent/outdent output and compute time elapsed in the function/block. The whole idea with special preprocessor for traces is IMO flawed and shows too much power is harmful, sometimes.> > Best regards,> > Michal Vodicka> UPEK, Inc.> [xxxxx@upek.com, http://www.upek.com]> > > > > > —> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256\> > To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Get the new Windows Live Messenger!
http://get.live.com/messenger/overview

33

I made a quick test and measured DbgPrint captured by DebugView. Call with no formatting parameters took less than 9500 cycles and call with 3 parameters took less than 15000 cycles. Not a big difference against WPP if you compute real time spent at modern CPU.

Above are best cases measured by dreaded KeQueryPerformanceCounter(); the worst cases were up to 100% more.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Alex Bendetov[SMTP:xxxxx@hotmail.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, February 15, 2007 10:56 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

DebugPrint from KernelMode even when consumed locally (via DebugView) can still be quite expensive. (QueryDebugFilterState, sprintf, raise IRQL, do callback, callback does some more work, etc…). TraceMessage is quite simpler and is non-blocking and non-spinning. I don’t have numbers for DebugPrint, but TraceMessage was under 2k cycles when I measured it.
Alex

> Subject: RE: [ntdev] New line in WPP trace
> Date: Thu, 15 Feb 2007 21:41:06 +0100
> From: xxxxx@upek.com
> To: xxxxx@lists.osr.com
>
> > ----------
> > From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, February 15, 2007 8:34 AM
> > To: Windows System Software Devs Interest List
> > Subject: RE: [ntdev] New line in WPP trace
> >
> > We wrote whole bunch of networking drivers that ran in 10Gbs and in
> > order to debug races and scenarios that happen when there is
> > traffic load I found it very helpful to use WPP (and I think it’s the
> > only way I can see output without loosing performance).
> >
> That’s the only reason why I still didn’t rejected the idea of using WPP completely. But is there a real difference? When traces are turned on, is there a difference between traditional approach when traces are printed via DbgPrint() and captured by DebugView and WPP captured some other way? In both cases there is an overhead which probably differs. Does anybody have some numbers?
>
> Did you see any differences between both approaches when debugging races? This is the only area where my traces sometimes cause that problem can’t be reproduced (but in other cases problem can be reproduced only with traces :slight_smile:
>
> > I don’t think that event log is the right tool for tracing or debugging
> > specially not when you debug networking events in 10Gbs.
> >
> Sure, event log has quite different purpose.
>
> > Maybe there should be a way to ran preprocessor before the WPP
> > preprocessor so one can use WPP from within macros.
> >
> This is one of things which discourages me. Everything would be much easier if one can use standard preprocessor macros and just call a function which’d make trace. I also use special macros for function enter and leave. In addition to ==> and <== they indent/outdent output and compute time elapsed in the function/block. The whole idea with special preprocessor for traces is IMO flawed and shows too much power is harmful, sometimes.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
>
>
>
>
> —
> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Live Search: New search found Try it! http:
> —
> Questions? First check the Kernel Driver FAQ at > http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
></http:>

34

Now try your measurements with multiple threads all pounding DbgPrint at
the same time so that there is contention on the DbgPrint lock :wink:

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, February 15, 2007 4:02 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

I made a quick test and measured DbgPrint captured by DebugView. Call
with no formatting parameters took less than 9500 cycles and call with 3
parameters took less than 15000 cycles. Not a big difference against WPP
if you compute real time spent at modern CPU.

Above are best cases measured by dreaded KeQueryPerformanceCounter();
the worst cases were up to 100% more.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Alex Bendetov[SMTP:xxxxx@hotmail.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, February 15, 2007 10:56 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

DebugPrint from KernelMode even when consumed locally (via DebugView)
can still be quite expensive. (QueryDebugFilterState, sprintf, raise
IRQL, do callback, callback does some more work, etc…). TraceMessage
is quite simpler and is non-blocking and non-spinning. I don’t have
numbers for DebugPrint, but TraceMessage was under 2k cycles when I
measured it.
Alex

> Subject: RE: [ntdev] New line in WPP trace
> Date: Thu, 15 Feb 2007 21:41:06 +0100
> From: xxxxx@upek.com
> To: xxxxx@lists.osr.com
>
> > ----------
> > From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, February 15, 2007 8:34 AM
> > To: Windows System Software Devs Interest List
> > Subject: RE: [ntdev] New line in WPP trace
> >
> > We wrote whole bunch of networking drivers that ran in 10Gbs and
in
> > order to debug races and scenarios that happen when there is
> > traffic load I found it very helpful to use WPP (and I think it’s
the
> > only way I can see output without loosing performance).
> >
> That’s the only reason why I still didn’t rejected the idea of using
WPP completely. But is there a real difference? When traces are turned
on, is there a difference between traditional approach when traces are
printed via DbgPrint() and captured by DebugView and WPP captured some
other way? In both cases there is an overhead which probably differs.
Does anybody have some numbers?
>
> Did you see any differences between both approaches when debugging
races? This is the only area where my traces sometimes cause that
problem can’t be reproduced (but in other cases problem can be
reproduced only with traces :slight_smile:
>
> > I don’t think that event log is the right tool for tracing or
debugging
> > specially not when you debug networking events in 10Gbs.
> >
> Sure, event log has quite different purpose.
>
> > Maybe there should be a way to ran preprocessor before the WPP
> > preprocessor so one can use WPP from within macros.
> >
> This is one of things which discourages me. Everything would be much
easier if one can use standard preprocessor macros and just call a
function which’d make trace. I also use special macros for function
enter and leave. In addition to ==> and <== they indent/outdent output
and compute time elapsed in the function/block. The whole idea with
special preprocessor for traces is IMO flawed and shows too much power
is harmful, sometimes.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
>
>
>
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Live Search: New search found Try it!
http:
> —
> Questions? First check the Kernel Driver FAQ at >
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>

—
Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer</http:>

35

Lock? Hey, I have an idea. DebugView hooks DbgPrint so maybe lock can be avoided. I turned off passthrough option so kernel print code won’t be called. And guess what. Now there are 2000 cycles for print without parameters and 4000 for 3 parameters. With minimal fluctuation now.

I guess previous 100% fluctuation was just because of the lock. No need to measure, just compute. In the worst case one CPU will wait for all other CPUs. So it’d take N * normal time. I tested it at dual CPU machine and the results meat this expenctation.

Conslusion: DebugView with passthrough turned off improves things so they’re comparable with WPP. Not a big surprise for me; I examined WPP code which has to deal with GUIDs and isn’t short.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Doron Holan[SMTP:xxxxx@microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Friday, February 16, 2007 1:20 AM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

Now try your measurements with multiple threads all pounding DbgPrint at
the same time so that there is contention on the DbgPrint lock :wink:

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, February 15, 2007 4:02 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

I made a quick test and measured DbgPrint captured by DebugView. Call
with no formatting parameters took less than 9500 cycles and call with 3
parameters took less than 15000 cycles. Not a big difference against WPP
if you compute real time spent at modern CPU.

Above are best cases measured by dreaded KeQueryPerformanceCounter();
the worst cases were up to 100% more.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Alex Bendetov[SMTP:xxxxx@hotmail.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, February 15, 2007 10:56 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] New line in WPP trace
>
> DebugPrint from KernelMode even when consumed locally (via DebugView)
can still be quite expensive. (QueryDebugFilterState, sprintf, raise
IRQL, do callback, callback does some more work, etc…). TraceMessage
is quite simpler and is non-blocking and non-spinning. I don’t have
numbers for DebugPrint, but TraceMessage was under 2k cycles when I
measured it.
> Alex
>
> > Subject: RE: [ntdev] New line in WPP trace
> > Date: Thu, 15 Feb 2007 21:41:06 +0100
> > From: xxxxx@upek.com
> > To: xxxxx@lists.osr.com
> >
> > > ----------
> > > From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> > > Reply To: Windows System Software Devs Interest List
> > > Sent: Thursday, February 15, 2007 8:34 AM
> > > To: Windows System Software Devs Interest List
> > > Subject: RE: [ntdev] New line in WPP trace
> > >
> > > We wrote whole bunch of networking drivers that ran in 10Gbs and
in
> > > order to debug races and scenarios that happen when there is
> > > traffic load I found it very helpful to use WPP (and I think it’s
the
> > > only way I can see output without loosing performance).
> > >
> > That’s the only reason why I still didn’t rejected the idea of using
WPP completely. But is there a real difference? When traces are turned
on, is there a difference between traditional approach when traces are>
printed via DbgPrint() and captured by DebugView and WPP captured some
other way? In both cases there is an overhead which probably differs.
Does anybody have some numbers?
> >
> > Did you see any differences between both approaches when debugging
races? This is the only area where my traces sometimes cause that
problem can’t be reproduced (but in other cases problem can be
reproduced only with traces :slight_smile:
> >
> > > I don’t think that event log is the right tool for tracing or
debugging
> > > specially not when you debug networking events in 10Gbs.
> > >
> > Sure, event log has quite different purpose.
> >
> > > Maybe there should be a way to ran preprocessor before the WPP
> > > preprocessor so one can use WPP from within macros.
> > >
> > This is one of things which discourages me. Everything would be much
easier if one can use standard preprocessor macros and just call a
function which’d make trace. I also use special macros for function
enter and leave. In addition to ==> and <== they indent/outdent output
and compute time elapsed in the function/block. The whole idea with
special preprocessor for traces is IMO flawed and shows too much power
is harmful, sometimes.
> >
> > Best regards,
> >
> > Michal Vodicka
> > UPEK, Inc.
> > [xxxxx@upek.com, http://www.upek.com]
> >
> >
> >
> >
> >
> > —
> > Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>
>
>
> _____
>
> Live Search: New search found Try it!
http:
> > —
> > Questions? First check the Kernel Driver FAQ at >
> http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
> >
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
> —
> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
></http:>

36

MICHAL:

Measuring this was a good idea.

>> xxxxx@upek.com 2007-02-15 19:01 >>>
I made a quick test and measured DbgPrint captured by DebugView. Call
with no formatting parameters took less than 9500 cycles and call with 3
parameters took less than 15000 cycles. Not a big difference against WPP
if you compute real time spent at modern CPU.

Above are best cases measured by dreaded KeQueryPerformanceCounter();
the worst cases were up to 100% more.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com]
on behalf of Alex Bendetov[SMTP:xxxxx@hotmail.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, February 15, 2007 10:56 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

DebugPrint from KernelMode even when consumed locally (via DebugView)
can still be quite expensive. (QueryDebugFilterState, sprintf, raise
IRQL, do callback, callback does some more work, etc…). TraceMessage
is quite simpler and is non-blocking and non-spinning. I don’t have
numbers for DebugPrint, but TraceMessage was under 2k cycles when I
measured it.
Alex

> Subject: RE: [ntdev] New line in WPP trace
> Date: Thu, 15 Feb 2007 21:41:06 +0100
> From: xxxxx@upek.com
> To: xxxxx@lists.osr.com
>
> > ----------
> > From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com]
on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, February 15, 2007 8:34 AM
> > To: Windows System Software Devs Interest List
> > Subject: RE: [ntdev] New line in WPP trace
> >
> > We wrote whole bunch of networking drivers that ran in 10Gbs and
in
> > order to debug races and scenarios that happen when there is
> > traffic load I found it very helpful to use WPP (and I think it’s
the
> > only way I can see output without loosing performance).
> >
> That’s the only reason why I still didn’t rejected the idea of
using WPP completely. But is there a real difference? When traces are
turned on, is there a difference between traditional approach when
traces are printed via DbgPrint() and captured by DebugView and WPP
captured some other way? In both cases there is an overhead which
probably differs. Does anybody have some numbers?
>
> Did you see any differences between both approaches when debugging
races? This is the only area where my traces sometimes cause that
problem can’t be reproduced (but in other cases problem can be
reproduced only with traces :slight_smile:
>
> > I don’t think that event log is the right tool for tracing or
debugging
> > specially not when you debug networking events in 10Gbs.
> >
> Sure, event log has quite different purpose.
>
> > Maybe there should be a way to ran preprocessor before the WPP
> > preprocessor so one can use WPP from within macros.
> >
> This is one of things which discourages me. Everything would be
much easier if one can use standard preprocessor macros and just call a
function which’d make trace. I also use special macros for function
enter and leave. In addition to ==> and <== they indent/outdent output
and compute time elapsed in the function/block. The whole idea with
special preprocessor for traces is IMO flawed and shows too much power
is harmful, sometimes.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
>
>
>
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Live Search: New search found Try it!
http:
> —
> Questions? First check the Kernel Driver FAQ at >
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>

—
Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer</http:>

37

Measuring is always a good idea :wink: I heard and made too many “qualified guesses” which proven wrong. This was just the next one.

For me it had immediate good effect. I told our QA to turn off Passthrough to kernel DebugView option and they were immediately able to reproduce problem which previously disappeared with traces.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Martin O’Brien[SMTP:xxxxx@evitechnology.com]
Reply To: Windows System Software Devs Interest List
Sent: Friday, February 16, 2007 7:23 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] New line in WPP trace

MICHAL:

Measuring this was a good idea.

>>> xxxxx@upek.com 2007-02-15 19:01 >>>
I made a quick test and measured DbgPrint captured by DebugView. Call
with no formatting parameters took less than 9500 cycles and call with 3
parameters took less than 15000 cycles. Not a big difference against WPP
if you compute real time spent at modern CPU.

Above are best cases measured by dreaded KeQueryPerformanceCounter();
the worst cases were up to 100% more.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com]
on behalf of Alex Bendetov[SMTP:xxxxx@hotmail.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, February 15, 2007 10:56 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] New line in WPP trace
>
> DebugPrint from KernelMode even when consumed locally (via DebugView)
can still be quite expensive. (QueryDebugFilterState, sprintf, raise
IRQL, do callback, callback does some more work, etc…). TraceMessage
is quite simpler and is non-blocking and non-spinning. I don’t have
numbers for DebugPrint, but TraceMessage was under 2k cycles when I
measured it.
> Alex
>
> > Subject: RE: [ntdev] New line in WPP trace
> > Date: Thu, 15 Feb 2007 21:41:06 +0100
> > From: xxxxx@upek.com
> > To: xxxxx@lists.osr.com
> >
> > > ----------
> > > From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com]
on behalf of Yossi Leybovich[SMTP:xxxxx@mellanox.co.il]
> > > Reply To: Windows System Software Devs Interest List
> > > Sent: Thursday, February 15, 2007 8:34 AM
> > > To: Windows System Software Devs Interest List
> > > Subject: RE: [ntdev] New line in WPP trace
> > >
> > > We wrote whole bunch of networking drivers that ran in 10Gbs and
in
> > > order to debug races and scenarios that happen when there is
> > > traffic load I found it very helpful to use WPP (and I think it’s
the
> > > only way I can see output without loosing performance).
> > >
> > That’s the only reason why I still didn’t rejected the idea of
using WPP completely. But is there a real difference? When traces are
turned on, is there a difference between traditional approach when
traces are printed via DbgPrint() and captured by DebugView and WPP
captured some other way? In both cases there is an overhead which
probably differs. Does anybody have some numbers?
> >
> > Did you see any differences between both approaches when debugging
races? This is the only area where my traces sometimes cause that
problem can’t be reproduced (but in other cases problem can be
reproduced only with traces :slight_smile:
> >
> > > I don’t think that event log is the right tool for tracing or
debugging
> > > specially not when you debug networking events in 10Gbs.
> > >
> > Sure, event log has quite different purpose.
> >
> > > Maybe there should be a way to ran preprocessor before the WPP>
> > > preprocessor so one can use WPP from within macros.
> > >
> > This is one of things which discourages me. Everything would be
much easier if one can use standard preprocessor macros and just call a
function which’d make trace. I also use special macros for function
enter and leave. In addition to ==> and <== they indent/outdent output
and compute time elapsed in the function/block. The whole idea with
special preprocessor for traces is IMO flawed and shows too much power
is harmful, sometimes.
> >
> > Best regards,
> >
> > Michal Vodicka
> > UPEK, Inc.
> > [xxxxx@upek.com, http://www.upek.com]
> >
> >
> >
> >
> >
> > —
> > Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>
>
>
> _____
>
> Live Search: New search found Try it!
http:
> > —
> > Questions? First check the Kernel Driver FAQ at >
> http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
> >
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
> —
> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
></http:>

38

Isn’t this purely a missing tool issue?
Will you like ETW/WPP more if there were a pretty real-time viewer for ETW, like DbgView?

–PA

“Tim Roberts” wrote in message news:xxxxx@ntdev…
> Yossi Leybovich wrote:
>> I can collect my traces by traceview or by dbgview with few simple
>> scripts and I don’t think it is nuisance.
>>
>
> Look, this argument over DbgPrint vs WPP is silly. It comes down to
> personal preference. Don believes in WPP and finds it very useful.
> That’s his right. Maxim believes in DbgPrint and finds WPP
> unnecessarily complicated. That’s his right.
>
> On my first KMDF project, I tried to embrace WPP, but I found myself
> being more annoyed then delighted, and replaced them all with KdPrint.
> I now regret that, and on the next project I’ll try harder for WPP.
> That’s also MY right.
>
> You’ll never convince someone to change, any more than you can convince
> someone to change text editors. If you don’t realize that gvim is the
> greatest editor in the world, then there’s clearly something wrong with
> you. :wink:
>
> –
> Tim Roberts, xxxxx@probo.com
> Providenza & Boekelheide, Inc.
>
>

39

Pavel A. wrote:

Isn’t this purely a missing tool issue?
Will you like ETW/WPP more if there were a pretty real-time viewer for ETW, like DbgView?

Yes, but I think it’s more of an experience issue. As I understand it,
there ARE ways for me to get a “pretty real-time view” of my traces, but
I just don’t have the habits yet. In particular, WPP_DEBUG is supposed
to route the messages in real-time to the kernel debugger.

As I said, I’m trying harder this time. We’ll see if it pays off.

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