ScopeLogger

The RAII design pattern can be utilized to create simple and intuitive logging facilities, like the one we will present now. Through the useful macro LOG_FUNC, the proposed ScopeLogger will easily create function call graphs at run time, to allow easy debugging and tracking of program execution.

Here’s the implementation:

// ---- header ----

#include <string>

// Following macro is not entirely portable, but works in MSVS & GCC
#define LOG_FUNC ScopeLogger s##__LINE__(__FUNCTION__)

struct ScopeLogger {
        ScopeLogger (const std::string &str);
        ~ScopeLogger ();

    private:
        std::string indent (unsigned ind) const;

        static unsigned indent_;
        const std::string msg_;
};

// ---- source ----

#include <iostream>

unsigned ScopeLogger::indent_ = 0;

ScopeLogger::ScopeLogger (const std::string &str)
 : msg_(str) {
    std::cout << indent(indent_++) << "[+] " << msg_ << std::endl;
}

ScopeLogger::~ScopeLogger () {
    std::cout << indent(--indent_) << "[-] " << msg_ << std::endl;
}

std::string ScopeLogger::indent (unsigned ind) const {
    return std::string(ind<<1, ' ');
}

Note that, as commented above, the macro LOG_FUNC is not entirely portable; The usage of the non-standard pre-defined macro __FUNCTION__ is not guaranteed to work on every compiler, although Microsoft’s Visual Studio & GCC do support it. GCC also supports a __PRETTY_FUNCTION__ macro which can be even more useful.

The code can be extended further: extra functionality can be added to the ScopeLogger class if needed, and compile time reliance on _DEBUG can be added (to disable output in a release build, for example).

Here’s an example of the generated call graph:

antrikot:~/work/sandbox/log> ./scopelogger.out
[+] main
  [+] run
  [-] run
  [+] work
    [+] attempt
    [-] attempt
  [-] work
  [+] attempt
  [-] attempt
  [+] run
  [-] run
[-] main

Generated by the following code:

#include "scopelogger.h"

bool run () {
    LOG_FUNC;

    static unsigned num = 1;
    return num--;
}

void attempt () {
    LOG_FUNC;
}

bool work () {
    LOG_FUNC;

    static bool state = true;
    if (state)
        attempt();
    return state -= state;
}

int main () {
    LOG_FUNC;

    while (run())
        if (!work())
            attempt();

    return 0;
}

This example only illustrates how easy using this facility actually is, whilst the generated output is just priceless for debugging or understanding execution flow.

13 thoughts on “ScopeLogger

  1. Very interesting post. I think that such a component with little additional stuffs (like handling different levels, and different output means like standard output, standard error stream, files, being able to plug databases maybe, etc) could be of a great interest and be the ultimate boost.log library everybody wants :p

      1. Indeed, but it’s been in the “proposed” state for a long time. I don’t know when it’ll be reviewed and possibly accepted, and even if it’ll be.

  2. Hi Roman!

    I love the scoped logger. Your logger helped us in finding bugs in our software. It’s awesome.

    I know that the logger in this post is only a demo, but I would suggest another feature. The current logger prints to std::cout. I would like to be able to instantiate the logger with any object which supports the << operator. This way you can log into std::cerr, log4cpp or stringstream.

    Nadav

  3. Nice! As another quibble, I’d suggest branching the LOG_FUNC definition to be null if _DEBUG is not defined. Naturally the overhead of stream outputs can be prohibitively expensive in production builds.

  4. Roman – do you have an actual scenario where the point of leaving a function adds value? (I mean – why should the destructor be instrumented?)

    1. Well, apart from maintaining the correct indentation (decreasing the indent_ member), the destructor doesn’t do much.
      In my opinion it just makes it easier to identify call trees if we print where the function actually makes its exit, but we couldv’e spared it just as easily.

      Another thing we could use the destructor for is timing the execution time of every function, so we could print the time each function took in the destructor of this ScopeGuard (using something very similar to this).

      1. If we skip the point-of-exit tracing, then VS already has something similar, via tracepoints: create a brekpoint, right click and mark ‘when hit..’, then mark ‘print a message’ and specify $CALLSTACK.

        Pros: (1) involves intervention only in the lowest function you wish to trace – and not its entire potential callers tree (which can be unknown), (2) doesn’t require re-compilation.
        Cons: (1) cannot (AFAIK) route output to a file or anywhere outside the debugger windows, (2) involves an actual breakpoint, with a significant performance penalty if the tracepoint is hit often.

        Anyway, seems to me this is mainly a debugging facility: to collect trace info in the field you’d probably want crash dumps and stack walkers and an entirely different mess. So for just debugging, I think trace points might be an easier solution (in particular because you can’t know the full range of potential callers).

        1. Very nifty feature of VS, thanks for introducing it.
          You are essentially correct with your observation that this will probably be for light debugging purposes, or maybe statistical analysis of execution (for example, we could also create a timer and print its stats on return, to have the timing of each function).
          This approach is also pretty useful since it does not have to be an entirely compile time mechanism – we can set at least some of these printouts to be run-time dependant (perhaps printing only if the function took longer than it should have, or depending on environment setup, etc).
          I ofcourse agree that if hardcore debug is necessary, we’ll probably have to invoke more complex and sophisticated tools (be it gdb, totalview, VS debugger, ..).

  5. Very nice code.
    I’d say that the exit point is also important – you can log stuff about the return value of the function, maybe special case bools, ints and pointers.
    Also interesting is the addition of MT support.

    On another subject:
    In Python it’s a “standard exercise” to implement a trace function decorator. With little additional work, such a decorator can work & look just like your LOG_FUNC, except maybe making it a little more Pythonic.

  6. It could be interesting to implement the same scopelogger for tracing objects instead of functions :)

    1. Essentially, that’s what it is. It would work the same when used within member functions (even through LOG_FUNC).

      We could add a sort of a LOG_MEMFUN macro, so it would print the ‘this’ pointer as well, perhaps?

Leave a Reply

Your email address will not be published. Required fields are marked *