glog C++版本代码分析 - codedump的网络日志
source link: https://www.codedump.info/post/20190729-glog/?
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
本文基于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_)]; // ... |
有了以上的准备，实际回头来看一个日志的输入
以上解决了生成日志的问题，继续往下看生成日志之后发到哪里去。
日志的分发由类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); |
写了一个简单的测试程序，起多个线程同时一起使用glog写入日志，用火焰图分别分析它的on和off CPU消耗如下：
on CPU：
off CPU：
从上面的火焰图可以看到几个优化点。
localtime_r的调用
在前面分析到的LogMessage::Init函数中，会调用localtime_r函数获得当前时区的时间，但是该函数有几个大问题：
- 本质上是一个传入当前秒数，然后根据时区将这个秒数转换成时区所在地时间的函数，然而由于需要加锁获取时区，所以每次调用该函数glibc内部的实现都需要加锁操作，表现在off CPU的火焰图中，就是__tz_convert这个函数的调用。
- 由于加锁，导致这个函数如果被信号中断然后又在信号处理中继续被调用，可能会导致死锁现象。
因此，优化的方式是自己实现一个完成相同功能的函数，而在传入参数中需要提供时区值，这样就变成了一个纯CPU肌酸而不需要加锁的操作。我单独把localtime和优化版本拿出来对比压测，能有很大的提升。
减少全局锁
前面分析到，在调用send_method之前需要全局加锁，从火焰图分析来看，确实也在这里耗费了相当的时间。
有些人提出了一种异步日志数据的方式，即独立出来一个日志线程，将日志都发往这个线程里面，而发送的流程可以使用无锁队列等机制减少锁的消耗，见 Efficient logging in multithreaded C++ server
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK