源码阅读之NanoLog(C++11版)
本文最后更新于 1017 天前,其中的信息可能已经有所发展或是发生改变。

最近想要锻炼一下开源代码阅读能力与C++实践能力,故而找到了NanoLog;

NanoLog有两个版本,一个是C++11,核心代码不足1000行,另一者为C++17,代码量较为庞大;

二者仅是同名,后者的运行速度是前者的百倍,是目前最快的日志系统。此处我先从前者(C++11)版本出发,初步地学习日志系统的实现,并进行记录,以供后来同我一样的无基础者参照,也希望能有老师指出我的错误与不足;往后若有空余时间再进行C++17版本的阅读学习与再实现;

注意:本文章是以一个有一定C++基础,但没有Log相关知识的视角进行阐述,可能会在编写过程中提出很多问题并记录解决这些问题的过程,会记录对于不了解的技巧、技术的学习思想过程,以供未来的我以及后来者阅读我的想法。


1.编译运行

C++11源码链接:https://github.com/Iyengar111/NanoLog

我先在Windows环境下运行。clone到本地后,使用VS2019新建工程,将NanoLog.cpp、NanoLog.hpp以及non_guaranteed_nanolog_benchmark.cpp导入工程;

由于VS2019自身的防护机制,我们需要在代码的头文件include之前,定义#define_CRT_SECURE_NO_WARNINGS,否则会报错unsafe;

non_guaranteed_nanolog_benchmark.cpp是一个用于测试的cpp文件,也是入口main函数所在,此时我们就可以编译运行了。

输出结果如下所示:

Thread count: 1
        Average NanoLog Latency = 2483 nanoseconds
Thread count: 2
        Average NanoLog Latency = 2565 nanoseconds
        Average NanoLog Latency = 2598 nanoseconds
Thread count: 3
        Average NanoLog Latency = 2774 nanoseconds
        Average NanoLog Latency = 2986 nanoseconds
        Average NanoLog Latency = 3053 nanoseconds
Thread count: 4
        Average NanoLog Latency = 2899 nanoseconds
        Average NanoLog Latency = 2937 nanoseconds
        Average NanoLog Latency = 3115 nanoseconds
        Average NanoLog Latency = 3284 nanoseconds
Thread count: 5
        Average NanoLog Latency = 3011 nanoseconds
        Average NanoLog Latency = 3056 nanoseconds
        Average NanoLog Latency = 3064 nanoseconds
        Average NanoLog Latency = 3185 nanoseconds
        Average NanoLog Latency = 3356 nanoseconds

Q1:原作者的测试结果运行速度是我的10-16倍,我的CPU性能要远高于原作者,二者的唯一区别是对方运行于Linux系统,不知道是哪方面的原因导致了这个问题?

A1:可能会有如下原因,一是VS的设置,x86和x64以及debug和release的影响,二是windows和linux的系统差异,于是我做了如下测试:

我尝试使用Linux进行测试;

在目标目录terminal输入如下:

g++ -g -O3 -std=c++11 -pthread NanoLog.cpp non_guaranteed_nanolog_benchmark.cpp -o non_guaranteed_nanolog_benchmark

./non_guaranteed_nanolog_benchmark

得到如下结果:

Thread count: 1
        Average NanoLog Latency = 74 nanoseconds
Thread count: 2
        Average NanoLog Latency = 124 nanoseconds
        Average NanoLog Latency = 124 nanoseconds
Thread count: 3
        Average NanoLog Latency = 77 nanoseconds
        Average NanoLog Latency = 147 nanoseconds
        Average NanoLog Latency = 169 nanoseconds
Thread count: 4
        Average NanoLog Latency = 149 nanoseconds
        Average NanoLog Latency = 274 nanoseconds
        Average NanoLog Latency = 172 nanoseconds
        Average NanoLog Latency = 194 nanoseconds
