Logging under MPI, Meson and Gtest

There cannot be good software without an automated and reproducible build system, better if it comes with tests. I wrote before on how to achieve that with CMake and Catch2. Today I’m going to experiment with Meson and Gtest, and the example is going to be less trivial than the previous time.

Digression: we need a logger!

I deal with quite a bit of scientific software, and unfortunately most of us scientist suffer from the “Works for me” syndrome.

  • Doesn’t build? Works for me!
  • Can’t find the dependency? Works for me!
  • It’s an unmodifiable mess of code? Works for me!
  • The only variable names are i, j, k and temp? Works for me!
  • No tests, linter went on strike and average line length is 263? Works for me!

Among the bad habits that us scientist really cannot get rid of, and that severely impacts reusing and composing scientific code, is constantly breaking the rule of silence: polluting the standard output with stuff that is not output and the standard error with stuff that is not errors. Full disclosure, I’ve never abstained from the practice of debugging code by print / printf / cout-ing numbered bestemmie and checking how many would actually print out before a crash. That said, I most often remove blasphemy once the bug has been squashed.

I recently found myself having to collect data from the output of a simulation, except the stdout was a huge mess of timing information, debugging prints, linear solver parameters and random other crap.

In the last ten+ years I have been spoiled by the vastity of Python’s standard library and by the ease of calling in an external dependency1, so I was disappointed by the lack of a more or less standard way of logging in C++, especially one that can work under MPI in parallel simulations. It’s time to code one.

MPILogger

The main requirements of my logger are that it support the usual logging levels, be C++-idiomatic, allow to seamlessly print either to screen or to file and be MPI-compatible. As I understand that the general trend in C++ is to move away from macros, it should also be pure code, and leverage on all the goodies of C++20.

First of all I defined the levels, and the way they should be converted to string (reflection2, I’m waiting for you!)

// part of mpilogger.hpp
#include <ostream>

enum LogLevel { CRITICAL, ERROR, WARNING, INFO, DEBUG };

// This is damn boilerplate!
std::ostream & operator<<(std::ostream & os, const LogLevel ll) {
    switch(ll) {
        case(CRITICAL): os << "CRITICAL"; break;
        case(ERROR): os << "ERROR"; break;
        case(WARNING): os << "WARNING"; break;
        case(INFO): os << "INFO"; break;
        case(DEBUG): os << "DEBUG"; break;
    }
    return os;
}

As for the idiomaticity, I want to be able to redirect stuff directly into the logger, setting the level in the process, à la logger << LEVEL << stuff;. After a first implementation where I was constantly blocking and unblocking a single stream, I opted for a solution with two different streams, one of which is constantly blocked.

// part of mpilogger.hpp
#include <filesystem>
#include <fstream>
#include <functional>
#include <iostream>
#include <ostream>
#include <string>

#include <mpi.h>

class Logger {
    private:
    // Single reference for both std::ostream and std::ofstream
    // Ref: (https://stackoverflow.com/questions/9459136/
    //       how-can-i-make-an-ostream-reference-an-ofstream-c)
    std::ofstream filestream;
    std::ofstream black_hole{};

    public:
    Logger(
            LogLevel level,
            const std::string & name,
            std::ostream & os = std::cout) :
        filestream(), level{ level }, os{ os }, name{ name }
    { black_hole.setstate(std::ios::badbit); };
    Logger(
            LogLevel level,
            const std::string & name,
            const std::filesystem::path file_path) :
        filestream{ file_path, std::ios::out },
        level{ level },
        os{ this->filestream },
        name{ name }
    { black_hole.setstate(std::ios::badbit); };

    const LogLevel level;
    std::ostream & os [[maybe_unused]];
    std::string name;

    std::ostream & operator<< (const LogLevel _level) {
        int rank;
        MPI_Comm_rank(MPI_COMM_WORLD, &rank);
        if (rank != 0)
            return black_hole;
        if (_level <= level) {
            os << "[" << _level << "][" << name << "]: ";
        }
        return os;
    }
};

The two constructors take care of when we want to print to screen (or to a stringstream, for what matters), or if we want to log to a file. I opted to also mandate that the logger be initialised with a name, kind of mimicking what Python’s Logger does.

The logger is instantiated with a Level, meaning that only that level and higher priority levels will be logged while lower priority messages will be suppressed. The logic for this is encoded in the operator<< overload. According to the semantics detailed above, the logger must receive a Level followed by the actual message that we want to log, therefore we can limit ourselves to overloading for a Level and returning a good or a bad stream depending on weather the message should be logged or suppressed. This is decided in two steps that should hopefully help the branch predictor to make better optimisations: we first check for the root MPI node and then for the level.

Building with Meson

C++ tooling is somewhat of a relic and hasn’t really caught up with the sleek experience of package managers and toolchains of more modern languages. This is not really a critique but rather stating a fact, and the very existence of pip, npm, cargo is due to standing on the shoulders of giants, or at least having those giants felt enough pain that they came up with a solution.

Meson is one of the latest attempts to bring sanity to the C++ ecosystem…and after using it for a couple of days I have to say that it is a pretty good one, too!

I started by init-iating a new C++ library project with

mkdir mpilogger && cd mpilogger
meson init --language cpp --type library --build

This is enough to take care of a decent amount of boilerplate that is typically manual when using CMake, including scaffolding for .hpp, .cpp and a bare bone test file. The actual build file is very readable and concise.

# meson.build
project('mpilogger', 'cpp',
  version : '0.1',
  default_options : [
    'warning_level=3', 'cpp_std=c++20', 'default_library=static'
  ]
)

# These arguments are only used to build the shared library
# not the executables that use the library.
lib_args = ['-DBUILDING_MPILOGGER']
mpi_dep = dependency('mpi', language: 'cpp')

