一个轻巧高效的多线程c++stream风格异步日志(一)

短命女 2022-05-15 03:41 500阅读 0赞

## 一个轻巧高效的多线程c++stream风格异步日志 ##

*   *  一个轻巧高效的多线程c++stream风格异步日志
        
         *  前言
         *  功能需求
         *  性能需求
         *  Logger实现
            
             *  LogStream类
             *  Logger类
             *  LogStream及Logger cpp源码

--------------------

### 前言 ###

本文主要实现muduo的异步日志.省去boost库中特性的引用,轻巧简洁。

对于编程而言,日志是必不可少的,对于关键进程,日志通常需要记录：  
1.收到的每条内部消息id.  
2.收到的每条外部消息全文.  
3.发出的每条消息全文,每条消息都有全局唯一的id.  
4.关键内部状态变更，等等.  
5.每条日志都有时间戳,以方便的追踪分布式系统中一个时间的来龙去脉.

c++日志大体上有两种API风格:  
`C/JAVA的printf(fmt, ...)风格：`  
log\_info(“received %d bytes from %s”, len, getName.c\_str());  
`c++的stream<<风格：`  
LOG\_INFO << “received << len << bytes from << getName.c\_str();

本文实现的是c++的stream风格, 优点是使用起来更自然，不用保持格式的一致性.

### 功能需求 ###

常规的通用日志库如log4j/logback通常会提供丰富的功能,但不一定是必须的功能.

1.日志有多种级别：TRACE、DEBUG、INFO、WARN、ERROR、FATAL等。  
2.日志可能会有多个目的地：文件、socket、SMTP等。  
3.日志消息格式可配置。  
4.可设置运行时过滤器(filter)、控制不同的组件的日志消息级别和目的地.

这四项中,除了第一项之外,其余并非是必须的功能.本文内容只包含第一项功能.  
对于分布式系统中的服务进程而言,日志的目的地只有一个：本地文件,往网络写日志消息是不可靠的，另一个坏处就是网络带宽的消耗.

muduo日志格式如下，本日志对格式有所改动，但基本信息不变。

日期          时间   微妙   线程  级别  函数名   正文       源文件名: 行号
    20180802 12:42:50.621354 44321 WARN  main just test - test.cpp:445
    20180802 12:42:50.621359 44321 INFO  main just test - test.cpp:446
    20180802 12:42:50.621364 44321 ERROR main just test - test.cpp:447

*  **时间戳精确到微妙，每条消息通过gettimeofday(2)获取当前时间.这样做不会有什么性能损失,在x86-64Linux上,gettimeofday()不是系统调用,不会陷入内核**
 *  **打印线程ID,便于分析多线程程序时序,也可以检测死锁**(未加入)
 *  **打印日志级别,通过查看有无ERROR日志快速定位**
 *  **打印文件名和行号,修复问题不至于搞错对象**
 *  **每条日志尽量占一行,便于分析日志**

### 性能需求 ###

只有日志库足够高效，程序员才敢在代码中输出足够多的诊断信息，减小运维难度，提升效率.它体现在：

*  **每秒几千万条日志没有明显的性能损失**
 *  **能应对一个进程产生大量日志数据的场景，如1GB/min。**
 *  **不阻塞正常的执行流程**
 *  **在多线程程序中，不造成争用**

为了实现性能指标，本日志设计中几点优化：

*  **时间戳字符串中的日期和时间两部分是缓存的,一秒之内的多条日志只需格式化微妙即可**
 *  **日志消息 的前四段是定长的,可避免运行时字串长度的计算**
 *  **线程id是预先格式化的字符串**
 *  **原文件名部分通过编译期计算来获得,避免运行期strrchr()的开销**

### Logger实现 ###

#### LogStream类 ####

LogStream类，主要作用是重载<<操作符，将基本类型的数据格式成字符串通过append接口存入LogBuffer中。  
![Alt text][]