Thread count: 5
        Average NanoLog Latency = 330 nanoseconds
        Average NanoLog Latency = 288 nanoseconds
        Average NanoLog Latency = 297 nanoseconds
        Average NanoLog Latency = 354 nanoseconds
        Average NanoLog Latency = 334 nanoseconds

运行结果和原作者大致相当,部分结果快约1倍;

然后我使用VS中的x64与release选项,运行结果如下:

Thread count: 1
        Average NanoLog Latency = 146 nanoseconds
Thread count: 2
        Average NanoLog Latency = 214 nanoseconds
        Average NanoLog Latency = 227 nanoseconds
Thread count: 3
        Average NanoLog Latency = 244 nanoseconds
        Average NanoLog Latency = 252 nanoseconds
        Average NanoLog Latency = 252 nanoseconds
Thread count: 4
        Average NanoLog Latency = 257 nanoseconds
        Average NanoLog Latency = 273 nanoseconds
        Average NanoLog Latency = 278 nanoseconds
        Average NanoLog Latency = 306 nanoseconds
Thread count: 5
        Average NanoLog Latency = 262 nanoseconds
        Average NanoLog Latency = 280 nanoseconds
        Average NanoLog Latency = 286 nanoseconds
        Average NanoLog Latency = 290 nanoseconds
        Average NanoLog Latency = 292 nanoseconds

运行结果和原作者大致相当,部分结果稍快一些,但差距不大;其中x64与x86测试结果相差一倍;

其中x64与x86以及debug和release之间的性能差异原因显而易见,而windows与linux的差异如此巨大始料未及,目前没有在网上找到相关的答案,我个人的猜想是linux会把更多的资源分配给我所要执行的程序。

(22/4/9)1.会不会是二者系统在多线程资源分配上的差异导致的(届时可以对比下不同线程数下二者的差异)? 2.会不会是因为计算时间所使用的库函数在二者系统实现上有差异而导致的?3.会不会是VS和G++在代码优化上的区别?

2.n_guaranteed_nanolog_benchmark.cpp分析

由于名字太长,下文我将之称为test.cpp;

我认为理解一个开源程序的前提是先要会使用这个开源程序,于是我们先看test.cpp;

在test.cpp中共有4个函数,首先是入口函数main:

int main()
{
    // 环形缓冲区大小以10MB传递
    // 每个log行=256字节,共计40960slots
    nanolog::initialize(nanolog::NonGuaranteedLogger(10), "/tmp/", "nanolog", 1);
    for (auto threads : { 1, 2, 3, 4, 5 })
    	run_benchmark(nanolog_benchmark, threads);
    return 0;
}

nanolog::initialize顾名思义是一个初始化函数,具体作用目前不明,从运行结果和main代码上可以推测得,测试由1-5个线程进行日志输出;

接下来看run_benchmark的定义:

template < typename Function >
void run_benchmark(Function && f, int thread_count)
{
    printf("Thread count: %d\n", thread_count);
    std::vector < std::thread > threads;
    for (int i = 0; i < thread_count; ++i)
    {
	threads.emplace_back(f);
    }
    for (int i = 0; i < thread_count; ++i)
    {
	threads[i].join();
    }
}

这里将函数作为模板,参数中用了右值引用,在main中我们可以看到这个函数的第一个参数是nanolog_benchmark函数,第二个参数是一个int,即线程数;

emplace_back是C++11中新增的函数以取代push_back,其区别是前者只需调用构造函数而后者还另需调用拷贝构造函数;

threads是thread类型的一个向量,在第二次遍历中,join是thread库中的一个函数,其作用是在子线程运行结束之前阻塞运行环境的线程,运行环境线程即指这个函数是在那个线程中运行的,例如在main中调用a.join()即指在线程a完成之前阻塞主线程,这可以用来实现线程之间的同步;

想要理解run_benchmark的运行机理,我们现在需要看nanolog_benchmark和timestamp_now的定义:

