Channels ▼
RSS

Open Source

Logging In C++: Part 2


Setting Logging Level At Line Granularity

The basic idea is to define a local static variable for each logging statement. The variable is used to enable/disable each individual log statement. A Set() function will be defined as a way to change the value of any of the local static variables.

The static variable can have different states:

  • Uninitialized: The meaning is that the log statement was never executed (yet).
  • Default: The user doesn't want to change the default (global) log level.
  • Enabled: The user wants to enable this log statement, no matter what the global log level is.
  • Disabled: The user wants to disable this log statement, no matter what the global log level is.

    
    enum TEnabler {NOT_INIT = -2, DEFAULT, DISABLE , ENABLE};
    
    

Let's define the static variable inside of a for loop like described above. In this way the definition of local static variable is packed in a macro, so users can use it without caring about what it contains. For example:


#define LOGMAN(level) for(static TEnabler enabler = NOT_INIT; …;…)  FILELog().Get(logINFO)

The following code:


LOGMAN(logINFO) << "Hello world!"; // a new static local variable is define for each log statement

will be expanded to:


for(static int enabler = NOT_INIT; …;…)  FILELog().Get(logINFO) << "Hello world!";

To make sure that the for loop's body (the log statement) is executed not more than once an extra if statement is used:


#define LOGMAN(level) if (alreadyLogged = false) \
else for(static TEnabler enabler = NOT_INIT; !alreadyLogged && …; alreadyLogged = true)  FILELog().Get(logINFO)

It is very likely that any compiler optimizer will detect that the if branch is never executed (always false), and the test will be completely removed.

The following function is defined as a way to detect if the current log statement is enabled:


bool LogEnabled(TEnabler& enabler, const TLogLevel& level, const char* pFile, int line);

The LOGMAN() macro then becomes:


#define LOGMAN(level) if (alreadyLogged = false) \
else for(static TEnabler enabler = NOT_INIT; !alreadyLogged && LogEnabled(enabler, level, __FILE__, __LINE__); \
alreadyLogged = true)  FILELog().Get(logINFO)

This is the implementation of LogEnabled():


bool LogEnabled(TEnabler& enabler, const TLogLevel& level, const char* pFile, int line)
{
    TEnabler safeEnabler = Read(enabler);
    if (safeEnabler == NOT_INIT)
    {
        Init(enabler, pFile, line);    
        safeEnabler = Read(enabler);
    }
    return ((safeEnabler == DEFAULT && FILELog::ReportingLevel().Get() >= level) || safeEnabler == ENABLED);
        }

To read/write the value of the static variable (shared between multiple threads) the Read()/Write() functions are used. They insert memory barriers, so this will make sure the ordering of the code is preserved and the code will work fine even on multiple processor machines. This can be implemented in a portable way by using the Boehm's atomic_ops library.

Also please note that the initialization of the static variable is done (statically) before the for loop is first executed. This avoids a race condition, which would occur if the variable were dynamically initialized.

Having very efficient code when the enabler variable is already initialized (enabler != NOT_INIT) is very important. For that reason locks were avoided on the normal path (DLCP), and there is a possibility that the Init() function above is actually called multiple times for the same variable. Because the Init() function is called just once for each log statement, the locks can be used inside this function, and serialize these calls, without worrying about effciency.

What Init() does is to add the addresses of the static variable into a global map, having the key the file name and the line number identifying the log statement:


typedef std::pair<std::string, int> TKey;
typedef std::vector<TEnabler*> TPtrLevels;    
typedef std::pair<TPtrLevels, TEnabler> TValue;
typedef std::map<TKey, TValue> TMap;

Please note that the value is not a single address but a vector of addresses. Multiple log statements on a single line can be handled this way:


void foo(int i)
{
    LOGMAN(logINFO) << i; LOGMAN(logINFO) << i;    
}

Another case when different static variable will be defined on the same line is when used inside template functions/methods:


template <typename T>
void foo(const T& t)
{
    LOGMAN(logDEBUG) << t; // "myfile.cpp", line = N
}

For each "T" type a different "static" variable will be generated.