shlib = library('mpilogger', 'mpilogger.cpp',
  install : true,
  cpp_args : lib_args,
  gnu_symbol_visibility : 'hidden',
  dependencies: mpi_dep
)

gtest_dep = dependency('gtest', main : false)

test_exe = executable('mpilogger_test', 'mpilogger_test.cpp',
  link_with : shlib,
  dependencies: [gtest_dep, mpi_dep]
)
test('mpilogger', test_exe)

add_test_setup('mpirun', exe_wrapper: ['mpirun', '-n', '2'], is_default: true)

# Make this library usable as a Meson subproject.
mpilogger_dep = declare_dependency(
  include_directories: include_directories('.'),
  link_with : shlib)

# Make this library usable from the system's
# package manager.
install_headers('mpilogger.hpp', subdir : 'mpilogger')

pkg_mod = import('pkgconfig')
pkg_mod.generate(
  name : 'mpilogger',
  filebase : 'mpilogger',
  description : 'Meson sample project.',
  subdirs : 'mpilogger',
  libraries : shlib,
  version : '0.1',
)

This is almost vanilla as returned by the init template. However, since we need to work with MPI we need to add the relevant dependency. Mind that since MPI works with both C and C++, it is important to specify that we want to work in C++ as such

mpi_dep = dependency('mpi', language: 'cpp')

I learnt this the hard way battling linking errors, and finally comparing mpic++ -showme against the compilation command generated by meson I solved the mystery. This is clearly explained in the documentation.

Another change is that we want to generate a static library, as the test that will be the focus of the next section would not compile otherwise. I didn’t quite understand why, but I suspect it is because it is practically a header-only library (even though in the final version I moved the printing of the Enum into a separate .cpp).

With these two changes the library part of the job is done. All there is left to do is

# in project root
meson compile -C build

Testing with Gtest

I had never used GoogleTest (a.k.a. Gtest) before. One positive feeling I have is that it takes less time to compile than Catch2, although I only had very limited experience with either framework, and it is totally possible that the reason why it took forever to compile tests using Catch2 be that I was using CMake.

The following code tests that only the root node logs out anything at all.

// mpilogger_test.cpp
#include <mpilogger.hpp>
#include <iostream>
#include <sstream>
#include <gtest/gtest.h>


TEST(TestMpiLogger, CheckDirect) {
    // GIVEN an MPI logger.
    // WHEN a message is logged to its info handle.
    // THEN the stream in processes different from rank 0 is empty.
    std::stringstream ss;
    Logging::Logger logger{ Logging::LogLevel::INFO, "MAIN", ss };

    logger << Logging::LogLevel::INFO  << "my log" << std::endl;
    const std::string s{ ss.str() };
    std::cerr << s << std::endl;
    const size_t string_length{ s.size() };
    int rank;
    MPI_Comm_rank(MPI_COMM_WORLD, &rank);
    if (rank != 0)
        EXPECT_EQ(string_length, 0) << "Rank " << rank << ": " <<
            string_length;
    else
        EXPECT_GE(string_length, 0) << "Rank " << rank << ": " <<
            string_length;
}


int main(int argc, char* argv[]) {

    MPI_Init(&argc, &argv);
    int size;
    int rank;
    MPI_Comm_size(MPI_COMM_WORLD, &size);
    MPI_Comm_rank(MPI_COMM_WORLD, &rank);
    if (rank == 0)
        std::cerr << "Running tests on " << size << " processes." << std::endl;

    testing::InitGoogleTest(&argc, argv);
    int retcode{ RUN_ALL_TESTS() };

    if (rank == 0)
        std::cerr << "RETCODE: " <<retcode << std::endl;

    MPI_Finalize();
    return retcode;
}

One thing to notice is that I had to use a custom main other than the one provided by Gtest in order to initialise the MPI session. This is also reflected in the meson.build file above, where the Gtest dependency explicitly states no main:

gtest_dep = dependency('gtest', main : false)

Gtest is well integrated with Meson and Meson’s documentation is helpful regarding its use down to these subtleties.

It is now time to run the tests, and since this library is all about being MPI-compatible, we should run them with mpiurn to test a nontrivial case. This can be achieved by adding the line

add_test_setup('mpirun', exe_wrapper: ['mpirun', '-n', '2'], is_default: true)

in the meson.build file.

The test command within Meson, meson test, by default hides all output and logs it to a file within the build/ directory. I found it useful while setting up to use the verbose flag to have it printed out to screen:

# in project root
meson test -v -C build

Beware of a glibc bug

At this point everything is set up but I was still getting random failures from my test suite. The reason has nothing to do with the code, Meson or Gtest. There is a known bug in glibc (I’m running 2.38) that interferes with MPI. You can read about it here for the MPI side and here for the glibc side.

Conclusions

I’m very positively impressed by Meson. I got curious about it after noticing that Numpy and Scipy use it as their build system and now I can totally see why. The developer’s experience is way better than with CMake. I don’t have a strong opinion about Gtest yet. It definitely gets the job done, and fast at that, however playing a bit with its fixture feature felt a bit too implicit for my liking, and I wish there was a way to explicitly interact with the fixture object. I guess that’s the imprinting you get after using pytest for years.

The full project is available on Codeberg. If you would like to comment this post, you’re very welcome to do so at this Mastodon toot.

Update 2023-01-14: I pinned the verison of the library that this post refers to and added minor details about the Meson buildfile and mpirun.

  1. Modulo all the quirks of Python’s dependency system, incompatible versions, etc. ↩︎

  2. See reflexpr and this Stack Overflow question. I feel like this problem should have been solved a long time ago. ↩︎