#ifndef _LOG_STREAM_HH
    #define _LOG_STREAM_HH
    #include <stdio.h>
    #include <string.h>
    
    const int kSmallBuffer = 4096;
    const int kLargeBuffer = 4096;
    
    template<int SIZE>
    class LogBuffer
    {
    public:
        LogBuffer(): m_cur(m_data){
        }
    
        ~LogBuffer(){
            //printf("%s", m_data);
        }
    
        void append(const char* /*restrict*/ buf, size_t len){
        // append partially
            if (/*implicit_cast<size_t>*/(avail()) > len)
            {
                memcpy(m_cur, buf, len);
                m_cur += len;
            }
        }
    
        // write in m_data directly
        char* current() {  return m_cur; };
        int avail() const { return static_cast<int> (end() - m_cur); }
        void add(size_t len) { m_cur += len; }
        int length() const {
       return m_cur - m_data;}
    
        const char* data() const { return m_data; }
    
    private:
        const char* end() const { return m_data + sizeof(m_data); }
    
        char m_data[SIZE];
        char* m_cur;
    };
    
    class LogStream{
    public:
        LogStream();
        ~LogStream();
    
        typedef LogBuffer<kSmallBuffer> Buffer;
        typedef LogStream self;
        self& operator<<(bool v);
    
        self& operator<<(short);
        self& operator<<(unsigned short);
        self& operator<<(int);
        self& operator<<(unsigned int);
        self& operator<<(long);
        self& operator<<(unsigned long);
        self& operator<<(long long);
        self& operator<<(unsigned long long);
    
        self& operator<<(const void*);
    
        self& operator<<(float v);
        self& operator<<(double);
    
        self& operator<<(char v);
        self& operator<<(const char *);
    
        void append(const char* data, int len) { return m_buffer.append(data, len); }
        const Buffer& buffer() const { return m_buffer; }
    
    private:
        LogStream(const LogStream& ls);         //no copyable
        LogStream& operator=(const LogStream& ls);
    
        template<typename T>
        void formatInteger(T v);
    
        Buffer m_buffer;
        static const int kMaxNumericSize = 32;
    
    };
    
    class Fmt{
    public:
        template<typename T>
        Fmt(const char* fmt, T val);
    
        const char* data() const { return m_buf; }
        int length() const { return m_length; }
    
    private:
        char m_buf[32];
        int m_length;
    };
    
    inline LogStream& operator<<(LogStream &s, const Fmt& fmt){
        s.append(fmt.data(), fmt.length());
        return s;
    }
    
    #endif

#### Logger类 ####

Logger类，使用LogStream的<<操作符将文件名，日志级别，时间等信息格式好提前写入LogBuffer中.  
它实际上是一个临时对象,通过宏定义临时构造一个logger对象，构造的时候即将上面信息写入LogBuffer,之后通过stream()接口引用LogStream的<<操作符写入我们的日志信息.  
优点是 ：对于日志级别低的log那么它将是一个空的操作.

// CAUTION: do not write:
    //
    // if (good)
    //   LOG_INFO << "Good news";
    // else
    //   LOG_WARN << "Bad news";
    //
    // this expends to
    //
    // if (good)
    //   if (logging_INFO)
    //     logInfoStream << "Good news";
    //   else
    //     logWarnStream << "Bad news";
    //
    #define LOG_TRACE if (Logger::logLevel() <= Logger::TRACE) \
        Logger(__FILE__, __LINE__, Logger::TRACE, __func__).stream()
    #define LOG_DEBUG if (Logger::logLevel() <= Logger::DEBUG) \
        Logger(__FILE__, __LINE__, Logger::DEBUG, __func__).stream()
    #define LOG_INFO if (Logger::logLevel() <= Logger::INFO) \
        Logger(__FILE__, __LINE__).stream()
    #define LOG_WARN Logger(__FILE__, __LINE__, Logger::WARN).stream()
    #define LOG_ERROR Logger(__FILE__, __LINE__, Logger::ERROR).stream()
    #define LOG_FATAL Logger(__FILE__, __LINE__, Logger::FATAL).stream()
    #define LOG_SYSERR Logger(__FILE__, __LINE__, false).stream()
    #define LOG_SYSFATAL Logger(__FILE__, __LINE__, true).stream()

