Literal Logging for C++

If the requirement of outputting a textual log from the C++ application is relaxed, we can create a faster logging framework. Enter llcpp (literal logging for c++). This framework uses C++17 template (and constexpr) meta-programming magic to reduce the number of allocations needed to zero and eliminates the need to format the data to human readable form. Later, a simple script can be used to transform the log into human readable form. Oh, and we get type safety for free.

Intrigued? skeptical? excited? angry? Read on!

This library is still in PoC mode. Feel free to try it and hack on it, but I can't promise a smooth ride just yet!

Also, I'll appreciate any feedback you may have :)

• Features
• Not textual?!
• Benchmarks
• Example
• Design Overview
• Extending
• Blog post

• Fast: Low call site latency, low total CPU usage. See benchmarks
• printf-like format syntax.
• Type safe: Mixing format type specifiers and arguments result in compilation error.
• No allocation for any log line.
• Header only.
• Available format specifiers: %d, %u, %x, %s. More coming soon.
• Prefixes available for line structure: Log level indication, Date/Time, Nanosecond timestamp.
• Synchronous: No independant state, when call returns the line has been written. May add async features in the future.
• Caveat: Output is not textual. See this. Parser written in python is implemented and will output the textual log.
• Caveat: Requires C++17. Tested on Clang 5.0.1 (Ubuntu) and Clang 900 (MacOS).
• Caveat: Requires a user-defined string literal GNU extension (template<tpyename CharT, CharT... Chars> operator""). Can be substituted with macro magic such as this if needed.

Yeah! Outputting textual logs is one of those "hidden" constrainsts/assumptions that no one talks about. If you think about it, you hardly ever read your logs directly. They're usually pulled and aggregated from your servers and go through a whole pipeline, adding a parser is no big deal.

Once you free yourself from this constraint, it's possible to implement a logging framework thats even faster than the current state of the art. How much faster you ask? See the benchmarks.

Make sure you read my post on benchmarking logging frameworks to get the whole story.

The following benchmark were run on Ubuntu 16.04.03. Compiled with Clang 5.0.1 with --std=c++1z -flto -O3 flags. /tmp is mounted on an SSD. llcpp is presented with both timestamp prefix and date/time prefix (which is slower due to localtime()).

(time in nanoseconds unless stated otherwise)

See my blog post for some discussion over worst-case measurements.

int main(int argc, char* argv[])
{
    using conf_t = llcpp::default_config;
    using prefix_tuple_t = std::tuple<llcpp::log_level_prefix, llcpp::localtime_prefix>;
    using logger_t = llcpp::file_logger<prefix_tuple_t, conf_t>;
    auto logger = logger_t("./log.txt");
    // Or: auto logger = llcpp::default_logger("./log.txt");

    logger.info("llcpp message #%d : This is some text for your pleasure. %s"_log, 0, "/dev/null");
    logger.info("llcpp message #%d : This is some text for your pleasure. %d %s %ld %llx. end."_log, 2, 42, "asdf", 24, 50);
    return 0;
}

The binary format is pretty straightforward: write the null-terminated format string, then write the in-memory binary representation of each of the arguments. For arithmetic types (ints, floats, etc.), the size of each binary representation is derived from the format string (%d will be 4 bytes, %lld will be 8 bytes, etc.). For strings, we have two options: writing the length and then the string or passing information about the maximum length in the format string and then copying the minimum between the given maximum and the string's actual length.

Examples:

• logger.info("Hello world"_log) - would simply be written as the null terminated string, as you'd expect.
• logger.info("Hello world %d"_log, 42) - would write the null terminated string, followed by 4 bytes representing 42 (little endian).
• logger.info("Hello world %lld"_log, 42) - would write the null terminated string, followed by 8 bytes representing 42 (little endian).
• logger.info("Hello world %s"_log, "42") - would write the null terminated string, followed by 4 bytes representing 2 (the length of "42") and 2 bytes with the actual string "42"
• logger.info("Hello world %8s"_log, "42") - would write the null terminated string, followed by 8 bytes, of which the first two would hold the string "42". If the string given in the argument is bigger, it would be truncated.

• User defined string literals are used to capture log format into variadic template parameters.
• string_format - Is specialized and holds a static array of characters representing the format string.
• format_parser - Parses the format string in compile time, generating a tuple of argument_parser's which correspond to the deduced arguments from the format.
• terminators - Are a collection of types that correspond to printf format type identifiers (such as 'd', 's', 'u', etc.). These are used by the format_parser to deduce the types of the escape sequences in the format string. These also provide a specific argument_parser which will be aggregated by the format_parser.
• log_line - Uses the string_format and format_parser to serialize the arguments to the log file. Exposes a operator() function which takes variadic arguments which are validated with the argument_parser's tuple provided by the format_parser.
• logging - Provide an interface for writing log parts to an output sink (file, network, etc.). Also handle prefix'es - a way to add structured data to your log lines (log level indication, timestamp, etc.). Also provide the high level (info(), warn(), etc.) functions.
• config - Allows the user to override internal classes such as string_format, format_parser and built-in terminator list for easy customization.

