0%

C++日志框架基准测试及源码分析

发表于 更新于 分类于

C++日志框架有非常多，如何进行选择，其中性能是一个非常重要的考量因素，本文对几种有代表性的日志框架进行基准测试，并深入到源码和实现原理进行分析对比，便于大家进行选择。

测试对象

log4cplus属于仿log4j一类，也是起步较早的日志框架，早在2010年，出于log4j的名气，我在项目中就采用了log4cplus；spdlog属于比较现代化的日志框架，专注于性能；boost.log是1.54进入boost库的，当年选择log4cplus时还在评审阶段，boost可以说是准C++标准库，能够进入boost库自然质量不低，但是其设计相对也比较复杂，boost.log使用起来着实不太方便，它不太像直接面向用户使用，而更像是作为底层库供用户封装为更上层库。

日志框架对比

三种日志库在一些特性和实现方式上存在比较大的差别，为更好理解他们，先做一个简单对比：

log4cplus spdlog boost.log
线程安全     默认线程安全 分mt和st 分mt和st
异步支持 从1.1.0开始增加asyncappender，可配置队列深度，线程数不可配，总为1，深度满后阻塞调用。每个日志对象所有。log4cplus并没有提供显式flush的接口，只有shutdown日志对象或close appender间接flush。（log4cplus的同步appender构造函数都有一个immediateFlush参数，表示C++标准输出流或文件流的flush） 可设置队列深度和线程数，深度满后有阻塞和丢弃老的两种策略；使用全局或每个日志独有都可以。         队列有限制深度/不限制深度以及fifo/ordering组合起来四种，限制深度的队列满后有阻塞和丢弃新的两种策略；线程数总为1个；sink frontend所有。
日志对象和sink的关系 sink在log4cplus中称为appender，每个日志对象显式指定appender。 每个日志对象显式指定sink。 无法显式指定日志对象(boost.log称为log source)对应到哪个sink，换言之每个日志对象对应所有sink，要实现某个日志对象只输出到某个sink，需要通过在sink上设置filter来实现。具体可参考：use-channel-hiearchy-of-boost-log-for-severity-and-sink-filtering，connecting a logger to a specific sink
日志继承 支持，类似log4j，日志继承有一个不好的地方，日志会自动写到父日志，而root日志是所有日志的祖先，如果配置了root日志，总会写到其中，这样会导致写入效率劣化严重 不支持 不支持
配置文件 支持，类似log4j 不支持 支持
自定义日志级别 支持 不支持 支持

boost.log

boost.log相对复杂，单独做一个简单介绍。boost.log使用了很多新的概念，设计上非常模块化，可以灵活组装和扩展。对于初次使用boost.log，上手不会特别顺畅，需要理解清楚以下几个核心概念：

  • Log source：就是其他框架中的日志对象，使用者直接面对的，其特别之处是日志级别也是完全自定义的；
  • Log sink frontend：异步和同步在这一层实现，sink backend作为参数传给它，创建之后add到core中；
  • Log sink backend：代表日志输出的载体，如控制台、文件等，这是我们比较熟悉的概念，把sink分为frontend和backend，我想是为了各层都可以独立扩展，非常灵活；
  • Logging core：它是单例的，建立source和sink之间的连接，就像一个hub一样，还可以设置一些全局fiter和属性。

以下列出目前boost.log支持的所有source和sink：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
namespace logging = boost::log;
namespace sinks = boost::log::sinks;
namespace src = boost::log::sources;
namespace expr = boost::log::expressions;
namespace attrs = boost::log::attributes;
namespace keywords = boost::log::keywords;

// Log source，mt表示线程安全版本，不带mt表示非线程安全版本
src::logger
src::logger_mt
src::severity_logger
src::severity_logger_mt
src::channel_logger
src::channel_logger_mt
src::severity_channel_logger
src::severity_channel_logger_mt

// Log sink frontend
sinks::unlocked_sink
sinks::synchronous_sink
sinks::asynchronous_sink

// 对于异步sink frontend有如下队列
//record queueing strategy
sinks::unbounded_fifo_queue
sinks::unbounded_ordering_queue
sinks::bounded_fifo_queue
sinks::bounded_ordering_queue
//overflow strategies:
sinks::drop_on_overflow
sinks::block_on_overflow

