Improving Print Logging with Line Pos Info & Modern C++

Table of Contents

No matter how proficient you are, I think, you might still use one of the primary methods of debugging: trace values using printf, TRACE, outputDebugString, etc… and then scan the output while debugging.

Adding information about the line number and the file where the log message comes from is a very efficient method that might save you a lot of time. In this post, I’ll describe one trick that is especially useful in Visual Studio but might also help in other IDE/compilers.

I’ll also show you how modern C++ and C++20 make code nicer.

The Trick

When you’re debugging C++ code, it’s very convenient to output values to console or the output window and scan the log. As simple as:

std::cout << "my val: " << val << '\n';

You can easily enhance this technique by adding LINE and FILE information. That way you’ll see the source of that message. Which might be very handy when you scan lots of logs.

In Visual Studio, there’s a trick that allows you to move quickly from the debug output window to a particular line of code.

All you have to do is to use the following format:

"%s(%d): %s", file, line, message

For example:

myfile.cpp(32) : Hello World

You can now double-click on the line in VS output window, and immediately VS opens myfile.cpp at line 32. See below for a file called DebuggingTipsSamples.cpp:

Why is it so important? In my case, I’ve lost a lot of time when I tried to look for the origin of some log output. When I see a message, I copy it, search the solution, and then usually after scrolling around I finally get to the right line of code. You cannot beat this double-clicking approach, which is much more efficient!

Now that you know the proper format of the message, how do you use it in the code? Let’s go step by step.

We’ll implement this code with “standard” C++, then move to modern C++ and finally see what’s coming with C++20.

Standard C++ for Visual Studio & Windows

For VS, first of all, you need to output the message using OutputDebugString (Win specific function):

OutputDebugString("myfile.cpp(32) : super");

Secondly, it’s better to wrap the above function with a trace/log macro:

#define MY_TRACE(msg, ...) \
    MyTrace(__LINE__, __FILE__, msg, __VA_ARGS__)

You can use it in the following way:

MY_TRACE("hello world %d", myVar);

The above code calls the MyTrace function that internally calls OutputDebugString.

Why a macro? It’s for convenience. Otherwise, we would have to pass the line number and the filename manually. File and Line cannot be fetched inside MyTrace because it would always point to the source code where MyTrace is implemented – not the code that calls it.

What are __FILE__ and __LINE__? In Visual Studio (see msdn), those are predefined macros that can be used in your code. As the name suggest they expand into the filename of the source code and the exact line in a given translation unit. To control the __FILE__ macro you can use the compiler option /FC. The option makes filenames longer (full path), or shorter (relative to the solution dir). Please note that /FC is implied when using Edit and Continue.

Please note that __FILE__ and __LINE__ are also specified by the standard, so other compilers should also implement it. See in 19.8 Predefined macro names .

Same goes for __VA_ARGS__: see 19.3 Macro replacement - cpp.replace

And here’s the implementation of MyTrace:

void MyTrace(int line, const char *fileName, const char *msg, ...) {
    va_list args;
    char buffer[256] = { 0 };
    sprintf_s(buffer, sizeof(buffer), "%s(%d) : ", fileName, line);
    OutputDebugString(buffer);

    // retrieve the variable arguments
    va_start(args, msg);
    vsprintf_s(buffer, msg, args);
    OutputDebugString(buffer);
    va_end(args);
}

But macros are not nice… we have also those C-style va_start methods… can we use something else instead?

Let’s see what how can we use modern C++ here

Variadic Templates to the Rescue!

MyTrace supports a variable number of arguments… but we’re using va_start/va_end technique which scans the arguments at runtime… but how about compile time?

In C++17 we can leverage fold expression and use the following code:

#define MY_TRACE_TMP(...) MyTraceImplTmp(__LINE__, __FILE__, __VA_ARGS__)

template <typename ...Args>
void MyTraceImplTmp(int line, const char* fileName, Args&& ...args) {
    std::ostringstream stream;
    stream << fileName << "(" << line << ") : ";
    (stream << ... << std::forward<Args>(args)) << '\n';

    OutputDebugString(stream.str().c_str());
}

