Redirection Through C++ Function Pointers

In this article, I show how function pointers can redirect application calls between a minimal logging function and a verbose logging function on the fly. The log statements remain in the code, making the code size a little larger than normal but hopefully a reasonable trade-off for being able to collect essential data. If the minimal logging function is called, it performs minimum processing so the intrusion on performance is balanced with the desired amount of logging. The minimum amount of logging I've chosen for this implementation is "none."

Log statements provide consistent observations for all application users. This eliminates false observations, recollection, hearsay, and the like. In the television show "CSI: Crime Scene Investigation," Gil Grissom (played by William Petersen) harps on the idea that the evidence is the only factual information available to diagnose a person's death after the fact. It might be a morbid analogy, but it's also true of the log files captured from the running of client applications. Log files are the history of what actually happened when the application was in the process of going belly-up or had a problem.

Function Pointer Syntax

The syntax for pointers to functions can be expressed in several ways. One way is a carry-over from C, where pointers to functions were always for static functions. In C++, pointers to functions can be static or nonstatic. Example 1 shows examples of type-defined pointers to functions.

In C++, nonstatic function calls require the implied passing of the this pointer, although some compilers use the keyword thiscall to describe the calling convention. This convention also implies that the callee cleans up the stack. In C/C++, calling of static functions is the same and usually follows the __stdcall calling convention, where the callee cleans up the stack. However, since log statements usually have a variable argument list, the calling convention will also require that the caller clean up the stack since only it knew the number of arguments passed in the function call.

Implementation of the Logger Class

Listing One is the header for the Logger class. Logger is implemented as a Singleton (see Design Patterns, by Erich Gamma, et al., Addison-Wesley, 1995) since it seems practical that an application have at least one local or linked-in logger at a time. The static and nonstatic calling forms for function pointers will be shown for demonstration purposes. Either calling form can be used, but only one is necessary.

A type definition is declared for the pointer to the current logging function; notice that it has a variable argument format. The function pointer is the mechanism for the redirection between the minimal logging and the verbose logging at any point in time. Two private class variables store the pointer to the logging function(s), one variable is for the static form; the other is for the nonstatic form. Inline accessors protect the pointers and make accessing them efficient.

Macros (see C++ FAQs, Second Edition, by Marshall Cline and Greg Lomow, Addison-Wesley, 1999) are provided for both calling forms as LOG_MSG_S and LOG_MSG_NS for the static and nonstatic forms, respectively. Many C++ books recommend avoiding macros because they promote code bloat and generally do not enforce type safety (see More Effective C++, by Scott Meyers, Addison-Wesley, 1996). My justification is to make the syntax used in the application readable and less prone to typing and compiler errors when trying to get the tedious syntax correct. The macros use pointer notation because the Logger is a Singleton and the client only has an instance pointer. To be complete, a macro LOG_MSG_NS is defined for the dot notation.

Listing Two is the implementation for the Logger class. The constructor initializes the function pointers, defaulting to minimal logging. Singletons have problems regarding their lifetime management (see Pattern Hatching, by John Vlissides, Addison-Wesley, 1998). I'm taking the coward's way out and deleting it in the destructor. It's not the best solution, but for this example it will work. SetQuality() calls a private function SwitchLoggingFunctions() to switch the function addresses stored in the pointers to be either the minimal or verbose function. The syntax for storing the pointers for the static and nonstatic forms is the same. However, what the pointers mean is different. The static pointer is an address for a function that can be called in a standalone fashion. The nonstatic member function pointer is only useful when dereferenced in conjunction with an object instance.

The minimal and verbose logging functions intentionally have private access. The client indirectly calls the logging functions using the macros, thereby abstracting the client from the redirection that automatically takes place. It also eliminates the need for the client to check the logging quality for every log message. In fact, Logger does not need to check the logging quality because the right function is always called.

The argument list I chose for the minimal and verbose functions requires at least two arguments to be passed. It's possible to create a new class to aggregate the arguments and even handle the variable argument list with a container; but there would be a performance trade-off. The new object would need to be constructed and initialized before being passed. Then it must be destructed after the call to the logging function is made. It would really depend on the number of fixed arguments passed. Also, if logging quality is minimal, the minimal implementation might not even use this object, so the steps mentioned would be unnecessary and the setup time before the call might be large.