// Log sink backend
sinks::basic_text_ostream_backend
sinks::text_file_backend
sinks::text_multifile_backend
sinks::text_ipc_message_queue_backend
sinks::syslog_backend
sinks::basic_debug_output_backend
sinks::basic_simple_event_log_backend
sinks::basic_event_log_backend

测试工具&代码

  • benchmark 1.5.0

    对benchmark的使用遇到一点小障碍，因为我希望将flush的时间也统计在内，但是benchmark的默认计时方式是无法在最后一个迭代，加入对flush的调用，因为最后一个迭代会自动停止计时。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    for (auto _ : state) {
    	function_to_be_measured();
    }

    // 等价于

    for (auto it = state.begin(), e = state.end(); it != e; ++it) {
        function_to_be_measured();
    }

    // 我希望这样，但是没有成功，因为!=操作符中，如果到达迭代最后，会自动停止计时
    for (auto it = state.begin(), e = state.end();;) {
        if (!(it != e)) {
            log.flush();
            break;
        }
        log.info(...);
        ++it;
    }

    因此，最终只有选择UseManualTime计时方式。

  • 测试代码：<https://github.com/zhongpan/cpp-logging-benchmark

    1. 时间和速率统计包含flush时间，也就是保证日志全部输出到控制台或文件；
    2. 异步写入都是采用1个线程，队列深度都设置为8192，队列满后都采用阻塞策略；
    3. 写入消息长度最小选择32，避免string的小字符串性能优化，能够代表更通常的场景；

测试结果

  • 测试环境：

    Intel® Core™ i5-7200U CPU @ 2.50GHz
    Micron 1100 SATA 256G

  • 测试结果：

a_c_32 a_c_512 s_c_32 s_c_512
log4cplus 298.557/s 47.8782/s 313.306/s 50.7682/s
spdlog 14.4967k/s 8.49778k/s 15.5747k/s 6.09162k/s
boost.log 6.55519k/s 3.86561k/s 4.98684k/s 3.22393k/s
a_f_32 a_f_512 s_f_32 s_f_512
log4cplus 15.8821k/s 5.48616k/s 11.2635k/s 4.91378k/s
spdlog 180.147k/s 109.091k/s 229.206k/s 135.489k/s
boost.log 29.3718k/s 25.9405k/s 15.7826k/s 14.6118k/s
  • 说明：

  1. 32/512表示消息字节数；

  2. a/s表示异步或同步；

  3. c/f表示控制台或文件；

结果分析

  1. 所有的日志框架都表现出文件的写入效率远高于控制台，因此尽量使用文件方式写日志；
  2. 同步和异步两种方式，如果把flush的时间统计在内，则效率区别不大，但是异步方式不会阻塞应用，如果考虑对应用的效率影响，异步方式显著优于同步，但是可能存在丟日志的情况，在应用退出时必须主动flush；
  3. 当消息长度增加时，写入效率都有所下降，spdlog当消息大于500字节时下降显著（见下面的源码分析），boost.log下降不明显；
  4. 各种情况写入效率都是：spdlog>boost.log>log4cplus，并且log4cplus的控制台写入效率非常非常低，spdlog的效率显著高于其他日志框架，特别是文件方式写入效率，让人难以置信👍，boost.log在复杂的设计下仍然保持良好的性能，也非常厉害。

spdlog性能优化源码分析

  1. std::string_view的使用避免字符串复制时内存分配
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
// spdlog/details/logger_impl.h
inline void spdlog::logger::log(source_loc source, level::level_enum lvl, const char *msg)
{
    if (!should_log(lvl))
    {
        return;
    }

    try
    {
        details::log_msg log_msg(source, &name_, lvl, spdlog::string_view_t(msg));
        sink_it_(log_msg);
    }
    SPDLOG_CATCH_AND_HANDLE
}
1
2
3
4
5
6
7
8
// spdlog/common.h

// string_view type - either std::string_view or fmt::string_view (pre c++17)
#if defined(FMT_USE_STD_STRING_VIEW)
using string_view_t = std::string_view;
#else
using string_view_t = fmt::string_view;
#endif
  1. 实现fmt::memory_buffer进行字符串格式化，500长度以内使用内部数组，避免堆内存分配，并且比sstream更快
