glog C++版本代码分析

2019-07-29

6分钟阅读时长

网络编程

本文基于glog CPP版本的0.4.0版本，对glog的实现机制做一些简单的分析记录。

概述

要记录一条日志，分为两个阶段：

首先生成日志。
然后将日志内容输出到相应的设备，如标准输出、文件等。

以下就分两部分展开对glog的分析。

日志的生成

一般有两种生成日志数据的方式：

类printf的方式，将需要输入的数据格式化。
类C++ stream流的方式，提供出来operator «操作符供输入数据。

前者的好处在于可以对输入的数据格式进行严格检查，不匹配的情况下编译器会进行告警。缺点则是不够灵活。后者的好处是灵活，除了用了进行一般的日志输入，还可以写出类似

CHECK_IF(某条件不成立) << 输出日志

的操作。

glog中选择了第二种方式。

首先来看glog对外暴露的用于日志输入的接口。其对应的宏是：

#define LOG(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()

#define COMPACT_GOOGLE_LOG_INFO google::LogMessage( \
    __FILE__, __LINE__)
#define COMPACT_GOOGLE_LOG_WARNING google::LogMessage( \
    __FILE__, __LINE__, google::GLOG_WARNING)

从中可以看到glog中每一条日志，都对应一个LogMessage的类，然后将返回其中的stream()对象输入日志数据。

每个LogMessage内部有一个名为LogMessageData的成员，用于保存这些数据，其中比较重要的成员有以下几个：

char message_text_[LogMessage::kMaxLogMessageLen+1]; // 用户存储日志的固定长度数组，大小为30KB。
LogStream stream_; // 用于接收用户日志的C++stream，构造时传入上面的message_text_来构造，所以实际写数据会到message_text_中。
void (LogMessage::*send_method_)(); // 用户最终发送日志数据的函数指针。
timestamp_、tm_time_：保存日志时间相关的成员。

实际根据日志创建出一个LogMessage对象时，会根据不同类型的日志，传入不同的send_method函数指针，而每个不同的LogMessage构造时都会去调用其内部的Init函数完成LogMessageData的构造，Init函数主要做的事情有：

存储send_method函数指针。
获取当前的系统时间，存放到相应的成员中。

而LOG之类的宏，实际返回的就是LogMessageData的stream指针，待到一切的输入完毕，这一条日志对应的LogMessage就会被析构，其析构函数内又会调用成员函数Flush，这个函数最终完成将日志输出的操作：

void LogMessage::Flush() {
  // ...
  {
    MutexLock l(&log_mutex);
    (this->*(data_->send_method_))();
    ++num_messages_[static_cast<int>(data_->severity_)];
  }
  // ...
}

有了以上的准备，实际回头来看一个日志的输入

log-generate

输出日志

以上解决了生成日志的问题，继续往下看生成日志之后发到哪里去。

日志的分发由类LogDestination来负责，其提供出去的接口多为静态函数。以某个send_method函数的实现来看，如LogMessage::SendToLog，省略大部分细节，其内部实现为：

void LogMessage::SendToLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) {
    // ...

    // log this message to all log files of severity <= severity_
    LogDestination::LogToAllLogfiles(data_->severity_, data_->timestamp_,
                                     data_->message_text_,
                                     data_->num_chars_to_log_);
    LogDestination::LogToSinks(data_->severity_,
                           data_->fullname_, data_->basename_,
                           data_->line_, &data_->tm_time_,
                           data_->message_text_ + data_->num_prefix_chars_,
                           (data_->num_chars_to_log_
                            - data_->num_prefix_chars_ - 1));
    // ...
}

其中：

LogDestination::LogToAllLogfiles：写日志到对应级别的日志文件中。
LogDestination::LogToSinks：写到用户自定义的sink输出中，传递那么多参数是为了去掉添加进去的logprefix，包括severity，ts，线程id，文件basename等。

接下来分别分析这两部分输出的操作。

写到对应级别的日志中

LogDestination内部有一个与不同日志级别相关的LogDestination数组：

static LogDestination* log_destinations_[NUM_SEVERITIES];

首先来看LogToAllLogfiles函数的实现：

