llcpp

Literal Logging for C++

TL;DR

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!

Status

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 :)

Contents

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

Features

• 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.

Not Textual?!

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.

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)

1 Thread Logging To /tmp

|Logger| 50th| 75th| 90th| 99th| 99.9th| Worst| Average | Total Time (seconds)| |:----:|:-------:|:-------:|:-------:|:-------:|:-------:|:-------:|:-------:|:---------------:| |llcpp (timestamp) | 165| 171| 211| 2058| 6313| 149432|230.360544| 0.42 | |llcpp (date/time) | 184| 195| 216| 2153| 3718| 1099523|260.166040| 0.53 | |mini-async-logger | 286| 335| 361| 1348| 2884| 6204357|324.418935| 1.32 | |NanoLog | 211| 248| 291| 1099| 3809| 2493347|798.895457| 3.01 | |spdlog | 729| 751| 780| 973| 3277| 1057879|744.825963| 0.95 | |g3log | 2300| 2819| 3230| 5603| 28176| 2249642|2490.365190| 3.86 |

4 Threads Logging To /tmp

|Logger| 50th| 75th| 90th| 99th| 99.9th| Worst| Average | Total Time (seconds)| |:----:|:-------:|:-------:|:-------:|:-------:|:-------:|:-------:|:-------:|:---------------:| | llcpp (timestamp) | 173| 191| 242| 7501| 36031| 2668978|458.101174| 1.61 | |llcpp (date/time) | 220| 227| 270| 15515| 46522| 2162221|567.410498| 1.69 | |mini-async-logger | 414| 581| 863| 2872| 24384| 5858754|612.069366| 5.52 | |NanoLog | 338| 404| 1120| 1859| 24906| 1599487|845.320061| 12.81 | |spdlog | 1100| 1193| 1238| 1373| 14022| 1312104|1032.874598| 1.91 | |g3log | 1904| 2452| 3171| 9600| 37283| 6174296|2428.927793| 16.29 |

Worst case measurements

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

Example

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;
}

Binary Log Format

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.

Design Overview

• 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.

Extending

Adding loggers:

• 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;
};

Adding terminators

• 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 si