Optimizing away log function calls depending on global log level

Question

I am a member of a university team designing a nanosatellite. We decided to implement our own (more lite) logging library to use, instead of, say, Google's glog, spdlog, plog and Boost::Log.

• The concept of different log levels is introduced, as a means of dividing the log messages into subcategories, according to their severity and whether they were expected to occur.
• Furthermore, there will be a "global log level" that can be defined. Everything less severe than the severity set as the global log level, will not be logged.

Due to obvious restrictions, it is imperative that log calls below the global log level get optimized away at compile time.

The first attempt was something like this (single header file): log levels:

// We can set the global log level by defining one of these
#if defined LOGLEVEL_TRACE
#define LOGLEVEL Logger::trace
#elif defined LOGLEVEL_DEBUG
#define LOGLEVEL Logger::debug
#elif defined LOGLEVEL_INFO
[...]
#else
#define LOGLEVEL Logger::disabled
#endif

the levels themselves are enum members:

enum LogLevel {
        trace = 32, // Very detailed information, useful for tracking the individual steps of an operation
        debug = 64, // General debugging information
        info = 96, // Noteworthy or periodical events
[...]
};

A operator<< overload for better readability:

template <class T>
Logger::LogEntry& operator<<(Logger::LogEntry& entry, const T value) {
    etl::to_string(value, entry.message, entry.format, true);

    return entry;
}

And the macro-constexpr sorcery to make the compiler do what we want:

#define LOG(level)
    if (Logger::isLogged(level)) \
        if (Logger::LogEntry entry(level); true) \
            entry
// [...]
static constexpr bool isLogged(LogLevelType level) {
        return static_cast<LogLevelType>(LOGLEVEL) <= level;
    }

There were many issues with this code (see the MR discussion for more).

• A call operator to the enum LogLevel has been added to return a new static LogEntry.
• It is inlined to force const propagation at -O1.
• Two LogEntry enums have been created.
• The second one is a nop with everything inline.
• if constexpr syntax has been added.

and more (see here and below for justification.)

That's the (chopped) state of the code currently:

#include <cstdint>
#include <string>

#define LOGLEVEL_EMERGENCY

#if defined LOGLEVEL_TRACE
#define LOGLEVEL Logger::trace
#elif defined LOGLEVEL_DEBUG
#define LOGLEVEL Logger::debug
#elif defined LOGLEVEL_INFO
#define LOGLEVEL Logger::info
#elif defined LOGLEVEL_NOTICE
#define LOGLEVEL Logger::notice
#elif defined LOGLEVEL_WARNING
#define LOGLEVEL Logger::warning
#elif defined LOGLEVEL_ERROR
#define LOGLEVEL Logger::error
#elif defined LOGLEVEL_EMERGENCY
#define LOGLEVEL Logger::emergency
#else
#define LOGLEVEL Logger::disabled
#endif

#define LOG_TRACE     (LOG<Logger::trace>())
#define LOG_DEBUG     (LOG<Logger::debug>())
#define LOG_INFO      (LOG<Logger::info>())
#define LOG_NOTICE    (LOG<Logger::notice>())
#define LOG_WARNING   (LOG<Logger::warning>())
#define LOG_ERROR     (LOG<Logger::error>())
#define LOG_EMERGENCY (LOG<Logger::emergency>())

class Logger {
public:

    Logger() = delete;

    typedef uint8_t LogLevelType;

    enum LogLevel : LogLevelType {
        trace = 32,
        debug = 64,
        info = 96,
        notice = 128,
        warning = 160,
        error = 192,
        emergency = 254,
        disabled = 255, 
    };

    enum class NoLogEntry {};

    struct LogEntry {
        std::string message = "";
        LogLevel level;

        explicit LogEntry(LogLevel level);

        ~LogEntry();

        LogEntry(LogEntry const&) = delete;

        template <class T>
        Logger::LogEntry& operator<<(const T value) noexcept {
            message.append(value);

            return *this;
        }

        Logger::LogEntry& operator<<(const std::string& value);
    };

    static constexpr bool isLogged(LogLevelType level) {
        return static_cast<LogLevelType>(LOGLEVEL) <= level;
    }

    static void log(LogLevel level, std::string & message);
};

template <Logger::LogLevel level>
constexpr inline auto LOG() {
    if constexpr (Logger::isLogged(level)) {
        return Logger::LogEntry(level);
    } else {
        return Logger::NoLogEntry();
    }
};

template <typename T>
[[maybe_unused]] constexpr Logger::NoLogEntry operator<<(const Logger::NoLogEntry noLogEntry, T value) {
    return noLogEntry;
}

int main() {
    LOG_NOTICE << "I am getting optimized away!";
    LOG_EMERGENCY << "I am not getting optimized away, and rightfully so";

    return 0;
}

As you can see in e.g.Compiler Explorer, the LOG_NOTICE is getting optimized away at -O1.

Do you have any suggestions?

• Caveats and pitfalls I might have missed?
• Better ways to implement this?
• Ways to decrease overhead?

Answer 1

Due to obvious restrictions, it is imperative that log calls below the global log level get optimized away at compile time.

If such restrictions exist, they are not obvious at all. It sounds like you're designing a piece of software to run exactly once in a completely understood environment — namely a cubesat. ("Completely understood" doesn't mean "completely controlled" — things can still go wrong at runtime — but at least you don't have to worry about different customers with different installation-specific requirements.)

