DIY MS Visual C++ Function Profiling using /Gh Compiler Option

Copyright © 2000 by Feng Yuan (author of Windows Graphics Programming: Win32 GDI and DirectDraw, www.fengyuan.com). All rights reserved.

Version 1.00: October 21, 2000

Version 1.00: October 25, 2000 (support for C++ added)

Problem

Given the source code for a Visual C++ program, how do you generate a profile for each function called during the execution of the program, together with parameters and return values.

Design

MS Visual C++ compiler has a rarely known compiler option /Gh, designed for hooking function calls. Once enabled, each function will call a user provided routine _penter. Withing the _penter routine, it's quite easy to get to the address of the original function caller, and parameters. With some stack manipulation, it's also possible to hook into each function return point to log function return values. These binary data can be decoded into more readable forms using a table of function information.

Implementation: a simple profiling library (profile.lib, do NOT compile with /Gh option)

Header File: Profile.h

// Copyright (C) 2000 by Feng Yuan (www.fengyuan.com)
typedef struct
{
    const void  * function;     // function address
    const TCHAR * parameter;    // formatting string for parameter decoding, '?' for class method
    const TCHAR * returnval;    // formatting string for return value decoding,
}   Signature;


extern Signature FuncTable[];   // function signature table

void Expect(Signature * pSig);  // expecting a call to record its address in its signature

Cpp File: Profile.cpp

// Copyright (C) 2000 by Feng Yuan (www.fengyuan.com)
#define STRICT

#include <windows.h>
#include <assert.h>
#include <tchar.h>

#include "profile.h"

#define MAX_DEPTH 512           // good enough for 512 levels of nesting

void * Stack[MAX_DEPTH * 2];    // NOT multi-thread safe
int    SP          = 0;
int    depth       = 0;

void _stdcall ExitFunc(unsigned * pStack)
{
    TCHAR       temp[MAX_PATH];
    Signature * pSig;

    depth --;

    SP --;
    pSig      = (Signature *) Stack[SP];
    
    strcpy(temp, "                                                                      ");

    if ( pSig )
        wsprintf(temp+depth*2, pSig->returnval, pStack[0]); // print return value in EAX register
    else
        wsprintf(temp+depth*2, "returns 0x%x", pStack[0]);
    
    OutputDebugString(temp);
    OutputDebugString("\n");

    SP --;
    pStack[0] = (unsigned) Stack[SP]; // change return address to point to original caller
}

extern "C" __declspec(naked) void __cdecl _pexit(void)
{
    _asm 
    { 
        push   eax        // function return value and placehold for return to original caller
        pushad            // save all general purpose registers 
        mov    eax, esp   // current stack pointer  
        add    eax, 32    // stack pointer before pushad
        push   eax        // push pointer to where EAX is saved as parameter to ExitFunc

        call   ExitFunc

        popad             // restore general registers
        ret               // return to original caller  
    }
}

void _stdcall EnterFunc(unsigned * pStack)
{
    char       temp[MAX_PATH];
    Signature * pSig;
    void      * pCaller;

    // pStack[-8] : EDI     general purpose registers saved on stack
    // pStack[-7] : ESI
    // pStack[-6] : EBP
    // pStack[-5] : ESP
    // pStack[-4] : EBX
    // pStack[-3] : EDX     usually 'this' pointer for an object
    // pStack[-2] : ECX
    // pStack[-1] : EAX

    // pStack[0]  : return address to the caller of _penter
    // pStack[0]-5: first byte of caller function, for example WinMain
    // pStack[1]  : return address to the caller function
    // pStack[2]  : parameter1
    // pStack[3]  : parameter2
    // pStack[4]  : parameter3
    // ...
    // pStack[N+1]: parameterN

    pCaller = (void *) (pStack[0] - 5); // the instruction for calling _penter is 5 bytes long
    pSig    = FuncTable;

    while ( pSig->function )            // search in the signature table
    {
        const BYTE * func = (const BYTE *) pSig->function;

        if ( (func==(const BYTE *) pCaller) || // release or debug with extra indirection (jmp)
             ( ( * func==0xE9 ) && ( (func + * (DWORD *) (func+1) + 5) == (const BYTE *) pCaller ) )
           )
           break;

        pSig ++;
    }

    strcpy(temp, "                                                             ");

    if ( pSig->function )       // decode parameters
        if ( pSig->parameter[0]=='?' )  // special marker for class method, need 'this' pointer in ECX register
            wsprintf(temp+depth*2, pSig->parameter+1, pStack[-2], pStack[2], pStack[3], pStack[4], pStack[5], pStack[6]); 
        else
            wsprintf(temp+depth*2, pSig->parameter, pStack[2], pStack[3], pStack[4], pStack[5], pStack[6]); 
    else
    {
        wsprintf(temp+depth*2, "%x(%x, %x, %x, ...)", pCaller, pStack[2], pStack[3], pStack[4]);

        pSig = NULL;
    }

    OutputDebugString(temp);
    OutputDebugString("\n");

    Stack[SP++] = (void *) pStack[1]; // save return address to original caller
    Stack[SP++] = pSig;               // save functions signature
    
    pStack[1]   = (unsigned) _pexit;  // HACK stack to link to _pexit  

    depth ++;
}

