Refactor comm functionality with spdlog

[craffael]

This PR is intended to eventually replace all the functionality contained in the lf/base/comm.h header with viable alternatives.

So far only a small subset of all comm.h usages has been refactored in order to test the new approach and discuss it's advantages and disadvantages. So far I've encountered two main use cases of the comm.h: 1) There are functions such as PrintInfo(std::ostream&, const Mesh&) which will print some information about an object (here mesh) to a stream. These functions are directly called from the "user", i.e. there are multiple examples and tests that call PrintInfo(std::ostream&, const Mesh&). Usually these PrintInfo functions print the information with varying degrees of detail depending on a global variable that has been declared with ADD_OPTION from comm.h. I.e. one can control the degree of detail by setting an additional global variable (here lf::mesh::utils::printinfo_ctrl). 2) Sometimes LehrFEM++ will log additional information to std::cout on its own (e.g. lf::assemble::AssembleMatrixLocally()). The level of detail is here also controlled by a global variable (ass_mat_dbg_ctrl) which has been declared with ADD_OPTION from comm.h.

In both cases there are global variables defined with the help of comm.h which provides the following advantages:

• The values of the static variables can be modified e.g. through boost program options. As far as I've seen it, this is only used for case 2) above. For usages of type 1), the corresponding control variables seem to be set directly by the calling code.

Based on these observations, I've refactored the two use cases from above differently:

1) PrintInfo

It seems, that these functions are always directly called from the "end-user" code and that the level of detail is also directly set in the calling code (and not via command line arguments or config files). Therefore I've removed the corresponding global variables completly and instead added a new argument to the function. E.g. instead of

void PrintInfo(const lf::mesh::Mesh& mesh, std::ostream& o);

the signature is now

void PrintInfo(std::ostream& o, const lf::mesh::Mesh& mesh, int ctrl = 100);

I think this is easier to understand, because the behavior of the PrintInfo() function does not depend on a hidden state variable (printinfo_ctrl). Moreover, it allows us to get rid of the comm.h functionality.

This refactoring was applied already to the following methods:

• void PrintInfo(const lf::mesh::Mesh& mesh, std::ostream& o) (lib/lf/mesh/utils/print_info.h)
• void PrintInfo(const lf::mesh::Entity& e, std::ostream& stream) (lib/lf/mesh/utils/print_info.h)
• virtual std::ostream& MeshHierarchy::PrintInfo(std::ostream &o) const (lib/lf/refinement/mesh_hierarchy.h)

Comparison to existing approach

• The new approach makes it a bit harder to change the level of detail via command line arguments. If this is required, the calling code will have to parse the command line arguments (e.g. with boost program options) and forward them to the PrintInfo call.
• The new approach is much more straightforward because the PrintInfo methods do not rely on a hidden state (stored in a global variable). Instead the function signature clearly describes all the required inputs.

1.1) Possible alternative

At the moment the PrintInfo methods output their data directly to a std::ostream. This is not a problem as long as the PrintInfo methods are always called from the user. However, if LehrFEM++ routines (e.g. AssembleMatrixLocally()) want to call PrintInfo methods to log additional information, we have a bit of a problem because spdlog uses the fmt library (it would be possible to make them work together but it's not so easy). So it would be worth a thought to modify the PrintInfo methods so that they accept spdlog::logger objects:

void PrintInfo(spdlog::logger&, const lf::mesh::Mesh& mesh);

I guess the best way would then be that the PrintInfo method decides itself on what log levels it wants to output what information (see section 2) below). But this is much less intuitive than just specifying the level as an additional parameter. Also if we pass a spdlog::logger to the PrintInfo() we will only have six different logging levels and not "inifinitely many" (see below).

1.2) Note about operator<<

Besides the PrintInfo methods, there are also many std::ostream& operator<<(std::ostream&,...) overloads present in the LehrFEM++ code. Some of them also rely on global state variables to control the level of detail. Sometimes they also simply call a corresponding PrintInfo() method/function. The problem with the operator<< overloads is, that they take exactly two arguments (namely the two operands) and we cannot add another argument to control the level of detail. But of course these operators can be transformed into a PrintInfo method without problems.

Therefore, I've decided to rewrite these operator overloads so that they return the absolute minimum of information that may be relevant to the user (e.g. the operator<< of base::RefEl will output the name of the Reference Element). I suggest that all functionality which writes more extensive output, be moved to a PrintInfo method/function (where we can control the amount of information with an additional parameter). Existing code, which relies on operator<<, is rewritten to use PrintInfo().

2) LehrFEM++ logs debug information

For this scenario, I've replaced the comm.h functionality with an spdlog logger. The general idea is, that every method/class that wants to log additional information declares a publicly accessible variable of type std::shared_ptr<spdlog::logger> (for classes a static public member, for functions a global variable in the namespace) and initializes it with a call to spdlog::stdout_color_mt(). In this way the logger will by default write to standard output and the default log level is info. I.e. only log messages with level >= info are output to the console.

E.g. instead of

// header file:
extern unsigned int ass_mat_dbg_ctrl;

// source file:
ADDOPTION(ass_mat_dbg_ctrl, Assembly_ctrl,
          "Debugging output control for AssembleMatrixLocally()");

we have now

// header file:
extern std::shared_ptr<spdlog::logger> assemble_matrix_logger;

// source file:
std::shared_ptr<spdlog::logger> assemble_matrix_logger =
    spdlog::stdout_color_mt("lf::assemble::assemble_matrix_logger");

