本文基于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:

on

off CPU:

off

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

localtime_r的调用

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

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

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

参考:

减少全局锁

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

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