logger: enable the use of spdlog static loggers

[n-eiling]

I would like to start a discussion about enabling or even completely refactor VILLAS to use spdlogs macros for logging. See https://github.com/gabime/spdlog/wiki/1.-QuickStart#logging-macros for details.

Benefits would be:

• Enabling logging in real-time / performance critical paths without any overhead if the logging level is disabled (If log level is set at compile time)
• Logging including filename, line numbers and function name (relies on gcc/clang extensions, but shouldn't break things when they are not present)
• No need to pass loggers around classes or keep them in member variables. We'd loose the information stored in the logger name - but I would argue this is redundant with filename in the logging output. Filename are much more helpful actually.

Disadvantages:

• "ugly" macros. I would probably redefine them as something shorter. LOG_DBG for example.

Example of how this would look like:

    if (c.interrupts > 1) {
      SPDLOG_WARN("Missed {} interrupts", c.interrupts - 1);
    }

    SPDLOG_TRACE("bytes: {}, intrs: {}, bds: {}", c.bytes, c.interrupts, c.bds);

Output:

16:43:09 149683 trace: Read from stream and write to address 15:0x40141000 (villas-fpga-ctrl.cpp:143)
16:43:09 149683 trace: bytes: 2, intrs: 1, bds: 1 (villas-fpga-ctrl.cpp:153)

[pjungkamp]

Review

Since you want the compiled in log level to be chosen at build-time I'd prefer the SPDLOG_ACTIVE_LEVEL to be defined by CMake.

I can definitely get behind the possibility to reduce the runtime overhead of logging.
And I'm also not too fond of the inherited Logger objects.

Considering Macros

I'm also considering redefining the SPDLOG_* macros in every .cpp file where they are used.

#define NODE_WARN(...) SPDLOG_WARN("node: " __VA_ARGS__)

This is the way Linux Kernel Modules often add their prefix to log messages.

Considering variadic constexpr inline functions

I personally really don't like the C preprocessor. C++ allows us to write e.g. if constexpr constructs to exclude the logging code at compile time without macro hacks. We should also evaluate these before committing to macros.

Conclusion

I'm really not sure what the best way to integrate the compile time switch for logging would be.

[n-eiling]

I agree that it should be defined in cmake. I just wanted to start a discussion before I invest too much dev time into this.

Prefixing log messages in not necessary though, as using the macros already implicitly give us the information about filename and even function from which we log. However, this only works when using the spdlog macros and not in the static spdlog loggers (e.g., spdlog::warn() does not allow logging the filename, but SPDLOG_WARN() does).

The macros are defined as:

#define SPDLOG_LOGGER_CALL(logger, level, ...) (logger)->log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, level, __VA_ARGS__)

#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_DEBUG
#define SPDLOG_LOGGER_DEBUG(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::debug, __VA_ARGS__)
#define SPDLOG_DEBUG(...) SPDLOG_LOGGER_DEBUG(spdlog::default_logger_raw(), __VA_ARGS__)
#else
#define SPDLOG_LOGGER_DEBUG(logger, ...) (void)0
#define SPDLOG_DEBUG(...) (void)0
#endif

I don't really mind if you want to replace the preprocessor if with a if testing a costexpr, but we cannot get rid of the macro because with need to insert __FILE__, __LINE__, and __FUNCTION__ at preprocessor time.

[stv0g]

I am strongly against this. We would loose important context by limiting us to a single logging instance. E.g. the name of a node is also part of some loggers. So if we remove the logger name we dont know which node instance produced a certain message.

Filename and line information is alao nothing I believe we should expose to the user. For debugging info, it could be nice. But we can still do this with macros and keeping individual logging instances.

Furthermore, VILLASnode has some advanced ways of filtering logs based on the logger name. E.g. showing only logs of the memory management or disabling those.

I dont see good enough arguments for making such a large change to the codebase.

Do we have a use case for the real-time critial path where a  few cycles matter? Branch prediction is to iur favour here and I think its a cost we can take.

[n-eiling]

I am strongly against this. We would loose important context by limiting us to a single logging instance. E.g. the name of a node is also part of some loggers. So if we remove the logger name we dont know which node instance produced a certain message.
Filename and line information is alao nothing I believe we should expose to the user. For debugging info, it could be nice. But we can still do this with macros and keeping individual logging instances.
Furthermore, VILLASnode has some advanced ways of filtering logs based on the logger name. E.g. showing only logs of the memory management or disabling those.

We don't need multiple logger instances for this though. We could add a prefix for info, warn and error and use filename and line infos for higher log level. This would be the best of both worlds, right?
Is there another good reason to have multiple instances? We don't use different sinks - I have not used the filtering features and I believe the one time I tried, it didn't work properly (I think because the logger isn't created properly in VILLASfpga). Does it require having multiple instances?
Also I would even disagree that we shouldn't expose line infos to users, because it would be pretty helpful for getting better issues.

Do we have a use case for the real-time critial path where a few cycles matter? Branch prediction is to iur favour here and I think its a cost we can take.

I haven't done any measurements, but I believe writing to stdout or a file is more than a few cycles. We could also improve this by using spdlogs asynchronous loggers though.

[stv0g]

We are using multiple sinks for Syslog and logging to files:

• Stdout
• Syslog:

  common/lib/log.cpp

  Line 52 in 3a66d8f

  sinks = std::make_shared<DistSink::element_type>();

• File:

  common/lib/log.cpp

  Line 118 in 3a66d8f

  auto sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(path);

Expressions are applying different log levels based on the name of the logger. If we have a single logger instance, that would not be possible anymore. I find it pretty useful to selectively log/debug certain areas of the code (e.g. memory management or hooks only).

My comment about branch prediction was not about the actual printing to stdout but only to the evaluation of the condition if a logging statement should be emitted or not (comparing the log level).

I think we also have support for multiple debug (verbosity) levels, to differentiate between more inmportant and less important debugging info.

How about if we only print file/line/function info when the debug level is active?

I really tried hard to keep the log messages concise and not to overload the user with to may details. I fear that the log lines will become really long and users stop reading the logs carefully.

[n-eiling]

OK so we could do something like this:

#define VILLAS_LOG(module, level, ...) if (level >= spdlog::info) { \
                                         villas::Log::get(module)->log(level, __VA_ARGS__) \
                                       } else { \
                                         SPDLOG_LOGGER_CALL(villas::Log::get(module), level, __VA_ARGS__) \
                                       }

and then in the modules

#include "log.hpp"
#define FPGA_LOG(...) VILLAS_LOG("fpga", __VA_ARGS__)

We could get even more evil with macro magic. But I guess we don't want to do that.

[stv0g]

I don't know if we really want to call Log::get() in every logging statement? I guess this boils down to a lookup in a std::map?

Can we pass the logger instance here directly?

[n-eiling]

Having to handle these logger instances is one thing I would like to avoid in any future change. I feel like this leads to people avoiding logging because it is cumbersome to pass a logger to every (new) place it is needed. Also there are a few places where loggers are named non-intuitively or classes using the wrong instance (e.g. of a super class).
I'm now thinking if it might not be better to reimplement your filtering in villas::Log and use a single spdlog instance. villas::Log could identify modules based on their filename or something similar.

Personally, I don't use filtering (is @stv0g the only one who uses it?). I would rather log to a file and search/filter using Linux tools. So to me, having to handle logger instances is not worth the filtering capability. (And I assume here from the previous discussion that this is the only benefit separate loggers have).
Then again, I don't use Node that much, so I might not have a good picture of our needs.