它的成员结构如下图所示:  
Impl对象是个私有类,主要是为了闭源，构造Impl的时候后写入时间戳，日志级别，文件名等等.  
logLevel()、setlogLevel()、为两个静态成员函数，用于设置日志级别.  
setOutput()也是个静态成员函数，主要作用是重定向日志的输出.默认是输出至stdout.

![这里写图片描述][70]

#ifndef _LOGGER_HH
    #define _LOGGER_HH
    
    #include <string.h>
    #include "LogStream.hh"
    #include "TimeStamp.hh"
    
    // CAUTION: do not write:
    //
    // if (good)
    //   LOG_INFO << "Good news";
    // else
    //   LOG_WARN << "Bad news";
    //
    // this expends to
    //
    // if (good)
    //   if (logging_INFO)
    //     logInfoStream << "Good news";
    //   else
    //     logWarnStream << "Bad news";
    //
    #define LOG_TRACE if (Logger::logLevel() <= Logger::TRACE) \
        Logger(__FILE__, __LINE__, Logger::TRACE, __func__).stream()
    #define LOG_DEBUG if (Logger::logLevel() <= Logger::DEBUG) \
        Logger(__FILE__, __LINE__, Logger::DEBUG, __func__).stream()
    #define LOG_INFO if (Logger::logLevel() <= Logger::INFO) \
        Logger(__FILE__, __LINE__).stream()
    #define LOG_WARN Logger(__FILE__, __LINE__, Logger::WARN).stream()
    #define LOG_ERROR Logger(__FILE__, __LINE__, Logger::ERROR).stream()
    #define LOG_FATAL Logger(__FILE__, __LINE__, Logger::FATAL).stream()
    #define LOG_SYSERR Logger(__FILE__, __LINE__, false).stream()
    #define LOG_SYSFATAL Logger(__FILE__, __LINE__, true).stream()
    
    class Logger
    {
    public:
        enum LogLevel
        {
            TRACE,
            DEBUG,
            INFO,
            WARN,
            ERROR,
            FATAL,
            NUM_LOG_LEVELS,
        };
    
    //compile time calculation of basename of source file
        class SourceFile
        {
        public:
            template<int N>
            inline SourceFile(const char (&arr)[N])
                :m_data(arr),
                 m_size(N-1){
                const char* slash = strrchr(m_data, '/'); // builtin function
                if (slash){
                    m_data = slash + 1;
                    m_size -= static_cast<int>(m_data - arr);
                }
            }
    
            explicit SourceFile(const char* filename)
                : m_data(filename){
                const char* slash = strrchr(filename, '/');
                if (slash){
                    m_data = slash + 1;
                }
                m_size = static_cast<int>(strlen(m_data));
            }
    
            const char* m_data;
            int m_size;
        };
    
        Logger(SourceFile file, int line);
        Logger(SourceFile file, int line, LogLevel level);
        Logger(SourceFile file, int line, LogLevel level, const char* func);
        Logger(SourceFile file, int line, bool toAbort);
        ~Logger();
    
        static void setLogLevel(LogLevel level);
        static LogLevel logLevel();
    
        LogStream& stream() { return m_impl.m_stream; }
    
        typedef void (*outputFunc)(const char *msg, int len);
        typedef void (*flushFunc)();
    
        static void setOutput(outputFunc);
        static void setFlush(flushFunc);
    
    private:
        Logger(const Logger &lg);           //no copyable
        Logger& operator=(const Logger &lg);
    
        class Impl
        {
        public:
            typedef Logger::LogLevel LogLevel;
            Impl(LogLevel level, int old_errno, const SourceFile& file, int line);
            void formatTime();
            void finish();
    
            TimeStamp m_time;
            LogStream m_stream;
            LogLevel m_level;
            int m_line;
            SourceFile m_fileBaseName;
        };
    
        Impl m_impl;
    
    };
    
    #endif