The verbose function handles the variable argument list. The macros va_start() and va_end() provided by most compiler vendors for C are used to setup the parsing of the variable arguments. I'm using Microsoft Visual C++ 6 in this article. I'm only passing the function name and line number as additional arguments. A fuller implementation would iterate through all arguments until it reached the end of the list. My purpose is to layout the bare minimum amount of code that would be required. A character buffer is formatted with a sprintf to include the function name and line number. A timestamp would be essential for a real implementation as well; but I'm blowing that off too. The output is suppressed with a calling parameter because the various logging resources (such as memory, files, sockets, and the like) would take differing amounts of time to complete. This limited implementation for the verbose logging function will be the basis for timing comparisons against the minimal logging function.

The minimal logging function just returns true because I want it to be as fast as possible. Since none of the arguments are used, the compiler will probably optimize this function call, which is a good thing. It might generate some warnings for the unreferenced variables that can be dealt with using pragmas or other tricks.

The logging functions in the static form would need to use the Instance() method if any Logger object instance data was needed. The nonstatic forms of the logging functions have immediate access to all object instance data. The static forms, since they don't pass a this pointer, should be slightly faster. However, it's only one argument and the functions have variable argument lists, so it probably won't save much time.

An alternative to the function pointers is the calling of a single logging function. This function would have to check the logging quality each time to determine what, if any, logging should be performed. For the contrived example I am presenting, the testing of two values is no big deal. But what if there were six or more quality values? Then a switch statement tests all values and performs the appropriate logging. The overhead of checking the flag every time a message was logged would have a cumulative affect on an application's performance. It also seems to be a messier implementation.

Example

Listing Three is code for an application using the Logger class. First, the Instance() method is called to cause the creation of a Logger. Then, SetQuality() is called to set the logging to either minimal or verbose. Finally, the macro LOG_MSG_S or LOG_MSG_NS indirectly calls the logging function.

The redirection to the minimal or verbose logging functions is encapsulated in the Logger class. The application sets the logging quality and executes the code beneath, using the LOG_MSG_S or LOG_MSG_NS macro. Whether the code is for debugging or a release environment, the application leaves the logging statements in place. Verbose logging can be turned on at any time for any reason. Some environments, such as Microsoft's visual tools, provide trace macros that generate code for debugging. However, the preprocessor eliminates the tracing for release builds. While handy during the development process, logging is extremely valuable for the maintenance and support phase. The other problem with the preprocessor deleting the log statements is that the program's addresses become different between the debug and release versions. This can be a royal pain when trying to interpret a stack or core dump when a release build crashes.

Timing Tests

I performed some simple timing tests using the static and nonstatic logging macros for both the minimal and verbose cases; see Table 1. The test times were generated on my Pentium Pro 200 for 1 million iterations. I'm only trying to show the impact of the setup of the logging, not the actual logging itself, so output was suppressed using the provided call parameter. The I/O times for logging to a device, whether it is memory, file, sockets, and so on, will certainly be the lion's share of the performance hit. My point is that the log statements can be left in place without causing a performance penalty if the logging quality is minimal. Once you switch to verbose logging, there is definitely a performance hit, but it should only be temporary because the quality can be switched back later.

When I ran the verbose logging timing tests, I wanted to know where the time was going. I commented out the sprintf() and was amazed at how fast the new test ran. I could only use the data from the debug configuration because the compiler does not perform optimizations; it builds and executes the code just as it is written. In the release configuration, the compiler saw that the sprintf() was not performed and that declared variables were not used, so it optimized the whole function to essentially do nothing. Therefore, those numbers are not valid for any comparisons. I verified this by generating and inspecting the assembly listings.

The sprintf() was only using two arguments, the function name and line number, and formatting them into a small character buffer. However, it still had a significant impact on the performance. The moral is that the use of sprintf in a logging implementation should be judicious or worked around if performance is that important. Since Logger lets the log quality change on the fly from minimal to verbose, the logging should be set to verbose only when necessary, and then it should be set back to minimal if system performance is an issue. To put this in perspective, the setup of the logging of the function name and line number took about 14 microseconds in the release configuration per call. When I enabled the logging to the stdout, the average time to log this simple message was about 1 millisecond per statement; so the time is not trivial, but it dwarfs the sprintf() time penalty. Therefore, it's hard to justify the removal of the log statements from a client application when the cost is so little if minimal logging is enabled.

Finally, the static logging form test times are about the same as the nonstatic form. Even though the static form is passing one less argument, the this pointer, it matters very little when verbose logging is enabled because the time is being spent in the sprintf() and in the logging device I/O. In the minimal logging quality scenario, the performance benefit can be seen between the two forms. However, the time in Table 1 is for 1 million iterations, so 0.06 seconds only works out to 60 nanoseconds per call (on my slow machine).