• Why does it need the "global log level" to be configurable at all? Surely for each given log message in your current codebase, you can just look at it and ask, "Will this message be helpful during the mission?" If it is, then it should be logged during the mission. If it is not, then it should not be logged during the mission (and since that's the only time this code will run, the message can be entirely removed from the codebase).

• OTOH, if it's not intuitively obvious which messages will be useful during the mission, then what you need is a runtime-configurable log level. "Oh shoot, something's going wrong. Quick, bump up the log level and let's see if the debug messages can give us a clue!" If the compiler has completely removed all the code that was involved with printing those debug messages, then you're screwed.

---

enum LogLevel : LogLevelType {
    trace = 32,
    debug = 64,
    info = 96,
    notice = 128,
    warning = 160,
    error = 192,
    emergency = 254,
    disabled = 255, 
};

You've placed disabled in the wrong place (assuming it means "a message which is never ever printed"). Emergency messages should always be printed; error messages usually printed; warnings and notices less often; info and trace messages least often; and then disabled messages never. So in your current scheme, disabled should be 0, and if you have a name for 255, it should be something like always.

Except that in practice I'd actually flip the ordering around, so that 0 messages were always printed (emergency) and 255 messages were hardly ever printed (debug). That way, when someone said "I'm turning the log level down," it would be clear which way they meant — lower integer number, fewer messages logged.

POSIX syslog severity levels work exactly the way I just described: 0 for emergencies, 7 for debug traces.

---

    template <class T>
    Logger::LogEntry& operator<<(const T value) noexcept {
        message.append(value);

        return *this;
    }

    Logger::LogEntry& operator<<(const std::string& value);

Why do you have a separate overload of << for strings? Surely the definition of that overload (not shown in your post) would just be message.append(value) anyway.

Also, consider using move semantics. Personally, I would write the entire overload set as

    template<class T>
    Logger::LogEntry& operator<<(T value) {
        message.append(std::move(value));
        return *this;
    }

I've removed the incorrect noexcept specifier — std::string::append is totally capable of throwing exceptions. Now, maybe you've decided that you want "out-of-memory during a logging operation" to call std::terminate and crash the whole process, but that really seems like something you should think carefully about. "Best practices for heap-allocation in space" is a whole rabbit hole you might not want to go down, but leaving that aside, just thinking about the behavior with noexcept and without noexcept, I'm pretty sure I'd prefer the behavior without noexcept.

(Removing noexcept will also decrease your code size, because it won't have to generate code to catch exceptions and call terminate. Rule of thumb: noexcept should go on move-constructors to avoid the vector pessimization; and maybe move-assignment and swap; and nowhere else.)

---

template <typename T>
[[maybe_unused]] constexpr Logger::NoLogEntry operator<<(const Logger::NoLogEntry noLogEntry, T value) {
    return noLogEntry;
}

It seems silly to use a different idiom here than you already used for the LogEntry case, especially when it means you have to cruft up your code with [[maybe_unused]] to suppress warnings. (Would any compiler actually warn on this code, though?) I would write this as a cut-and-paste of the LogEntry case:

    template<class T>
    Logger::NoLogEntry& operator<<(const T&) {
        // do not log it
        return *this;
    }

I guess for bonus metaprogramming points you could implement the entire thing as

template<LogLevelType Lvl>
struct LogEntry {
    std::string message;
    explicit LogEntry() = default;
    LogEntry(LogEntry const&) = delete;
    ~LogEntry();

    template<class T>
    LogEntry& operator<<(T value) {
        if (Lvl <= GLOBAL_LOG_LEVEL) {
             message.append(std::move(value));
        }
        return *this;
    }
};

#define LOG_ALWAYS LogEntry<0>()
#define LOG_ERROR LogEntry<10>()
#define LOG_NOTICE LogEntry<100>()
#define LOG_INFO LogEntry<200>()
#define LOG_DEBUG LogEntry<255>()

Notice that I'm not using if constexpr on my compile-time-constant condition there. The compiler will constant-fold it away without my help, and if I do use if constexpr then I don't get the extra compile-time sanity-checking to make sure that the body of the if is well-formed. if constexpr is a tool for template metaprogramming; if you're not doing template metaprogramming then you probably shouldn't be using it.

LOG_TRACE << 42.0;
    // If I never build your code with GLOBAL_LOG_LEVEL==TRACE,
    // I'll never see any indication that appending a double to a string
    // is ill-formed! This could lead me to write a lot of wrong code
    // that will cost me a lot of fixup time when I eventually do try
    // to build it in TRACE mode.

---

Watch out! You aren't using the tried-and-true assert idiom here — unwanted calls to LOG_DEBUG don't get macro'ed away. So for example

#include <assert.h>
assert(some_expensive_sanity_check());  // produces no code

#include <glog/logging.h>
LOG(INFO) << (some_expensive_sanity_check() ? "Yes" : "No");  // produces no code

#include <your-thing.h>
LOG_INFO << (some_expensive_sanity_check() ? "Yes" : "No");  // produces very much code

If you anticipate logging expensive things, then either:

• Use the macro tricks from assert or LOG(INFO) to ensure that some_expensive_sanity_check() is macro'ed away when unwanted, or

• Provide a "getter" for the log level, so that you can explicitly guard expensive log messages:

    #include <your-thing.h>
    if (INFO_IS_LOGGED) {
        LOG_INFO << (some_expensive_sanity_check() ? "Yes" : "No");
            // produces very much code, but the code
            // won't be executed unless INFO_IS_LOGGED
    }
  

---

TLDR: if you're going to Not-Invented-Here a piece of code, then you owe it to yourself to make your replacement as simple as possible. The more "tricks" you use, the more places you have to screw up and thus end up worse than the established code you could have used for free in the first place.