In spdlog there are six log levels and I suggest that we use them as follows (ordered by importance): level	description
Critical	Coarsest level, use it for logging additional information just before the program aborts. (e.g. before an assert fails)
Error	For logging information related to a recoverable error. E.g. when an exception is thrown.
Warn	Warn the user when something may not work as expected.
Info	Inform the user about something important. Use this only if it adds a lot of value for the user. We don't want to clutter the output uneccessarily.
Debug	Additional information that helps in debugging a problem.
Trace	Even more detailed information for debugging a problem.

By default all log messages with level Info or higher are output to the standard output. Every code that uses LehrFEM++ will see these messages. Therefore use these log levels carefully! Almost all log messages in LehrFEM++ should have the Debug or Trace level.

This refactoring was applied already to the following methods:

• lf::assemble::AssembleMatrixLocally() (lib/lf/assemble/assembler.h). Check e.g. examples/assemble/Dirichlet_Laplacian_demo.cc to see the new output.

Comparison to existing approach

• The new approach is much more flexible in terms of the output format. SPDLog can also log into a file or into syslog, etc...
• The new approach is less flexible in term of "logging levels": SPDLog only knows 6 log levels. The old approach allowed (almost) infinitely many log levels and they could differ from method to method. Especially the SWITCHEDSTATEMENT functionality from comm.h cannot be reproduced with spdlog. However, this can also be an advantage because the user only every has to decide between six options whereas in the old approach, he had to check for every method/class what options were possible.
• The old approach allowed the user to set the values of the ctrl variable via command line arguments. With SPDLog the user can load the log levels for each logger also either via command line arguments or via environment variables. Currently this is not possible because hunter has an outdated version of spdlog, but once https://github.com/cpp-pm/hunter/pull/260 is resolved, this is no problem.
• In the old approach the user could also set the ctrl variable directly in the code. This is also possible with spdlog: lf::assemble::assemble_matrix_logger->set_level(spdlog::level::trace);
• The new approach allows us to remove all logging statements that are below a given level at compile time to optimize runtime performance. At the moment all Log statements of level debug and trace are removed at compile time for Release builds. For Debug builds, nothing is removed.
• The old approach relied on the std::streams api for formatting. SPDLog relies on the fmt library. I like fmt a lot :)
• spdlog adds additional information to the output: the date and time of the log entry, the name of the logger and the location where it was logged. But this can also be configured.

Next Steps:

@hiptmair I suggest you take a look at the changed files of this PR in order to understand the consequences. Maybe we should the skype some time to discuss the implementation...

[hiptmair]

Ad PrintInfo(): Adding an argument controlling the level of detail is a good idea. I prefer passing an ostream & argument, because this leaves more flexibility. I am wondering whether an output stream can be connected with a logger.

[hiptmair]

Concerning operator <<: ok that it outputs only the most basic information. Alternative: Every class with output functionality has a logger attached to it. This logger stores a log level and the output operator is also controlled by that log level. Is this possible?

[craffael]

I am wondering whether an output stream can be connected with a logger.

Yeah it's possible, but not very elegant:

std::stringstream stream;
mat.PrintInfo(stream);
logger->log(spdlog::level::trace, stream.str());

[craffael]

Alternative: Every class with output functionality has a logger attached to it. This logger stores a log level and the output operator is also controlled by that log level. Is this possible?

Yeah that would be possible, one can read the log level of a logger. But I think it can make the code quite hard to understand and argue about. I mean as long as operator<< is only used by the end user it's not so much of a problem. But if operator<< is e.g. used by the AssembleMatrixLocally() method to log information about the assembly and the user decides to use operator<< somewhere else in another context it can get confusing quite fast. For example, if the user wants to change the level of detail of his output, he may change the log level, but then suddendly also the output of AssembleMatrixLocally() grows a lot. I think the underlying problem is, that if AssembleMatrixLocally() calls operator<< internally, then it expects to behave operator<< in some specific way. If we allow the user to change the way that operator<< works, then AssembleMatrixLocally is "screwed".

[craffael]

@hiptmair I'm more or less done :) I've been able to completly remove the lf::base::comm functionality from LehrFEM++. Do you want to have a look at it before I merge it into master?

Some of the bigger changes that have happened:

• MeshHierarchy had a lot of log-flags with which one could fine-tune the logging. These log statements have now either level Trace or Debug.
• I Introduced a new class LineFeedFormatter which prints multiline log messages with the right indentation.
• I've added a documentation page about logging and debug output to the doxygen documentation and i've updated the contribution guide.

[hiptmair]

I have browsed some of the LehrFEM++ sources and at how logging is implemented now:

• There should be a dedicated example demonstrating the logging facilities. It could perform the local refinement of a simple mesh and do so with different logging levels activated. Different formatting and output options could be used.
• Are the output_ctrl_ static variables still needed?
• The availability of a logger object for a free function/class should be mentioned in the documentation of that function.

[craffael]

* The availability of a logger object for a free function/class should be mentioned in the documentation of that function.

For free functions I agree. For classes the logger is anyway a public static member of the class and gets an entry in the documentation, see e.g. lf::mesh::hybrid2d::Mesh. Do you think should mention the logger also in the documentation of the class itself?

[craffael]

Okay I've mostly followed your suggestions: 1) there is now an example examples/logger/mesh_hierarchy_demo.cc with which one can see how spdlog::loggers can be used to read log levels from environment variables, command line and how output can be redirected to a file. 2) I replaced all outputctrl variables that I could find. I've missed some last time because they were not declared using the functionality of comm.h... 3) All free functions that use a logger mention this in their documentation. For classes I have not yet updated the documentation because the logger already shows up as a static public member variable in the doxygen documentation. But I can also add a paragraph about the logger in the main documentation of these classes?

[craffael]

@hiptmair What do you think about the this PR?

[hiptmair]

Please merge. Everything looks fine.