Signature * pExpect = NULL;     

void Expect(Signature * pSig)   // expecting a call to setup caller address 
{
    pExpect = pSig;
}

void _stdcall EnterFunc0(unsigned * pStack)
{
    if ( pExpect )                                          // if expecting a call during setup
    {
        pExpect->function = (const void *) (pStack[0] - 5); // just record function address
        pExpect = NULL;
    }
    else
        EnterFunc(pStack);                                  // process the call
}

extern "C" __declspec(naked) void __cdecl _penter(void)
{ 
    _asm 
    { 
        pushad              // save all general purpose registers
        mov    eax, esp     // current stack pointer
        add    eax, 32      // stack pointer before pushad
        push   eax          // push pointer to return address as parameter to EnterFunc0
        
        call   EnterFunc0

        popad               // restore general purpose registers
        ret                 // start executing original function
    }
}

Sample Program, compiled with /Gh option, link with profile.lib

#include "stdafx.h"
#include "profile\profile.h"

int gcd(int x, int y)
{ 
    if ( x==0 )
        return y;
    else
        return gcd(y % x, x);
} 

int fac(int n)
{
    if (n<=1)
        return 1;
    else
        return n * fac(n-1);
}

class CFraction
{
    int m_x;
    int m_y;

public:
    
    CFraction(int x, int y)
    {
        m_x = x;
        m_y = y;
    }

    virtual ~CFraction()
    {
    }

    virtual void mul(CFraction & f)
    {
        m_x *= f.m_x;
        m_y *= f.m_y;
    }

    void div(CFraction & f)
    {
        m_x *= f.m_y;
        m_y *= f.m_x;
    }
};

Signature FuncTable[] =
{
    {   gcd,     "gcd(%d,%d)",                        "gcd returns %d"                },
    {   fac,     "fac(%d)",                           "fac returns %d"                },
    {   WinMain, "WinMain(0x%x, 0x%x, \"%s\", %d)",   "WinMain returns %d"            },

    {   NULL,    "?%x->CFraction::CFraction(%d, %d)", "CFraction::CFraction returns"  },
    {   NULL,    "?%x->CFraction::~CFraction()",      "CFraction::~CFraction returns" },
    {   NULL,    "?%x->CFraction::mul(%x)",           "CFraction::mul returns"        },
    {   NULL,    "?%x->CFraction::dul(%x)",           "CFraction::div returns"        },
    {   NULL,    NULL,                                NULL                            }
};

int APIENTRY WinMain(HINSTANCE hInstance, 
                     HINSTANCE hPrevInstance, 
                     LPSTR     lpCmdLine, 
                     int       nCmdShow) 
{ 
    Expect(& FuncTable[3]);
    {
        CFraction N(3, 5);
        
        Expect(& FuncTable[5]); N.mul(N);
        Expect(& FuncTable[6]); N.div(N);

        Expect(& FuncTable[4]);
    }

    CFraction num1(3, 5);
    CFraction num2(10, 11);

    num1.div(num2);
    num2.mul(num1);

    return gcd(1143, 60) + fac(5);
}

Sample Program Output

WinMain(0x400000, 0x0, "", 1)
  12ff18->CFraction::CFraction(3, 5)
  CFraction::CFraction returns
  12ff0c->CFraction::CFraction(10, 11)
  CFraction::CFraction returns
  12ff18->CFraction::dul(12ff0c)
  CFraction::div returns
  12ff0c->CFraction::mul(12ff18)
  CFraction::mul returns
  gcd(1143,60)
    gcd(60,1143)
      gcd(3,60)
        gcd(0,3)
        gcd returns 3
      gcd returns 3
    gcd returns 3
  gcd returns 3
  fac(5)
    fac(4)
      fac(3)
        fac(2)
          fac(1)
          fac returns 1
        fac returns 2
      fac returns 6
    fac returns 24
  fac returns 120
  12ff0c->CFraction::~CFraction()
  CFraction::~CFraction returns
  12ff18->CFraction::~CFraction()
  CFraction::~CFraction returns
WinMain returns 123

Limitation