• Loggers must use the CRTP and inherit from logger_base.
• Loggers must implement the following functions:
  • void line_hint_impl() - Called by logger_base when an entire log line was written.
  • void write_impl(const std::uint8_t *data, const std::size_t len) - Called by the serialization code for each log line part.
• Loggers should let the user pass a PrefixTuple and Config by template parameters, and pass it to logger_base.

Example:

template<typename PrefixTuple, typename Config = config::default_config>
struct vector_logger : public logger_base<PrefixTuple, vector_logger<PrefixTuple>, Config> {

    vector_logger(std::vector<std::uint8_t>& vec, PrefixTuple&& prefix_tuple) : m_vec(vec),
        logger_base<PrefixTuple, vector_logger<PrefixTuple>>(std::forward<PrefixTuple>(prefix_tuple))
    {
    }

    void line_hint_impl() {
    }

    void write_impl(const std::uint8_t *data, const std::size_t len) {
        m_vec.insert(m_vec.end(), data, data+len);
    }

private:
    std::vector<std::uint8_t>& m_vec;
};

• Terminators must inherit from terminator<char, X> where X is the character representing the type identifier in the format string (i.e. 'd', 's', etc.).
• Terminators must not interfere with other terminators. For example: Adding an 'l' terminator would interfere with the 'l' options of the 'd' terminator (think about '%lld').
• Terminators must declare template <typename FormatTuple, std::size_t EscapeIdx, std::size_t TerminatorIdx> struct argument_parser with the following static members and functions:
  • static constexpr std::size_t argument_size - The size used when serializing this argument
  • using argument_type - The C++ type that this argument_parser expect to receive from the caller when serializing.
  • static constexpr bool is_fixed_size - False if this argument_parser cannot know in compile-time the size that will be needed during serialization.
  • template <typename Logger, typename Arg> static void apply(Logger& logger, const Arg arg) - The serialization function. It should use logger.write() to write the serialized data.
  • template <typename Logger> static void apply_variable(Logger& logger, const char *arg) - An auxiliary function that will be called if is_fixed_size is false. It should be used to write auxiliary serialization data if necessary.
• Terminators should be declared in the llcpp::user_terminators namespace.

Example:

namespace llcpp::user_terminators {
struct d : public terminator<char, 'd'>
{
    template <typename FormatTuple, std::size_t EscapeIdx, std::size_t TerminatorIdx>
    struct argument_parser
    {
        static constexpr bool is_fixed_size = true;
        static constexpr std::size_t num_of_l = tuple_counter<FormatTuple, char, 'l', EscapeIdx, TerminatorIdx>::count;
        static_assert(num_of_l < 3, "Invalid conversion specifier");
        static constexpr std::size_t argument_size = ((num_of_l == 0) ? (sizeof(std::uint32_t)) : (sizeof(std::uint32_t) * num_of_l));
        using argument_type = typename std::conditional<
            num_of_l == 0,
            int,
            typename std::conditional<
                num_of_l == 1,
                long,
                long long>::type>::type;

        template <typename Logger, typename Arg>
        static void apply(Logger& logger, const Arg arg)
        {
            static_assert(std::is_integral<Arg>::value,
                        "Integral argument's apply function called with non-integral value");
            static_assert(argument_size >= sizeof(Arg),
                        "Discrepency detected between parsed argument_size and size of given arg, "
                        "you may need a specialized argument_parser");
            logger.write((std::uint8_t *)&arg, argument_size);
        }

        template <typename Logger>
        static void apply_variable(Logger& logger, const char *arg) {}
    };
};
}

• Prefixes must implement template<typename Logger> void apply(logging::level::level_enum level, Logger& logger). This function should use the given logger to write the prefix as needed.

Example:

struct nanosec_time_prefix : public prefix_base {
    template<typename Logger>
    void apply(typename logging::level::level_enum level, Logger& logger) {
        auto now = std::chrono::system_clock::now();
        auto now_ns = std::chrono::duration_cast<std::chrono::nanoseconds>(now.time_since_epoch()).count();
        "[%llu]: "_log(logger, now_ns);
    }
};

You may extend the default configuration using the config_with_XXX declarations. Example:

using conf_t = llcpp::default_config::config_with_additional_terminators<std::tuple<llcpp::user_terminators::p>>;

using prefix_tuple_t = std::tuple<llcpp::log_level_prefix, llcpp::time_format_prefix<>>;
using logger_t = llcpp::file_logger<prefix_tuple_t, conf_t>;

For more information and background, head over to my blog posts here!