none
WPP macros and tracing funcion entry / exit RRS feed

  • General discussion

  • Hi.  I am using WPP tracing in an AVStream driver.  I have a class and an accompanying macro that I use to log function entry / exit.  While I know that this should probably be done as a post-processing step, I'd like to use the existing tools (Traceview) to produce an "easier on the eye" version of logs with a high level of detail.

    So basically I want display logs like so:

    0 549 09\12\2013-19:41:22:859        ++CUSBHardware::StopMidiStreaming
    0 550 09\12\2013-19:41:22:859            Waiting for MIDI output 0x00000003 to quiesce...
    0 551 09\12\2013-19:41:22:859            Wait Complete.
    0 552 09\12\2013-19:41:22:859            ++CUSBHardware::BulkUsb_Stop
    0 553 09\12\2013-19:41:22:859                ++CUSBHardware::BulkUsb_ObjectCleanup
    0 554 09\12\2013-19:41:22:859                    pipe = 0x8786C5F8, numTransferObjects = 2
    0 555 09\12\2013-19:41:22:859                    Calling KeWaitForSingleObject(&pipeInformation->NoPendingIrpEvent)  with 0x0
    0 556 09\12\2013-19:41:22:859                    ++CUSBHardware::BulkUsb_BulkIrp_Complete
    0 557 09\12\2013-19:41:22:859                        ++CUSBHardware::BulkUsb_ProcessTransfer
    0 558 09\12\2013-19:41:22:859                            [CUSBHardware::BulkUsb_ProcessTransfer]: IRQL: 0x2
    0 559 09\12\2013-19:41:22:859                            **ERROR: Bulk irp failed with status = C0000120
    0 560 09\12\2013-19:41:22:859                            **ERROR: urb failed with status = C0010000
    0 561 09\12\2013-19:41:22:859                        --CUSBHardware::BulkUsb_ProcessTransfer
    0 562 09\12\2013-19:41:22:859                        Returning: STATUS_MORE_PROCESSING_REQUIRED
    0 563 09\12\2013-19:41:22:859                    --CUSBHardware::BulkUsb_BulkIrp_Complete
    0 564 09\12\2013-19:41:22:859                    ++CUSBHardware::BulkUsb_BulkIrp_Complete
    0 565 09\12\2013-19:41:22:859                        ++CUSBHardware::BulkUsb_ProcessTransfer
    0 566 09\12\2013-19:41:22:859                            [CUSBHardware::BulkUsb_ProcessTransfer]: IRQL: 0x2
    0 567 09\12\2013-19:41:22:859                            **ERROR: Bulk irp failed with status = C0000120
    0 568 09\12\2013-19:41:22:859                            **ERROR: urb failed with status = C0010000
    0 569 09\12\2013-19:41:22:859                        --CUSBHardware::BulkUsb_ProcessTransfer
    0 570 09\12\2013-19:41:22:859                        Returning: STATUS_MORE_PROCESSING_REQUIRED
    0 571 09\12\2013-19:41:22:859                    --CUSBHardware::BulkUsb_BulkIrp_Complete
    0 572 09\12\2013-19:41:22:859                    Wait complete
    0 573 09\12\2013-19:41:22:859                --CUSBHardware::BulkUsb_ObjectCleanup
    0 574 09\12\2013-19:41:22:859            --CUSBHardware::BulkUsb_Stop
    0 575 09\12\2013-19:41:22:859        --CUSBHardware::StopMidiStreaming


    Code from the above log looks roughly like:

    NTSTATUS CUSBHardware::StopMidiStreaming ()
    {
    PAGED_CODE();
    FUNCTIONTRACE;

    if(KeGetCurrentIrql() > PASSIVE_LEVEL)
    {
    DBGTRACE(DBG_INFO, "%scalled at elevated IRQL!!!",tabarray[MAScopedLogger::mIndent]);
    }
    else
    {

    if(MidiStreamStarted)
    {
    for (ULONG i = 0; i < NumberOfPipes; i++)
    {
    if ((PipeInfo[i]->PipeType == UsbdPipeTypeBulk)&&
    (USBD_PIPE_DIRECTION_IN(PipeInfo[i])&&
    (PipeInfo[i]->AudioProperties.IsMidiPipe)))
    {
    BulkUsb_Stop(PipeInfo[i]);
    }
    else if ((PipeInfo[i]->PipeType == UsbdPipeTypeBulk)&&
    (!USBD_PIPE_DIRECTION_IN(PipeInfo[i])&&
    (PipeInfo[i]->AudioProperties.IsMidiPipe)))
    {
    DBGTRACE(DBG_MIDI_OUT,"%sWaiting for MIDI output 0x%08lX to quiesce...",tabarray[MAScopedLogger::mIndent], PipeInfo[i]->InterfaceIndex);
    KeWaitForSingleObject(&PipeInfo[i]->NoPendingIrpEvent,
    Executive, 
    KernelMode, 
    FALSE, 
    NULL);
    DBGTRACE(DBG_MIDI_OUT, "%sWait Complete.",tabarray[MAScopedLogger::mIndent]);
    }
    }
    }
    MidiStreamStarted = FALSE;

    return STATUS_SUCCESS;
    }

    return STATUS_UNSUCCESSFUL;
    }

    And the class (implementation)and macro to provide FUNCTIONTRACE and DBGTRACE; 

    #define FUNCTIONTRACE  MAScopedLogger _maScopedLogger(__FUNCTION__)

    #include "ScopedLogger.cpp.tmh"

    const char *tabarray[] = {" ","\t","\t\t","\t\t\t","\t\t\t\t","\t\t\t\t\t","\t\t\t\t\t\t","\t\t\t\t\t\t\t","\t\t\t\t\t\t\t\t"};

    int MAScopedLogger::mIndent;    // static

    MAScopedLogger::MAScopedLogger(const charinString ) : mString(inString)

    {

        DoTraceMessage(DBG_FUNCS,"%s++%s",tabarray[mIndent],mString);

        mIndent = min(mIndent+1,(sizeof(tabarray)/sizeof(tabarray[0])));

    }

    MAScopedLogger::~MAScopedLogger( void )

    {

        mIndent = max(0,mIndent-1);

        DoTraceMessage(DBG_FUNCS,"%s--%s",tabarray[mIndent],mString);

    };

    ... In a header file somewhere

    // begin_wpp config

    // FUNC DBGTRACE(FLAG,MSG,...);

    // end_wpp

    Because I can't figure out how to use (if it can even be done) pre / post macros I came up with an ugly, brute-force technique that forces all DBGTRACE() instances to include the indent level as the first message parameter like so:

        DBGTRACE(DBG_BULKUSB,"%sDebuggish stuff %s",tabarray[MAScopedLogger::mIndent],pHere);

    Quite ugly, but not too difficult to change 1200+ occurrences using some regex magic.  To make things even uglier, I can't hide any of the hideousness with #defines because of the pre-processor!

    Is there a cleaner way to do this using the PRE and POST macros or something? I can't figure out how to prepend something to the message before its passed to the TraceMessage() function.  I keep hitting dead-ends because of the fact that most of the work is done by the pre-processor...

    Any help greatly appreciated!

     

    Friday, September 13, 2013 2:34 AM

