Skip to content

Add full-featured logging system

Steffen Müthing requested to merge feature/logging-system into master

While working on some solver components of PDELab, I got (not for the first time) rather annoyed with the way we currently handle logging:

  • Logging in PDELab mostly consists of manually setting and tracking a verbose state and then writing code that checks that state before doing an often convoluted write with the verbose streams syntax of the standard library. Generating a single log message often spans three or four lines of code, drowning the actual program logic.
  • As changes to the standard library streams tend to be persistent, code has to be careful to save and restore the old stream state by instantiating a guard object.
  • In many places, your choice of logging targets includes just stdout, because logging happens to std::cout.
  • It is complicated to turn off logging for rank > 0 in parallel programs, and impossible to do more interesting stuff like logging to a rank-specific file.
  • It is difficult to locally change the logging verbosity for just one part of your program or even change where those messages get logged.
  • Adding metadata to the log messages is cumbersome (PDELab has log tags, but they need to be explicitly emitted as part of each log message).
  • It is impossible to configure the log output without changing the source code and recompiling.
  • It is very unclear what the verbosity levels mean.

Some of these problems can be worked around by using the debug streams from dune-common, but that still doesn't solve the more complicated problems listed above, most of all the very verbose stream syntax and the fact that the system relies on global stream singletons.

So I looked around a little for a better alternative and found spdlog, which seemed pretty nice, if a little heavyweight for our purposes (it's intended for application servers that generate tens of thousands of log messages per second across multiple threads). It also used the excellent {fmt} library for string formatting.

This MR takes {fmt} and builds a comprehensive logging framework on top of it. It has the following features:

  • There are a number of well-defined log levels given by the enumeration LogLevel.
  • Logging does not use the stream syntax of the standard library, but the powerful string formatting features of {fmt}, which uses the new style format string syntax from Python, e.g. "Hello, {}". This supports positional arguments and format specifiers, see documentation. Log messages are checked at compile time for correctness, which requires a user-defined string literal. A version of {fmt} looks likely to become part of C++2a.
  • Logging happens through lightweight Logger objects, which are cheap to construct and copy and have value semantics. Loggers filter messages at runtime based on their verbosity limit and are attached to exactly one backend doing the actual processing.
  • Log messages are formatted and packaged into a LogMessage instance, which provides additional metadata.
  • Log messages are persisted by Sinks. Multiple sinks can be connected to each backend, and one sink can serve multiple backends.
  • There is a central configuration store in the class Dune::PDELab::Logging. This store must be initialized before using the logging system and can be configured from an INI file.
  • Ignored log messages do not incur a lot of overhead (no function calls), and the actual expensive log message processing happens in non-inline code, avoiding local code bloat.
  • Console logging is deactivated by default for rank > 0.
  • As large parts of existing programs will still be logging to std::cout et. al., there is optional support for redirecting the C++ streams into the logging system.

Consider the following small example:

Dune::PDELab::Logging::init(mpi_helper.getCollectiveCommunication(), params.sub("logging"));

// Import the _fmt literal
using namespace Dune::Literals;

Dune::PDELab::log(Dune::PDELab::notice,"Starting program"_fmt); // logs to the default logger

auto newton_log = Dune::PDELab::logger("newton"); // gets a logger for the backend called "newton"
newton_log.setLevel(Dune::PDELab::trace);         // really log everything!
newton_log.debug("The answer is {:10}"_fmt,42);       // log with field width 10

// Creates a new logger from information in the parameter tree, defaults to a logger for backend
// "linsolve" if available, otherwise the default logger
auto component_log = Dune::PDELab::Logging::componentLogger(parameter_tree,"linsolve");

The general idea is to have each component store its own logger by value, which it either gets as an explicit constructor parameter or (preferred) from a call to Dune::PDELab::Logging::componentLogger() together with the ParameterTree. Your components take a ParameterTree, right? ;-)

class MyTimeStepper
{
  Logger _log;
  int _step = 0;

public:
  MyTimeStepper(const Dune::ParameterTree& config)
    : _log(Dune::PDELab::Logging::componentLogger(config,"timestep"))
  {}

  void apply()
  {
    _log.info("Start timestep {:4}"_fmt,_step);
    ...
    // log all stage-related messages with an additional indentation of 2
    auto stage_log = _log.indented(2);
    stage_log.detail("Start stage"_fmt);
    ...
  }
};

The configuration can typically all happen in an INI file:

[logging]
# makes the default backend write to stderr and the logfile
default.sinks = stderr, logfile
# new loggers created for the default backend will start at level debug
default.level = debug
# enable redirection of std streams to automatically created backends cout, cerr, clog
# log messages will have level notice
redirect = notice

[logging.sink]
# the stdout sink exists by default, here we change its output format
stdout.pattern = "[{paddedlevel}] [{logger}] {msg}"
# Mentioning a sink creates it automatically using the nested keys
logfile.type  = file-per-rank
logfile.file  = "logfile.txt"
logfile.level = detail

[logging.backend]
# creates a new backend called newton, which inherits the default configuration
newton = default

# creates and configures a new backend called linsolve
linsolve.extra_sinks = stdout
linsolve.level = info
linsolve.indent = 4

# makes a MyTimeStepper instance use the following logging configuration if passed
# the subtree "timestep"
[timestep]
log.level = detail

Current drawbacks are:

  • We cannot rely on {fmt} being available and optionally vendor it. That is no problem license-wise ({fmt} is BSD 2-clause), but we now need a Git submodule in dune-pdelab, which might trip up our users. I've made sure that CMake emits a very clear message with instructions on how to fix the problem.
  • The _fmt user-defined literal is a little unfortunate because it relies on a compiler extension to work, but this could be made conditional on compiler support if necessary. The big advantage of the literal is that it enables compile-time validation of the format string against its arguments. In C++20, we can switch to standard functionality again (or maybe even use stdlib functionality, as {fmt} stands a good chance of making it into the standard).
  • There is no way to completely elide the log calls at compile time the way the debug streams do.
  • The implementation and part of the interface is C++17.

Medium term, this might also go into dune-common if we can agree on it.

Edited by Steffen Müthing

Merge request reports