You can tell WPP which are your Trace functions TTRACE_ENTER, etc
The easiest way to do this is with a config block that WPP scans, also
can be done with a command line option. See the TraceDrv sample for how
the config block works, it has detailed explanation. Also my
presentation from DevCon2005 had details.
//begin_wpp config
//USEPREFIX (TTRACE_ENTER, “%!STDPREFIX! ===>”); //here is where you
add the prefix
//FUNC TTRACE_ENTER(FLAGS,LEVEL,(MSG,…));
//end_wpp // you can also add a suffix
Not sure how you are doing the elapsed time.
But ETW logs a timestamp with the event, PID, TID, processor, and some
other values. Other starndard values are taken from the TMF, like format
string, component name, etc.
Bottom line is that you can correlate the ENTER/EXIT events to get the
elapsed time.
So yes you can do all that, and as simple as printf and better, because
we support extended format strings.
-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, February 15, 2007 3:38 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] WPP trace - Function Entry/Exit Tracing
I found the example before but shows only the simple case. And if I
understand correctly, %!FUNC! can’t be used in debug prints (if the
debug version of driver is built with them instead of WPP). The
presentation doesn’t contain the most interesting parts. For example at
page 31. And do you really believe this thread would even exist if WPP
accomplishes the last point at page 4 (as simple as printf…) 
Well, my code usually looks like this:
NTSTATUS DispatchDevCtrl(IN PDEVICE_OBJECT DeviceObject, IN PIRP Irp) {
TTRACE_ENTER(Ioctl, TDBG_DEBUG, (“DispatchDevCtrl(%p, %p)”,
DeviceObject, Irp));
…
TTRACE(Ioctl, TDBG_DEBUG, (“Processing IOCTL %x <%s> (input length:
%d, output length: %d)”,
IoctlCode, GetIoctlCodeName(IoctlCode),
InputBufferLength, OutputBufferLength));
…
TTRACE_LEAVE((“DispatchDevCtrl() -> %x [%d]”, Status,
ReturnedSize));
return(Status);
}
where Ioctl is trace area which contains current trace level. Traces in
different sources can and usually have different areas. Note LEAVE macro
uses ENTER parameters and measures elapsed time. The appropropriate
debug output looks like this:
0.26440164 <0:0> Ioctl[1006]: ==> DispatchDevCtrl(89D50B00,
8AA9CF20)
0.26475674 <0:0> Ioctl[1082]: Processing IOCTL 81c06070
<tcusb_ioctl_get_version> (input length: 0, output length: 16)
0.26480985 <0:0> Ioctl[1799]: <== (0.395) DispatchDevCtrl() -> 0
[16]
Also note indent for intermediate trace message. Is it possible to
achieve the same effect with WPP? I don’t need to see code, just if it
is even possible.
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 Ian Service[SMTP:xxxxx@microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, February 15, 2007 10:33 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] WPP trace - Function Entry/Exit Tracing
>
> I changed the subject line a little as I was getting lost with the
> different threads.
>
> Regarding Function Entry/Exit tracing, there is a basic example in the
> MSDN.
>
> http://msdn2.microsoft.com/en-us/library/ms797191.aspx
>
> and some presentation here
>
>
http://download.microsoft.com/download/5/b/5/5b5bec17-ea71-4653-9539-204
> a672f11cf/Software_Tracing.ppt
>
> They do show up in searches.
>
> It needs a extra function to finish what Yossi needs.
>
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
> Sent: Thursday, February 15, 2007 12:41 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] New line in WPP trace
>
> > ----------
> > 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
>
> —
> 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</tcusb_ioctl_get_version>