foo(1); // a static variable is defined for "myfile.cpp", line = N
foo(1.2); // another static variable is defined for the same "myfile.cpp", line = N

Before implementing the Init() function, let's look at the implementation of the Set() function. It will allow changing the value of static variables identified by the file name and line number:


void Set(const char* pFile, int line, TEnabler enabler)
{
    boost::mutex::scoped_lock l(GetMutex());
    TKey key = std::make_pair(std::string(pFile), line);
    TMap::iterator i = GetMap().find(key);
 
    if (i != GetMap().end())
    {
        TValue& value = i->second;
        value.second = enabler;
        TPtrLevels& levels = value.first;
        for (TPtrLevels::iterator j = levels.begin(); j != levels.end(); ++j)
        {
            Write(enabler, **j);
        }
    }
    else
    {
        GetMap()[key] = std::make_pair(TPtrLevels(), enabler);
   }
}

The function checks if there are any static variable addresses in the map at the moment (for the file name and line number parameters). If there are any, it will set the value accordingly. If there are no values in the map yet (for example the Set() was called before the log statement at file name/number was first executed), it just saves the value in the map.

This is a possible implementation of the Init() function:


void Init(TEnabler& enabler, const char* pFile, int line)
{
    boost::mutex::scoped_lock l(GetMutex());
    TKey key = std::make_pair(std::string(pFile), line);
    TMap::iterator i = GetMap().find(key); 
    if (i != GetMap().end())
    {
        TValue& value = i->second;
        value.first.push_back(&enabler);
        Write(value.second, enabler);
    }
    else
    {
        Write(DEFAULT, enabler);
        TPtrLevels levels;
        levels.push_back(&enabler);            
        GetMap()[key] = std::make_pair(levels, DEFAULT);
    }
}

The function will insert in the global map the address of the static variable. If the key is not in the map it will use the DEFAULT value. If the key is in the map it will use whatever the value was already set. If Init() is called multiple times with the same static variable address (probably because of a race condition) the code checks if the address is already in the vector, and it ignores the second occurrence. However ignore this situation can be ignored, and accept in this situation having the same address multiple times in the vector. This is a very rare situation and the code will work fine either way anyway.

The Set() and Init() functions are the only ways to change the global map, and both are using the same mutex in to synchronize the access to the map. They are also using the Write() function in order to set the static shared variables, that will insert the appropriate memory barriers.


Related Reading


More Insights






Currently we allow the following HTML tags in comments:

Single tags

These tags can be used alone and don't need an ending tag.

<br> Defines a single line break

<hr> Defines a horizontal line

Matching tags

These require an ending tag - e.g. <i>italic text</i>

<a> Defines an anchor

<b> Defines bold text

<big> Defines big text

<blockquote> Defines a long quotation

<caption> Defines a table caption

<cite> Defines a citation

<code> Defines computer code text

<em> Defines emphasized text

<fieldset> Defines a border around elements in a form

<h1> This is heading 1

<h2> This is heading 2

<h3> This is heading 3

<h4> This is heading 4

<h5> This is heading 5

<h6> This is heading 6

<i> Defines italic text

<p> Defines a paragraph

<pre> Defines preformatted text

<q> Defines a short quotation

<samp> Defines sample computer code text

<small> Defines small text

<span> Defines a section in a document

<s> Defines strikethrough text

<strike> Defines strikethrough text

<strong> Defines strong text

<sub> Defines subscripted text

<sup> Defines superscripted text

<u> Defines underlined text

Dr. Dobb's encourages readers to engage in spirited, healthy debate, including taking us to task. However, Dr. Dobb's moderates all comments posted to our site, and reserves the right to modify or remove any content that it determines to be derogatory, offensive, inflammatory, vulgar, irrelevant/off-topic, racist or obvious marketing or spam. Dr. Dobb's further reserves the right to disable the profile of any commenter participating in said activities.

 
Disqus Tips To upload an avatar photo, first complete your Disqus profile. | View the list of supported HTML tags you can use to style comments. | Please read our commenting policy.
 

Video