inline void LogDestination::LogToAllLogfiles(LogSeverity severity,
                                             time_t timestamp,
                                             const char* message,
                                             size_t len) {

  if ( FLAGS_logtostderr ) {           // global flag: never log to file
    ColoredWriteToStderr(severity, message, len);
  } else {
    for (int i = severity; i >= 0; --i)
      LogDestination::MaybeLogToLogfile(i, timestamp, message, len);
  }
}

可以看到，对某个级别的日志而言，会依次调用级别值更小的日志输出，比如WARN级别的日志也会输出到INFO级别的日志文件中。

接着看MaybeLogToLogfile函数的实现：

inline void LogDestination::MaybeLogToLogfile(LogSeverity severity,
                                              time_t timestamp,
					      const char* message,
					      size_t len) {
  const bool should_flush = severity > FLAGS_logbuflevel;
  LogDestination* destination = log_destination(severity);
  destination->logger_->Write(should_flush, timestamp, message, len);
}

inline LogDestination* LogDestination::log_destination(LogSeverity severity) {
  assert(severity >=0 && severity < NUM_SEVERITIES);
  if (!log_destinations_[severity]) {
    log_destinations_[severity] = new LogDestination(severity, NULL);
  }
  return log_destinations_[severity];
}

可以看到：

首先会从log_destination中根据日志级别，得到对应的log_destinations_数组成员返回。
然后调用destination->logger_成员的Write函数写日志，其中会传入一个叫should_flush的参数，仅在传入的日志级别大于FLAGS_logbuflevel才会为真，这样可以控制不同级别日志的flush到磁盘的行为。

而logger_成员是一个Logger接口，本质上是一个纯虚类，因此glog也提供了接口给用户定制不同级别日志对应的Logger类：

// Set the logger for the specified severity level.  The logger
// becomes the property of the logging module and should not
// be deleted by the caller.  Thread-safe.
extern GOOGLE_GLOG_DLL_DECL void SetLogger(LogSeverity level, Logger* logger);

写到用户自定义sink中

接下来看看怎么将日志输出到用户自定义sink中的流程。

而每个LogDestination内部又有一个叫LogSink的类来真正负责日志的输出，该类也是一个纯虚类，用户需要实现其中的send方法来完成日志的输出。对于每个级别的日志而言，会将同级别的LogSink一起放在一个向量中：

static vector<LogSink*>* sinks_

因此，当需要输出自定义的日志时，就遍历该向量进行调用：

inline void LogDestination::LogToSinks(LogSeverity severity,
                                       const char *full_filename,
                                       const char *base_filename,
                                       int line,
                                       const struct ::tm* tm_time,
                                       const char* message,
                                       size_t message_len) {
  ReaderMutexLock l(&sink_mutex_);
  if (sinks_) {
    for (int i = sinks_->size() - 1; i >= 0; i--) {
      (*sinks_)[i]->send(severity, full_filename, base_filename,
                         line, tm_time, message, message_len);
    }
  }
}

log-output

性能分析

写了一个简单的测试程序，起多个线程同时一起使用glog写入日志，用火焰图分别分析它的on和off CPU消耗如下：

on CPU：

off CPU：

off

从上面的火焰图可以看到几个优化点。

localtime_r的调用

在前面分析到的LogMessage::Init函数中，会调用localtime_r函数获得当前时区的时间，但是该函数有几个大问题：

本质上是一个传入当前秒数，然后根据时区将这个秒数转换成时区所在地时间的函数，然而由于需要加锁获取时区，所以每次调用该函数glibc内部的实现都需要加锁操作，表现在off CPU的火焰图中，就是__tz_convert这个函数的调用。
由于加锁，导致这个函数如果被信号中断然后又在信号处理中继续被调用，可能会导致死锁现象。

因此，优化的方式是自己实现一个完成相同功能的函数，而在传入参数中需要提供时区值，这样就变成了一个纯CPU肌酸而不需要加锁的操作。我单独把localtime和优化版本拿出来对比压测，能有很大的提升。

参考：

localtime函数死锁分析

减少全局锁

前面分析到，在调用send_method之前需要全局加锁，从火焰图分析来看，确实也在这里耗费了相当的时间。

有些人提出了一种异步日志数据的方式，即独立出来一个日志线程，将日志都发往这个线程里面，而发送的流程可以使用无锁队列等机制减少锁的消耗，见 Efficient logging in multithreaded C++ server