Conclusion

The Logger class demonstrates one way you can use redirection through function pointers. A client is allowed to change the quality of the logging service provided. Since Logger supports minimal and verbose logging, the client can determine which type of logging should take place at any time. By choosing minimal logging, the impact of log statements on the client applications' real-time performance is minimized. Using logging changes an application's behavior and performance, but if used wisely, it has significant benefits.

I chose the logging example because too often, it is easy to yield to the temptation of yanking out the log statements before releasing code to production. I've never seen a system in production that has been free of defects. In my experience, log files have been invaluable in tracking down bugs. It is essential to know where the program was and what it was doing just before it failed or encountered an error. I recommend using logging from the beginning of application development. Performance issues can be remedied by using minimal logging and verbose logging only when necessary. I'm not recommending that library vendors leave logging and trace statements in functions such as strcpy(). The example shows that the log statements can be left in the high-level application logic and turned on when necessary.

Logger demonstrates that a single interface, the LOG_MSG_S or LOG_MSG_NS macros, is used to call the right logging function depending on the current quality setting. This eliminates the need for the application or even the Logger class to continually check the logging quality and call the right logging function or having to pass the log quality every time. The changing of the logging quality is a state transition that is processed once, and the function pointers are set to the appropriate values.

One disadvantage of the function pointer technique is a built-in assumption that changes to the function pointer value are relatively infrequent. In the Logger class, it seemed reasonable that logging would be set to minimal or verbose for some period of time or number of calls. An application in production might switch to verbose logging to collect detailed information and then switch back to minimal logging in order to save disk space, run faster, and so on. If the logging quality needed to change for every message at any given time, then this technique might not be a good solution unless the quality value was used as an index into an array of function pointers. A minor limitation of the technique also requires the various functions to have the same call signature. The logging example used a variable argument list with a few fixed arguments, so the problem is not that severe. In another use of the technique, an abstract base class reference could be passed to the called function. The function would discern the type of the object instance and act accordingly, averting the restriction by encapsulating the data in an object.

Redirection through function pointers abstracts a client from many implementations of underlying functions. The Logger example uses this technique to minimize the affect of log statements on application performance, so their presence in production code is justified. Function pointers have many uses; the logging example is just one use of the technique. Where can you use it in your application?

DDJ

Listing One

// Declaration for the Logger Class
#if !defined(LOGGER_H_INCLUDED)
#define LOGGER_H_INCLUDED
using namespace std;    // for cout
class Logger
{
    public:
        // Singleton Pattern Instance Accessor Function
        static Logger* Instance();
        // Declare Type Definitions for the static and non-static
        // forms for a Pointer to a Function that accepts several
        // fixed arguments followed by a variable argument list
        // (common in a function that has a format statement)
        typedef bool (*PFLogMsgS)(bool bNoOutput, const char* szFormat,...);
        typedef bool (Logger::*PFLogMsgNS)(bool bNoOutput,
                                           const char* szFormat,...);
        // Handy macros to make calling the logging function easier.
        // The syntax in the non-static case is tedious.
        #define LOG_MSG_S (Logger::getLogMsgS())
        #define LOG_MSG_NS(pObject) ((pObject)->*(pObject->getLogMsgNS()))

        // Macro if using an instance
        #define LOG_MSG_NSi(object) ((object).*(object.getLogMsgNS()))
        ~Logger(void){ delete _instance; _instance = NULL; }

        // Declare accessors for the function pointers
        static PFLogMsgS  getLogMsgS(void)        { return m_pLogMsgS;  }
               PFLogMsgNS getLogMsgNS(void) const { return m_pLogMsgNS; }
        typedef enum
        {
            MINIMAL,
            VERBOSE
        } LOG_QUALITY;
        LOG_QUALITY GetQuality(void) const { return m_eLogQuality; }
        void SetQuality(LOG_QUALITY quality = MINIMAL);
    protected:
        // Singleton Pattern uses a protected Ctor
        Logger(LOG_QUALITY quality = MINIMAL);
    private:
        // Declare storage for a pointer to the instance
        static Logger* _instance;
        // Declare storage for pointers to the logging function
        static PFLogMsgS  m_pLogMsgS;
               PFLogMsgNS m_pLogMsgNS;
        void SwitchLoggingFunctions(LOG_QUALITY quality);
        // Logging Functions, Static (S) and Non-Static (NS) Forms
        static bool Verbose_S(bool bNoOutput, const char* szFormat,...);
        static bool Minimal_S(bool bNoOutput, const char* szFormat,...);
        bool Verbose_NS(bool bNoOutput, const char* szFormat,...);
        bool Minimal_NS(bool bNoOutput, const char* szFormat,...);
    private:
        LOG_QUALITY m_eLogQuality;  // MINIMAL or VERBOSE
};
#endif  // !defined(LOGGER_H_INCLUDED)