完成Logger即可直接使用了。  
直接通过宏LOG\_DEBUG << 即可打印格式化好的日志信息. 只是默认输出到stdout.  
后面文章会给出日志文件类及异步线程类的实现.

#### LogStream及Logger cpp源码 ####

//LogStream
    #include <stdio.h>
    #include <assert.h>
    #include <algorithm>
    #include "LogStream.hh"
    
    LogStream::LogStream(){
    }
    
    LogStream::~LogStream(){
    }
    
    LogStream& LogStream::operator<<(bool v){
        m_buffer.append(v ? "1" : "0", 1);
        return *this;
    }
    
    
    LogStream& LogStream::operator<<(short v){
        *this << static_cast<int>(v);
        return *this;
    }
    
    LogStream& LogStream::operator<<(unsigned short v)
    {
      *this << static_cast<unsigned int>(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(int v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(unsigned int v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(long v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(unsigned long v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(long long v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(unsigned long long v)
    {
      formatInteger(v);
      return *this;
    }
    
    LogStream& LogStream::operator<<(const void*){
        printf("undefine\n");
    }
    
    LogStream& LogStream::operator<<(float v)
      {
        *this << static_cast<double>(v);
        return *this;
      }
    
    LogStream& LogStream::operator<<(double v){
        if(m_buffer.avail() >= kMaxNumericSize){
            int len = snprintf(m_buffer.current(), kMaxNumericSize, "%.12g", v);
            m_buffer.add(len);
        }
        return *this;
    }
    
    LogStream& LogStream::operator<<(char v){
        m_buffer.append(&v, 1);
        return *this;
    }
    
    LogStream& LogStream::operator<<(const char *str){
        if(str){
            m_buffer.append(str, strlen(str));
        }else{
            m_buffer.append("(NULL)", 6);
        }
    
        return *this;
    }
    
    const char digits[] = "9876543210123456789";
    const char* zero = digits + 9;
    
    //convert to str
    template<typename T>
    size_t convert(char buf[], T value){
        T i = value;
        char *p = buf;
    
        do{
            int lsd = static_cast<int>(i % 10);
            i /= 10;
            *p++ = zero[lsd];
        } while(i != 0);
    
        if(value < 0){
            *p++ = '-';
        }
    
        *p = '\0';
        std::reverse(buf, p);
    
        return p - buf;
    }
    
    template<typename T>
    void LogStream::formatInteger(T v)
    {
        if(m_buffer.avail() >= kMaxNumericSize){
            size_t len = convert(m_buffer.current(), v);
            m_buffer.add(len);
        }
    }
    
    template<typename T>
    Fmt::Fmt(const char* fmt, T val)
    {
        m_length = snprintf(m_buf, sizeof(m_buf), fmt, val);
        assert(static_cast<size_t>(m_length) < sizeof(m_buf));
    }
    
    // Explicit instantiations
    
    template Fmt::Fmt(const char* fmt, char);
    
    template Fmt::Fmt(const char* fmt, short);
    template Fmt::Fmt(const char* fmt, unsigned short);
    template Fmt::Fmt(const char* fmt, int);
    template Fmt::Fmt(const char* fmt, unsigned int);
    template Fmt::Fmt(const char* fmt, long);
    template Fmt::Fmt(const char* fmt, unsigned long);
    template Fmt::Fmt(const char* fmt, long long);
    template Fmt::Fmt(const char* fmt, unsigned long long);
    
    template Fmt::Fmt(const char* fmt, float);
    template Fmt::Fmt(const char* fmt, double);
    
    
    
    //Logger
    
    #include <time.h>
    #include <stdint.h>
    #include <stdlib.h>
    #include <assert.h>
    #include <stdio.h>
    #include <errno.h>
    #include <string.h>
    #include "TimeStamp.hh"
    #include "Logger.hh"
    
    __thread char t_time[64];
    __thread time_t t_lastSecond;
    __thread char t_errnobuf[512];
    
    const char* strerror_tl(int savedErrno)
    {
      return strerror_r(savedErrno, t_errnobuf, sizeof(t_errnobuf));
    }
    
    Logger::LogLevel g_logLevel = Logger::INFO;
    
    void Logger::setLogLevel(LogLevel level){
        g_logLevel = level;
    }
    
    Logger::LogLevel Logger::logLevel(){
        return g_logLevel;
    }
    
    const char* LogLevelName[Logger::NUM_LOG_LEVELS] =
    {
        "[TRACE]",
        "[DEBUG]",
        "[INFO ]",
        "[WARN ]",
        "[ERROR]",
        "[FATAL]",
    };
    
    // helper class for known string length at compile time
    class T
    {
     public:
      T(const char* str, unsigned len)
        :m_str(str),
         m_len(len)
      {
        assert(strlen(str) == m_len);
      }
    
      const char* m_str;
      const unsigned m_len;
    };
    
    void defaultOutput(const char *msg, int len){
        size_t n = fwrite(msg, 1, len, stdout);
        (void)n;
    }
    
    void defaultFlush(){
        fflush(stdout);
    }
    
    Logger::outputFunc g_output = defaultOutput;
    Logger::flushFunc g_flush = defaultFlush;
    
    void Logger::setOutput(outputFunc out){
        g_output = out;
    }
    
    void Logger::setFlush(flushFunc flush){
        g_flush = flush;
    }
    
    Logger::Logger(SourceFile file, int line)
        : m_impl(INFO, 0, file, line){
    }
    
    Logger::Logger(SourceFile file, int line, LogLevel level)
        : m_impl(level, 0, file, line){
    }
    
    Logger::Logger(SourceFile file, int line, bool toAbort)
        : m_impl(toAbort? FATAL:ERROR, errno, file, line){
    }
    
    Logger::Logger(SourceFile file, int line, LogLevel level, const char* func)
        : m_impl(level, 0, file, line){
        m_impl.m_stream << '[' << func << "] ";
    }
    
    Logger::~Logger(){
        m_impl.finish();
        const LogStream::Buffer& buf(stream().buffer());
        g_output(buf.data(), buf.length());
        if (m_impl.m_level == FATAL)
        {
            g_flush();
            abort();
        }
    }
    
    Logger::Impl::Impl(LogLevel level, int savedErrno, const SourceFile& file, int line)
        : m_time(TimeStamp::now()),
          m_stream(),
          m_level(level),
          m_fileBaseName(file),
          m_line(line)
    {
        formatTime();
        m_stream << LogLevelName[level] << ' ';
        m_stream << '[' << m_fileBaseName.m_data << ':' << m_line << "] ";
        if (savedErrno != 0)
        {
            m_stream << strerror_tl(savedErrno) << " (errno=" << savedErrno << ") ";
        }
    }
    
    void Logger::Impl::finish()
    {
        m_stream<< '\n';
    }
    
    void Logger::Impl::formatTime()
    {   
        int64_t microSecondsSinceEpoch = m_time.microSecondsSinceEpoch();
        time_t seconds = static_cast<time_t>(microSecondsSinceEpoch / TimeStamp::kMicroSecondsPerSecond);
        int microseconds = static_cast<int>(microSecondsSinceEpoch % TimeStamp::kMicroSecondsPerSecond);
        if (seconds != t_lastSecond){
            t_lastSecond = seconds;
            struct tm tm_time;
    
            ::gmtime_r(&seconds, &tm_time); // FIXME TimeZone::fromUtcTime
    
            int len = snprintf(t_time, sizeof(t_time), "%4d-%02d-%02d %02d:%02d:%02d",
            tm_time.tm_year + 1900, tm_time.tm_mon + 1, tm_time.tm_mday,
            tm_time.tm_hour + 8, tm_time.tm_min, tm_time.tm_sec);
            assert(len == 19); (void)len;
        }
    
        Fmt us(".%06d ", microseconds);
        assert(us.length() == 8);
        m_stream << t_time << us.data();
    }

[Alt text]: /images/20220515/cbe13ffc2b654c6186ca5dfb4234f4dc.png
[70]: /images/20220515/5136b0a53b2645b2858395d5f3a277d7.png