uint64_t timestamp_now()
{
    return std::chrono::high_resolution_clock::now().time_since_epoch() / std::chrono::microseconds(1);
}
void nanolog_benchmark()
{
    int const iterations = 100000;
    char const * const benchmark = "benchmark";
    uint64_t begin = timestamp_now();
    for (int i = 0; i < iterations; ++i)
	LOG_INFO << "Logging " << benchmark << i << 0 << 'K' << -42.42;
    uint64_t end = timestamp_now();
    long int avg_latency = (end - begin) * 1000 / iterations;
    printf("\tAverage NanoLog Latency = %ld nanoseconds\n", avg_latency);
}

timestamp_now非常清晰的可以明白这是获得当前时间戳,其中chrono是一个C++11的时间std库,now函数返回一个std::chrono::time_point类型,其time_since_epoch函数返回一个从其时钟起点开始的时间点,与microseconds相除就类似于小学数学应用题里进行单位统一,除以1ms即将单位统一到ms级别;

接下来来看nanolog_benchmark,首行初始化了迭代次数,次行则只是给出输出的主题,begin和end或者运行前后的时间戳,而后avg_latency即是二者之差放大到ns级再用iterations缩小,此处可能会产生一个问题,即当迭代次数小于1000时产生的结果会有误差;

这里第二行用了char const * const,其左边的const修饰char,表示指针指向的内容不变,右边的const修饰*,表示指针指向的地址不变;

LOG_INFO即是日志系统日志输出,如下所示:

#define NANO_LOG(LEVEL) nanolog::NanoLog() == nanolog::NanoLogLine(LEVEL, __FILE__, __func__, __LINE__)
#define LOG_INFO nanolog::is_logged(nanolog::LogLevel::INFO) && NANO_LOG(nanolog::LogLevel::INFO)
#define LOG_WARN nanolog::is_logged(nanolog::LogLevel::WARN) && NANO_LOG(nanolog::LogLevel::WARN)
#define LOG_CRIT nanolog::is_logged(nanolog::LogLevel::CRIT) && NANO_LOG(nanolog::LogLevel::CRIT)

暂且将LOG_INFO的实现搁置,我们现在可以明白nanolog_benchmark函数作用即是调用日志系统进行100000次日志迭代,然后输出平均每次的时间。

接下来我们可以回过头来看run_benchmark函数;

第一个循环threads.emplace_back(f)将线程对象即nanolog_benchmark函数放入vector中,第二个循环则是保障对于每一个线程都运行结束后run_benchmark才会结束;

比较特殊的,因为需要将函数作为参数进行传递,所以这里使用了右值引用,原因是thread利用了move语义进行赋值。

最后回到main函数,我们已经可以明白其作用机理了;

initialize进行对日志系统初始的配置,而后的循环则依次使用1-5的线程数,每次都会令每一个线程执行100000次日志操作,并且输出每个线程平均每次日志操作所需要的时间。

3.NanoLog.hpp分析

NanoLog.hpp大多是函数等的声明,这里主要对define进行分析。

前文有提到过,这里再贴一次代码:

#define NANO_LOG(LEVEL) nanolog::NanoLog() == nanolog::NanoLogLine(LEVEL, __FILE__, __func__, __LINE__)
#define LOG_INFO nanolog::is_logged(nanolog::LogLevel::INFO) && NANO_LOG(nanolog::LogLevel::INFO)
#define LOG_WARN nanolog::is_logged(nanolog::LogLevel::WARN) && NANO_LOG(nanolog::LogLevel::WARN)
#define LOG_CRIT nanolog::is_logged(nanolog::LogLevel::CRIT) && NANO_LOG(nanolog::LogLevel::CRIT)

先看后三行。nanolog是namespace,is_logged从字面上来看是一个判断是否日志输出的bool函数,LogLevel是一个C++11的enum class,并将底层类别指定为uint8_t;

enum class LogLevel : uint8_t { INFO, WARN, CRIT };
bool is_logged(LogLevel level);

利用了&&的短路特性,前者为真则执行后者,反之则不执行;