Back to Article

Listing Two

// Definition for Logger Class Functions
#include "stdafx.h"
#include <iostream>
#include <stdarg.h>
#include "Logger.h"

// Initialize static class data (once before program runs)
Logger* Logger::_instance = 0;
Logger::PFLogMsgS Logger::m_pLogMsgS = Logger::Verbose_S;

// Implement the Instance method
Logger* Logger::Instance()
{
    // If first time called, make a new one.
    // (For all time, there will be only one unique instance.)
    if (_instance == 0)
    {
        _instance = new Logger;
    }
    return _instance;
}
Logger::Logger(LOG_QUALITY quality /* = MINIMAL */ )
{
    SwitchLoggingFunctions(quality);
}
void Logger::SetQuality(LOG_QUALITY quality /* = MINIMAL */ )
{
    SwitchLoggingFunctions(quality);
}
// This function ignores thread safety
// Add synchronization here and
// in the macros if necessary
void Logger::SwitchLoggingFunctions(LOG_QUALITY quality)
{
    switch ( quality )
    {
        case MINIMAL:
            m_eLogQuality = quality;
            m_pLogMsgS  = Logger::Minimal_S;
            m_pLogMsgNS = Logger::Minimal_NS;
            break;
        case VERBOSE:
            m_eLogQuality = quality;
            m_pLogMsgS  = Logger::Verbose_S;
            m_pLogMsgNS = Logger::Verbose_NS;
            break;

        default:
            m_eLogQuality = MINIMAL;
            m_pLogMsgS  = Logger::Minimal_S;
            m_pLogMsgNS = Logger::Minimal_NS;
            break;
    }
}
// This function looks exactly the same as Verbose_NS,
// except it's static and doesn't get a this pointer.
bool Logger::Verbose_S(bool bNoOutput, const char* szFormat,...)
{
    // Setup for varg processing
    va_list vl;
    va_start( vl, szFormat);

    // Assume 1st 2 vargs are the filename and line number,
    // and ignore other arguments for this demonstration
    char* pFileName   = va_arg( vl, char* );
    int   nLineNumber = va_arg( vl, int );

    // Format the simple message
    char buffer[256];
    sprintf(buffer, szFormat, pFileName, nLineNumber );

    // Allow for output suppression on the fly, especially when doing millions
    // of iterations for timing tests. If caller wants output, use stdout 
    // device for this demonstration knowing there are many other devices
    // that could be used.
    if ( !bNoOutput)
    {
        printf(buffer);
    }
    // Finish the varg processing
    va_end( vl );
    return true;
}
bool Logger::Verbose_NS(bool bNoOutput, const char* szFormat,...)
{
    // Setup for varg processing
    va_list vl;
    va_start( vl, szFormat);
    // Assume 1st 2 vargs are the filename and line number,
    // and ignore other arguments for this demonstration
    char* pFileName   = va_arg( vl, char* );
    int   nLineNumber = va_arg( vl, int );

    // Format the simple message
    char buffer[256];
    sprintf(buffer, szFormat, pFileName, nLineNumber );

    // Allow for output suppression on the fly, especially when doing millions
    // of iterations for timing tests. If caller wants output, use stdout 
    // device for this demonstration knowing there are many other devices
    // that could be used.
    if ( !bNoOutput)
    {
        printf(buffer);
    }
    // Finish the varg processing
    va_end( vl );

    return true;
}
bool Logger::Minimal_S(bool bNoOutput, const char* szFormat,...)
{   return true;    }
bool Logger::Minimal_NS(bool bNoOutput, const char* szFormat,...)
{   return true;    }

// End of Logger.cpp

Back to Article

Listing Three

// Sample Code. Instantiate the Logger by calling the Instance Method
// Set the Quality Level, then Use the Log Macros

Logger* pLogger = Logger::Instance();
pLogger->SetQuality(Logger::VERBOSE);
bool bResult;
bResult = LOG_MSG_S(false, "File: %s Line: %d Msg: Hello\n",
                                               __FILE__, __LINE__ );
bResult = LOG_MSG_NS(pLogger)(false, "File: %s Line: %d Msg: World\n", 
                                               __FILE__, __LINE__ );

Back to Article