本文转载自微信公众号《没有逻辑》，作者Draveness。转载本文请联系真诺逻辑公众号。《看论文》是分析计算机与软件工程领域论文的系列文章。在本系列的每篇文章中，我们都会阅读一篇来自OSDI和SOSP等顶级会议的论文。介绍所有细节，但会筛选论文的关键内容。如果您对相关论文非常感兴趣，可以直接点击链接阅读原文。本文是关于2018年ATC期刊的论文——NanoLog:ANanosecondScaleLoggingSystem[^1]。本文实现的NanoLog是一个高性能的日志系统，兼容C++社区的其他日志系统，如：spdlog与BoostLog、glog和BoostLog相比，其性能可以提升1~2个数量级更高。在本文中，我们将简要分析一下NanoLog的设计和实现原理。日志是系统可观察性的重要组成部分。相信很多工程师都有线上出现问题时临时加日志排查问题的经历。笔者刚刚又经历了这个过程。稍有经验的开发人员会在系统中添加大量的日志。方便生产环境排查问题。更有经验的开发者会小心翼翼的在系统中添加日志（尤其是低延迟的实时系统），因为打印日志这件看似简单的事情，实际上会带来很多额外的开销。打印日志是一件简单的事情。几乎所有的工程师从编程的第一天起就学会了如何使用printf等函数将字符串打印到标准输出。99%的程序都会用到这种方法。不会造成性能问题，但是在生产环境中，我们会使用结构化的、易于解析的格式来代替printf，例如：在日志中添加时间戳、文件名、行号等信息。图1-常见的日志系统但剩下的1%的程序需要超低延迟系统，它们的响应时间要求可能在微秒甚至纳秒级。在这种场景下，如果仍然需要日志系统提供可观察性，我们就需要深入研究将日志写入标准输出或文件的细节，例如：使用缓冲区、异步写入文件、减少动态特性的使用，例如反射，除此之外，我们还需要保证日志输出的顺序，避免消息丢失或截断。spdlog、glog、BoostLog已经能够满足大部分应用的需求，但是对于这些对延迟敏感的应用，打印日志所需的几微秒可能会显着增加请求的处理时间，影响程序的性能.如今，SharedNanoLog是一个可以打印纳秒级日志的系统。架构设计NanoLog可以毫秒级打印日志，因为它可以在编译期间提取静态日志消息，并在离线阶段处理日志格式化等问题。它的核心优化是基于以下两个条件：开发者可以直接读取的格式化日志不一定要在应用运行时直接生成，我们可以在运行时记录日志的动态参数，运行后按需生成;日志消息中的绝大部分信息都是静态冗余的，只有少数参数变化，我们可以在编译时获取日志的静态内容，在后处理器中只打印一次；正是因为大多数日志都遵循以上特点，NanoLog可以实现纳秒级的日志打印。NanoLog不同的设计方式决定了它会与传统的日志模块有着截然不同的架构。它由以下三个组件组成：图2-NanoLog系统架构预处理器：在编译时从源代码中提取日志消息，用优化代码替换原始日志语句，并为每条日志消息生成压缩和字典辅助函数；runtimelibrary：将多线程打印的日志缓存在buffer中，使用预处理阶段生成的辅助函数输出压缩二进制日志；解码器：利用预处理阶段生成的字典对日志进行解码，得到人类可读的日志；传统的日志系统只包含运行时，我们只需要在代码中引入头文件、链接静态库或动态库并在指定位置输出日志，日志系统就会将日志打印到标准输出或指定位置程序运行期间的文件。然而，NanoLog打破了上述传统设计。为了减少运行时的开销，我们将一些操作迁移到编译期间和运行之后，这也遵循了工作质量守恒定律：工作不会凭空消失，只会从运行时获得转移到其他阶段在程序生命周期中，NanoLog使用以下操作来减少日志系统的开销：在编译时重写日志语句以去除静态信息，并将昂贵的格式化操作推迟到代码运行后的阶段，这样可以减少大量的计算和运行时的I/O带宽要求；为每条日志消息编译特定的代码，可以高效处理动态参数，避免在运行时解析日志消息和编码参数类型；使用轻量级压缩算法和无序日志减少运行时I/O和处理时间；使用后处理将压缩日志数据和编译时提取的静态信息结合起来，生成可读日志；在实现原理这一节中，我们将简要分析NanoLog系统中三大组件，即预处理、运行时和后处理的具体实现原理。预处理NanoLog使用Python来实现预处理器。程序的入口在处理器/解析器中。它扫描用户的源文件，生成元数据文件和修改后的源代码，然后将这些修改后的代码编译成.so或.a文件，而不是编译原始代码。除此之外，预处理器读取所有生成的元数据文件，生成C++源代码并将其编译到NanoLog的运行时库和最终用户程序中：图3-它将添加到源代码中的预处理器NANO_LOG的每个NANO_LOG生成两个语句，即记录和压缩，前者将动态参数记录在日志中，后者对记录的数据进行压缩，以减少程序的I/O时间。下面是预处理器生成的record函数：inlinevoid__syang0__fl__E32374s3237424642lf__s46cc__100__(NanoLog::LogLevellevel,constchar*fmtStr,constchar*arg0,intarg1,intarg2,doublearg3){externconstuint32_t__fmtId__E32374s3237424642lf__s46cc__100__;if(level>NanoLog::getLogLevel())return;uint64_ttimestamp=PerfUtils::Cycles::rdtsc();size_tstr0Len=1+strlen(arg0);;size_tallocSize=sizeof(arg1)+sizeof(arg2)+sizeof(arg3)+str0Len+sizeof(NanoLogInternal::Log::UncompressedEntry);NanoLogInternal::Log::UncompressedEntry*re=reinterpret_cast(NanoLogInternal::RuntimeLogger::reserveAlloc(allocSize));re->fmtId=__fmtId__E32374s3237424642lf__s46cc__100__;re->timestamp=timestamp;re->entrySize=static_cast(allocSize);char*buffer=re->argData;//记录非字符串参数NanoLogInternal::Log::r??ecordPrimitive(buffer,arg1);NanoLogInternal::Log::r??ecordPrimitive(buffer,arg2);NanoLogInternal::日志::recordPrimitive(缓冲区，arg3);//在入口末尾记录字符串(ifany)memcpy(buffer,arg0,str0Len);buffer+=str0Len;*(reinterpret_cast::type>::type*>(buffer)-1)=L'\0';//MaketheentryvisibleNanoLogInternal::RuntimeLogger::finishAlloc(allocSize);}每个函数都包含一个特定的fmtId，日志压缩和解压也会使用这里生成的标识符，上面函数也会为参数分配内存空间，并调用recordPrimitive，以便将所有参数记录到缓冲区中压缩使用的compress也遵循类似的逻辑：inlinessize_tcompressArgs__E32374s3237424642lf__s46cc__100__(NanoLogInternal::Log::UncompressedEntry*re,char*out){char*originalOutPtr=out;//AllocatenibblesBufferUtils::TwoNibbles*nib=reinterpret_cast(out);out+=2;char*args=re->argData;//读回所有原语sintarg1;std::memcpy(&arg1,args,sizeof(int));args+=sizeof(int);intarg2;std::memcpy(&arg2,args,sizeof(int));args+=sizeof(int);doublearg3;std::memcpy(&arg3,args,sizeof(double));args+=sizeof(double);//Packalltheprimitivesnib[0].first=0x0f&static_cast(BufferUtils::pack(&out,arg1));nib[0].second=0x0f&static_cast(BufferUtils::pack(&out,arg2));nib[1].first=0x0f&static_cast(BufferUtils::pack(&out,arg3));if(true){//memcpyallthestringswithoutcompressionsize_tstringBytes=re->entrySize-(sizeof(arg1)+sizeof(arg2)+sizeof(arg3)+0)-sizeof(NanoLogInternal::日志::取消压缩essedEntry);if(stringBytes>0){memcpy(out,args,stringBytes);out+=stringBytes;}}returnout-originalOutPtr;}日志记录和压缩函数由Python预处理器生成分析源码。最开始使用的NANO_LOG会被预处理器扩展成新的代码。这个预处理器的功能和C++的预处理器非常相似，但是这里需要扩展的代码太复杂了，我们在C++中使用预处理器比较困难。处理器实现运行时应用静态链接NanoLog运行时通过线程上的缓冲区将记录动态参数的低延迟记录操作和磁盘I/O等高延迟操作解耦。线程上的缓冲区会存储record方法调用的结果，这些数据对于后台压缩线程也是可见的：图4-运行时线程上用来临时存储数据的缓冲区是提升性能的关键程序。我们应该尽量满足避免锁竞争和缓存一致性带来的额外开销的需要，临时缓冲区使用循环队列和单生产者消费者模型来减少数据同步开销。图5-环形队列环形队列是一种使用固定大小缓存的连续数据结构。它的头尾相连，非常适合缓存数据流。Linux内核将这个数据结构作为Socket读写缓冲区[^2]，音视频也会使用环形队列来暂存刚刚接收到还没有解码的数据。struct__kfifo{unsignedintin;unsignedintout;unsignedintmask;unsignedintesize;void*data;};运行时除了通过无锁环形队列提升性能外，还需要解决环形队列中的日志消耗问题。为了提高后台线程的处理能力，运行时会将日志的组装推迟到后处理，并对日志数据进行压缩，以减少高I/O延迟的影响。后处理后处理器的实现比较简单，因为每条日志都包含一个特定的标识符，后处理器会根据标识符在压缩的日志头中找到编译时产生的相关信息，展开并解包日志。需要注意的是，由于每个线程在运行过程中都有自己的临时缓冲区来存放日志，所以NanoLog最终打印出来的日志并不能严格保证时间顺序，只能保证日志输出的顺序一般是有序的。总结NanoLog是一个设计非常有趣，值得学习的日志系统，但它并不适合所有的项目。它将运行时需要做的工作转移到编译和后处理阶段，减轻了程序运行时的负担，但是其输出的二进制日志不能直接读取，这也增加了开发者处理日志的工作量.虽然论文中提到日志分析引擎基本上是收集、解析、分析工程师可以直接读取的日志，大部分时间都花在了读取和解析日志上，但是使用二进制日志不仅可以减少读取和解析时间，还可以减少昂贵的开销I/O和使用的带宽，但这在我们的系统中是否是一个优势是一个见仁见智的问题。日志使用二进制输出格式确实可以在很多方面降低成本，但不仅需要日志采集解析系统的支持，而且牺牲了开发者的本地调试体验。如果没有自动收集和解压日志的模块，手动解压线路去日志排查问题是一种非常糟糕的体验，但在极端性能场景下，我们可能没有太多选择，即使体验可能会有所牺牲。