1
2
3
4
5
6
7
// spdlog/sinks/basic_file_sink.h    
	void sink_it_(const details::log_msg &msg) override
    {
        fmt::memory_buffer formatted;
        sink::formatter_->format(msg, formatted);
        file_helper_.write(formatted);
    }
1
2
3
4
5
6
7
8
9
10
11
// spdlog/fmt/bundled/format.h

// The number of characters to store in the basic_memory_buffer object itself
// to avoid dynamic memory allocation.
enum { inline_buffer_size = 500 };

template <typename T, std::size_t SIZE = inline_buffer_size,
          typename Allocator = std::allocator<T> >
class basic_memory_buffer: private Allocator, public internal::basic_buffer<T> {
 private:
  T store_[SIZE];
  1. 缓存时间字符串，避免重复格式化
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
// spdlog/details/pattern_formatter.h   
    void format(const details::log_msg &msg, const std::tm &tm_time, fmt::memory_buffer &dest) override
    {
        using std::chrono::duration_cast;
        using std::chrono::milliseconds;
        using std::chrono::seconds;

#ifndef SPDLOG_NO_DATETIME

        // cache the date/time part for the next second.
        auto duration = msg.time.time_since_epoch();
        auto secs = duration_cast<seconds>(duration);

        if (cache_timestamp_ != secs || cached_datetime_.size() == 0)
        {
            cached_datetime_.clear();
            cached_datetime_.push_back('[');
            fmt_helper::append_int(tm_time.tm_year + 1900, cached_datetime_);
            cached_datetime_.push_back('-');

            fmt_helper::pad2(tm_time.tm_mon + 1, cached_datetime_);
            cached_datetime_.push_back('-');

            fmt_helper::pad2(tm_time.tm_mday, cached_datetime_);
            cached_datetime_.push_back(' ');

            fmt_helper::pad2(tm_time.tm_hour, cached_datetime_);
            cached_datetime_.push_back(':');

            fmt_helper::pad2(tm_time.tm_min, cached_datetime_);
            cached_datetime_.push_back(':');

            fmt_helper::pad2(tm_time.tm_sec, cached_datetime_);
            cached_datetime_.push_back('.');

            cache_timestamp_ = secs;
        }
        fmt_helper::append_buf(cached_datetime_, dest);
  1. 控制台输出使用CRT接口，相对于ostream更快
1
2
3
4
5
6
7
8
9
10
11
12
13
14
// spdlog/details/console_globals.h
struct console_stdout
{
   static std::FILE *stream()
   {
       return stdout;
   }
#ifdef _WIN32
   static HANDLE handle()
   {
       return ::GetStdHandle(STD_OUTPUT_HANDLE);
   }
#endif
};
1
2
3
4
5
6
// corecrt_wstdio.h in windows sdk 10.0.17763.0
_ACRTIMP_ALT FILE* __cdecl __acrt_iob_func(unsigned _Ix);

#define stdin  (__acrt_iob_func(0))
#define stdout (__acrt_iob_func(1))
#define stderr (__acrt_iob_func(2))
  1. 文件写入使用的CRT接口，相对于ofstream快
1
2
3
4
5
6
7
8
9
10
// sdplog/details/file_helper.h    
   void write(const fmt::memory_buffer &buf)
   {
       size_t msg_size = buf.size();
       auto data = buf.data();
       if (std::fwrite(data, 1, msg_size, fd_) != msg_size)
       {
           throw spdlog_ex("Failed writing to file " + os::filename_to_str(_filename), errno);
       }
   }

总结

三种日志框架各有所长，我觉得日志框架最重要的还是性能和接口易用性，为了调试bug，必须打必要的日志，但是开了日志，又影响到程序性能，甚至本来必现的问题，因为效率变差的原因都不出来了，这就尴尬了。经过以上分析对比，spdlog在性能和接口易用性上完胜其他日志框架，是日志框架的首选，其次boost.log也是一个不错选择，但是其接口用起来不是特别顺畅，对于log4cplus还是不推荐大家使用了，已经用了的尽快切换吧，当然spdlog使用了大量C++新特性，你必须使用C++11以上的新标准，但这似乎不是什么问题。

-------------本文结束感谢您的阅读-------------