// use like:
MY_TRACE_TMP("hello world! ", 10, ", ", 42);

The above code takes a variable number of arguments and uses ostringstream to build a single string. Then the string goes to OutputDebugString.

This is only a basic implementation, and maybe not perfect. If you want you can experiment with the logging style and even try with a fully compile-time approach.

There are also other libs that could help here: for example {fmt} or pprint - by J. Galowicz.

C++20 and No Macros?

During the last ISO meeting, the committee accepted std::source_location into C++20!

C++ Extensions for Library Fundamentals, Version 2 - 14.1 Class source_location

This new library type is declared as follows:

struct source_location {
    static constexpr source_location current() noexcept;
    constexpr source_location() noexcept;
    constexpr uint_least32_t line() const noexcept;
    constexpr uint_least32_t column() const noexcept;
    constexpr const char* file_name() const noexcept;
    constexpr const char* function_name() const noexcept;
};

And here’s a basic example, adapted from cppreference/source_location:

#include <iostream>
#include <string_view>
#include <experimental/source_location>

using namespace std;
using namespace std::experimental; 

void log(const string_view& message, 
      const source_location& location = source_location::current()) {
    std::cout << "info:"
              << location.file_name() << ":"
              << location.line() << " "
              << location.function_name() << " "
              << message << '\n';         
}

int main() {
    log("Hello world!");

    // another log
    log("super extra!");
}

We can rewrite or log example into

template <typename ...Args>
void TraceLoc(const source_location& location, Args&& ...args) {
    std::ostringstream stream;
    stream << location.file_name() << "(" << location.line() << ") : ";
    (stream << ... << std::forward<Args>(args)) << '\n';

    std::cout << stream.str();
}

Play with the code @Coliru

(as of March 2021, source_location is available in VS 2019 16.10, and GCC 11)

Now, rather than using __FILE__ and __LINE__ we have a Standard Library object that wraps all the useful information.

We can also throw some std::format:

template <typename ...Args>
void TraceLoc(const std::source_location& loc, Args&& ...args) {
	auto str = fmt::format("{}({}): {}\n", loc.file_name(), loc.line(), 
                            fmt::format(std::forward<Args>(args)...));

	std::cout << str;
}

TraceLoc(std::source_location::current(), "{}, {}, {}", "hello world", 10, 42);

(Please replace fmt:: with std:: once std::format is available in our compilers :))

And play with the code @Compiler Explorer

Unfortunately, we cannot move the source location argument after variadic args… so we still have to use macros to hide it.

Do you know how to fix it? so we can use a default argument at the end?

Ideally:

template <typename ...Args>
void TraceLoc(Args&& ...args, 
              const source_location& location = source_location::current())
{
   // ...
}

We can wait for Non-terminal variadic template parameters @cor3ntin blog (hopefully this feature will be considered for C++23).

There’s also one technique that we can use, suggested by a comment where we can use a Logger object with a constructor taking source location… I’ll show that trick next time.

Additional Tools

In Visual Studio it’s also possible to use Trace Points (Thanks xtofl for mentioning it in a comment!).

Basically, when you set a breakpoint, you can select it and select “Actions” and write an expression which is evaluated and send to the Debugger output window. Make sure to set “continue execution”. This technique might be handy when you iterate through large collections and you don’t want to manually step each iteration. One disadvantage is that since it’s not called directly from code, it might slow down the application.

See a screenshot from a simple debugging session:

And more information:

A similar feature is also available in GDB - Tracepoints (Debugging with GDB)

Summary

In this article, I showed a useful technique that might enhance simple printf-style debugging and logging.

Initially, we took a popular code that is mostly C-style and then we tried to update it with modern C++. The first thing was to use variadic template arguments. That way we can scan the input params at compile time, rather than use va_start/va_end C runtime functions. The next step was to look at the future implementation of source_location a new type that will come in C++20.

With source_location we could skip using __FILE__ and __LINE__ predefined macros, but still, the logging macro (#define LOG(...)) is helpful as it can hide a default parameter with the location info.

code from the article: @github.

How about your compiler/IDE? Do you use such line/pos functionality as well? Maybe your logging library already contains such improvements?