All replies

  • You can avoid the need to add an explicit "tabarray[MAScopedLogger::mIndent]" parameter to each trace statement.  The trick is WPP's USEPREFIX directive.

    Before we jump into a code example, though, I want to call attention to another detail.  With WPP, it's better to not have a C/C++ wrapper function around the trace statement.  A wrapper breaks WPP's ability to track the function, sourcefile, and line number associated with each trace statement.

    You've worked around that by passing around __FUNCTION__, but that's actually somewhat harmful, since that puts the name of every function into the compiled binary.  One of the big advantages of WPP is that WPP's %!FUNC! is only stored in the TMF (or PDB).  So when using WPP's %!FUNC!, your compiled binary is smaller (and leaks less intellectual property, if you care), and the code runs faster (since it doesn't have to pass an extra string pointer with each trace statement).

    Unfortunately, WPP won't quite automatically emit complete enter/exit traces from just a single statement at the top of the function.  But there are two alternatives that are possible with WPP:

    1.  Have two trace directives per function: Enter() and Exit().  This gets you all the same traces as the C++ wrapper class, but more efficiently.

    2.  Have one trace directive that emits a full Enter trace, but a partial Exit trace.  The partial Exit trace doesn't include any function information:

       >>> Enter A
           >>> Enter B
           <<< Exit
           >>> Enter C
               >>> Enter D
               <<< Exit
           <<< Exit
           >>> Enter E
           <<< Exit
       <<< Exit


    So I'll demo code that implements the second option, with partial Exit traces.  First, (and this is the key trick) set up trace statements with USEPREFIX to prepend the indent level automatically:

    //begin_wpp config
    //FUNC TraceAuto{LEVEL=TRACE_ENTER_EXIT,AUTOTRACE=0}(...);
    //USEPREFIX (TraceAuto, "%!STDPREFIX!%s", autoindent.Get());
    //USESUFFIX (TraceAuto, ">>> Enter  %!FUNC!");
    //FUNC TraceAutoExit{LEVEL=TRACE_ENTER_EXIT}(...);
    //USEPREFIX (TraceAutoExit, "%!STDPREFIX!%s", this->Get());
    //USESUFFIX (TraceAutoExit, "<<< Exit");
    //end_wpp

    We use the dummy parameter AUTOTRACE just so that we can force those traces to use a custom PRE macro.  The custom PRE macro actually creates an instance of our auto-indent class.

    #define WPP_LEVEL_ENABLED(level) (WPP_CONTROL(WPP_BIT_DEFAULT).Level >= (level))
    #define WPP_LEVEL_LOGGER(level) WPP_CONTROL(WPP_BIT_DEFAULT).Logger,
    
    #define WPP_LEVEL_AUTOTRACE_ENABLED(level,dummy1) WPP_LEVEL_ENABLED(level)
    #define WPP_LEVEL_AUTOTRACE_LOGGER(level,dummy1) WPP_LEVEL_LOGGER(level)
    #define WPP_LEVEL_AUTOTRACE_PRE(level,dummy1) Indent::Auto autoindent;
    

    All that gets us a "TraceAuto()" directive that expands out to something like this:

    Indent::Auto autoindent;
    if (WPP_BIT_DEFAULT.level >= TRACE_ENTER_EXIT)
        DoTraceMessage("%!STDPREFIX!%s", autoindent.get());

    Here's sample usage:

    void MyFunction()
    {
        TraceAuto();
    
        // do stuff
    }

    If you're playing along at home, you'll need the usual WPP boilerplate to get this to work:

    #define TRACE_ENTER_EXIT TRACE_LEVEL_RESERVED6
    
    // bacb3336-8c92-4a7d-a105-909dc858bc3d
    #define WPP_CONTROL_GUIDS                               \
            WPP_DEFINE_CONTROL_GUID(                        \
                INDENTSAMPLE,                               \
                (bacb3336, 8c92, 4a7d, a105, 909dc858bc3d), \
                WPP_DEFINE_BIT(DEFAULT)                     \
            )

    Finally, the actual details of the Indent::Auto class depend on whether you're user- or kernel-mode, and whether you can assume your tracing is single-threaded.  Here's an implementation that assumes single-threadedness:

    namespace Indent { namespace Details { static const UINT INDENT_LEVEL = 4;

    // Assumes single-threaded!
    // Use __declspec(thread) for thread-safe in usermode.
    // Thread-safe in kernelmode is more difficult :) UINT g_Indent = 0; static PCSTR GetCurrent() { #define WHITESPACE " " if (g_Indent >= RTL_NUMBER_OF(WHITESPACE)) return WHITESPACE; return WHITESPACE + (RTL_NUMBER_OF(WHITESPACE) - g_Indent); #undef WHITESPACE } } using namespace Details; PCSTR IndentMore() { g_Indent += INDENT_LEVEL; return GetCurrent(); } PCSTR IndentLess() { if (g_Indent < INDENT_LEVEL) { __debugbreak(); g_Indent = 0; return GetCurrent(); } auto result = GetCurrent(); g_Indent -= INDENT_LEVEL; return result; } class Auto { public: Auto() { IndentMore(); } ~Auto() { TraceAutoExit(); IndentLess(); } PCSTR Get() { return GetCurrent(); } }; }

    By the way, if you do want to go with explict Enter and Exit directives, you can do that by changing the configuration to this:

    //begin_wpp config
    //FUNC TraceEnter{LEVEL=TRACE_ENTER_EXIT}(...);
    //USEPREFIX (TraceEnter, "%!STDPREFIX!%s", Indent::IndentMore());
    //USESUFFIX (TraceEnter, ">>> Enter %!FUNC!");
    //FUNC TraceExit{LEVEL=TRACE_ENTER_EXIT}(...);
    //USEPREFIX (TraceExit, "%!STDPREFIX!%s", Indent::IndentLess());
    //USESUFFIX (TraceExit, "<<< Exit  %!FUNC!");
    //end_wpp

    Then the usage changes to

    void MyFunction()
    {
        TraceEnter();
    
        // Do stuff
    
        TraceExit();
    }

    This gets the same results as the other option, except the Exit traces also contain the correct function name.


    Friday, September 13, 2013 9:59 PM
  • Thanks very much for taking the time to give useful example code and explanations.  I understand your point about having function name strings in the executable and agree that they are much better handled as symbols in a .pdb file. This has not been too much of a concern as the intent is not to distribute "instrumented" executable, though its nice to have the option.  For production builds I #define the tracing macros away, mostly for efficiency reasons but thank you for pointing out the security issues as well.  I'll give the "entry + partial exit" technique a try.

    Thanks again for your responses!

    -wade

    Wednesday, September 18, 2013 3:35 PM