接下来看第一行。NanoLog和NanoLogLine分别是结构体和类,前者重载了==运算符用于和NanoLogLine进行判断,后者调用了构造函数;

NanoLogLine(LogLevel level, char const* file, char const* function, uint32_t line);
struct NanoLog
{
	bool operator==(NanoLogLine&);
};

此外,NanoLogLine重载了<<运算符便于日志的输出;

NanoLogLine& operator<<(char arg);
NanoLogLine& operator<<(int32_t arg);
NanoLogLine& operator<<(uint32_t arg);
NanoLogLine& operator<<(int64_t arg);
NanoLogLine& operator<<(uint64_t arg);
NanoLogLine& operator<<(double arg);
NanoLogLine& operator<<(std::string const& arg);

template < size_t N >
NanoLogLine& operator<<(const char(&arg)[N])
{
	encode(string_literal_t(arg));
	return *this;
}

template < typename Arg >
typename std::enable_if < std::is_same < Arg, char const* >::value, NanoLogLine& >::type operator<<(Arg const& arg)
{
	encode(arg);
	return *this;
}

template < typename Arg >
typename std::enable_if < std::is_same < Arg, char* >::value, NanoLogLine& >::type operator<<(Arg const& arg)
{
	encode(arg);
	return *this;
}

在main中是这样用宏LOG_INFO的:

LOG_INFO << "Logging " << benchmark << i << 0 << 'K' << -42.42;

这里的一些看上去似乎无意义的元素正好对应了上述的几种重载类型,达到了尽可能全面测试的效果;

现在还不明白为什么define的三种LOG类型可以达成这样的效果,具体还需要看函数实现,所以暂且搁置。

4.NanoLog.cpp分析

4.1NanoLogLine

每一条日志的主体类结构如下所示,一者为了方便输出,重载了大量的<<以适配不同情况

    class NanoLogLine
    {
    public:
	NanoLogLine(LogLevel level, char const * file, char const * function, uint32_t line);
	~NanoLogLine();

	NanoLogLine(NanoLogLine &&) = default;
	NanoLogLine& operator=(NanoLogLine &&) = default;

	void stringify(std::ostream & os);

	NanoLogLine& operator<<(char arg);
	NanoLogLine& operator<<(int32_t arg);
	NanoLogLine& operator<<(uint32_t arg);
	NanoLogLine& operator<<(int64_t arg);
	NanoLogLine& operator<<(uint64_t arg);
	NanoLogLine& operator<<(double arg);
	NanoLogLine& operator<<(std::string const & arg);

	template < size_t N >
	NanoLogLine& operator<<(const char (&arg)[N])
	{
	    encode(string_literal_t(arg));
	    return *this;
	}

	template < typename Arg >
	typename std::enable_if < std::is_same < Arg, char const * >::value, NanoLogLine& >::type
	operator<<(Arg const & arg)
	{
	    encode(arg);
	    return *this;
	}

	template < typename Arg >
	typename std::enable_if < std::is_same < Arg, char * >::value, NanoLogLine& >::type
	operator<<(Arg const & arg)
	{
	    encode(arg);
	    return *this;
	}

	struct string_literal_t
	{
	    explicit string_literal_t(char const * s) : m_s(s) {}
	    char const * m_s;
	};

    private:	
	char * buffer();

	template < typename Arg >
	void encode(Arg arg);

	template < typename Arg >
	void encode(Arg arg, uint8_t type_id);

	void encode(char * arg);
	void encode(char const * arg);
	void encode(string_literal_t arg);
	void encode_c_string(char const * arg, size_t length);
	void resize_buffer_if_needed(size_t additional_bytes);
	void stringify(std::ostream & os, char * start, char const * const end);

    private:
	size_t m_bytes_used;
	size_t m_buffer_size;
	std::unique_ptr < char [] > m_heap_buffer;
	char m_stack_buffer[256 - 2 * sizeof(size_t) - sizeof(decltype(m_heap_buffer)) - 8 /* Reserved */];
    };
上一篇
下一篇