C++中glog源码剖析以及如何设计一个高效 log模块

每个开发者编程中都会记录log信息，多数人都会使用log第三方库，log库使用起来很方便，但我们也需要了解log系统的原理，这里以glog为例进行分析。

开始

这里不会介绍glog中是如何控制INFO、ERROR等级别的输出的，其实就是一个宏控制，主要介绍google glog中一次LOG(INFO)过程中究竟发生了什么，以及为什么glog是线程安全的。

glog中的LOG(INFO)其实是一个宏定义，如下：

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

那么LOG(INFO)相当于
COMPACT_GOOGLE_LOG_INFO.stream()

而COMPACT_GOOGLE_LOG_INFO也是一个宏，如下：

#define COMPACT_GOOGLE_LOG_INFO google::LogMessage(__FILE__, __LINE__)
那么LOG(INFO)相当于
COMPACT_GOOGLE_LOG_INFO.stream()也就相当于
google::LogMessage(__FILE__, __LINE__).stream()

这里就构造了一个google::LogMessage的临时对象，语句执行完就会自动析构，google::LogMessage的大体结构如下：

// 这里是摘下来的极简版，实际比这复杂很多
class LogMessage {
 LogMessageData::LogStream stream_; // 自定义的输出流，继承的std::ostream
 LogMessage(const char* file, int line);
 ~LogMessage(); // 在析构函数中有大量逻辑，后面讲解
 std::ostream& stream(); // 返回stream_
 void SendToLog(); // 主要函数
 void Init(const char* file, int line, LogSeverity severity,
 void (LogMessage::*send_method)());
 void Flush();
 LogMessageData* allocated_; // LogMessageData，主要的结构体
 LogMessageData* data_;
};

LogMessage的构造函数如下：

LogMessage::LogMessage(const char* file, int line)
 : allocated_(NULL) {
 Init(file, line, GLOG_INFO, &LogMessage::SendToLog);
}

Init函数精简版如下：

void LogMessage::Init(const char* file,
 int line,
 LogSeverity severity,
 void (LogMessage::*send_method)()) {
 allocated_ = NULL;
 // 主要看这里，glog比较高效的地方就在于它没有频繁的申请内存，而是使用线程thread_local特性，为每个线程创建一块私有内存，同一线程频繁的使用这块内存构造LogMessageData的对象，因为这个LogMessageData对象是临时对象，每次都会立刻析构，这样下一个对象可以重复在这块内存地址来构造对象
 if (thread_data_available) {
 thread_data_available = false;
 // 这里会将LogMessageData对象构造在内存对齐的地址上，HAVE_ALIGNED_STORAGE这个宏在C++11后会有效，C++11前就会走到这个#else分支，需要自己进行手动内存对齐，为什么HAVE_ALIGNED_STORAGE宏下面的代码可以直接构造对象，下面会介绍
 #ifdef HAVE_ALIGNED_STORAGE
 data_ = new (&thread_msg_data) LogMessageData;
 #else
 const uintptr_t kAlign = sizeof(void*) - 1;

 char* align_ptr =
 reinterpret_cast(reinterpret_cast(thread_msg_data + kAlign) & ~kAlign);
 data_ = new (align_ptr) LogMessageData;
 assert(reinterpret_cast(align_ptr) % sizeof(void*) == 0);
 #endif
 } else {
 allocated_ = new LogMessageData();
 data_ = allocated_;
 }
 // 下面这一堆代码就是在每一行log具体信息前加上一些信息前缀，时间戳线程号文件名行数等等
 stream().fill('0');
 data_->preserved_errno_ = errno;
 data_->severity_ = severity;
 data_->line_ = line;
 data_->send_method_ = send_method;
 data_->sink_ = NULL;
 data_->outvec_ = NULL;
 WallTime now = WallTime_Now();
 data_->timestamp_ = static_cast(now);
 localtime_r(&data_->timestamp_, &data_->tm_time_);
 int usecs = static_cast((now - data_->timestamp_) * 1000000);

 data_->num_chars_to_log_ = 0;
 data_->num_chars_to_syslog_ = 0;
 data_->basename_ = const_basename(file);
 data_->fullname_ = file;
 data_->has_been_flushed_ = false;

 // If specified, prepend a prefix to each line.  For example:
 //    I1018 160715 f5d4fbb0 logging.cc:1153]
 //    (log level, GMT month, date, time, thread_id, file basename, line)
 // We exclude the thread_id for the default thread.
 if (FLAGS_log_prefix && (line != kNoLogPrefix)) {
 stream() << LogSeverityNames[severity][0]
 << setw(2) << 1+data_->tm_time_.tm_mon
 << setw(2) << data_->tm_time_.tm_mday
 << ' '
 << setw(2) << data_->tm_time_.tm_hour  << ':'
 << setw(2) << data_->tm_time_.tm_min   << ':'
 << setw(2) << data_->tm_time_.tm_sec   << "."
 << setw(6) << usecs
 << ' '
 << setfill(' ') << setw(5)
 << static_cast(GetTID()) << setfill('0')
 << ' '
 << data_->basename_ << ':' << data_->line_ << "] ";
 }
 data_->num_prefix_chars_ = data_->stream_.pcount();
}

为什么HAVE_ALIGNED_STORAGE宏下面的代码可以直接构造对象呢？

看这里

#ifdef HAVE_ALIGNED_STORAGE
static GLOG_THREAD_LOCAL_STORAGE
 std::aligned_storage
		

			是因为C++11后可以直接使用std::aligned_storage来申请对齐的内存地址。
		
		

			LOG(INFO)<<”xxx”<<”yyy”中，glog是如何收集到xxx和yyy数据的呢？
		
		

			我们上面看到LogMessage的构造函数中会构造核心的LogMessageData对象，看如下LogMessageData的结构体和构造函数中的注释
		
struct LogMessage::LogMessageData  {
 LogMessageData();

 int preserved_errno_;      // preserved errno
 // Buffer space; contains complete message text.
 char message_text_[LogMessage::kMaxLogMessageLen+1]; // 这里存放log的具体信息
 LogStream stream_; // std::ostream
 char severity_;      // What level is this LogMessage logged at?
 int line_;                 // line number where logging call is.
 void (LogMessage::*send_method_)();  // Call this in destructor to send
 union {  // At most one of these is used: union to keep the size low.
 LogSink* sink_;             // NULL or sink to send message to
 std::vector* outvec_; // NULL or vector to push message onto
 std::string* message_;             // NULL or string to write message into
 };
 time_t timestamp_;            // Time of creation of LogMessage
 struct ::tm tm_time_;         // Time of creation of LogMessage
 size_t num_prefix_chars_;     // # of chars of prefix in this message
 size_t num_chars_to_log_;     // # of chars of msg to send to log
 size_t num_chars_to_syslog_;  // # of chars of msg to send to syslog
 const char* basename_;        // basename of file that called LOG
 const char* fullname_;        // fullname of file that called LOG
 bool has_been_flushed_;       // false => data has not been flushed
 bool first_fatal_;            // true => this was first fatal msg

 private:
 LogMessageData(const LogMessageData&);
 void operator=(const LogMessageData&);
};

LogMessage::LogMessageData::LogMessageData()
 : stream_(message_text_, LogMessage::kMaxLogMessageLen, 0) {
}
// 这里就不列出LogStream的构造函数啦，LogStream内部会使用到streambuf，而这个streambuf的地址就是上面LogMessageData构造函数中传入的message_text_地址，这样stream_接收到的所有的数据都会存到这个message_text_中.
		

			将stream接收到的数据都存到了messagetext中，那数据是如何写到文件中去的并且是线程安全的呢？
		
		

			这些逻辑都是在LogMessage的析构函数中，看精简代码：
		
LogMessage::~LogMessage() {
 Flush();// 主要功能在Flush函数中
 if (data_ == static_cast(&thread_msg_data)) {
 data_->~LogMessageData();
 thread_data_available = true;
 }
 else {
 delete allocated_;
 }
}
		

			Flush函数精简：
		
void LogMessage::Flush() {
 {
 MutexLock l(&log_mutex);// 注意，这里使用了全局log锁，所以写操作等等都是线程安全的，即没有出现日志错乱现象
 (this->*(data_->send_method_))(); // 这里的send_method_可以从上面Init函数中看见其实就是使用SendToLog()
 ++num_messages_[static_cast(data_->severity_)];
 }
}
		

			SendToLog函数精简：
		
void LogMessage::SendToLog() {
 // LogDestination类中有好多静态函数，LogToAllLogfiles和MaybeLogToStderr是两个常用的函数，一个写到文件中，一个写到输出流中, data->severity_这里指的是log级别，即INFO、WARNING或者ERROR等
 LogDestination::LogToAllLogfiles(data_->severity_, data_->timestamp_,
 data_->message_text_,
 data_->num_chars_to_log_);

 LogDestination::MaybeLogToStderr(data_->severity_, data_->message_text_,
 data_->num_chars_to_log_);
}
		

			LogDestination::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 {
 // 看这里，glog会把高级别的log也会写在低级别的log文件中，即ERROR的log也会出现在INFO的log文件中
 for (int i = severity; i >= 0; --i)
 LogDestination::MaybeLogToLogfile(i, timestamp, message, len);
 }
}
		

			LogDestination::MaybeLogToLogfile函数精简：
		
inline void LogDestination::MaybeLogToLogfile(LogSeverity severity,
 time_t timestamp,
 const char* message,
 size_t len) {
 const bool should_flush = severity > FLAGS_logbuflevel;
 // 这里每个log level都会有一个LogDestination的对象指针
 LogDestination* destination = log_destination(severity);
 // Write就是写文件操作
 destination->logger_->Write(should_flush, timestamp, message, len);
}
		

			glog中日志写到文件中是什么时候Flush到磁盘中的呢？
		
		

			看下destination->logger_->Write函数精简实现:
		
void LogFileObject::Write(bool force_flush,
 time_t timestamp,
 const char* message,
 int message_len) {
 MutexLock l(&lock_);

 // We don't log if the base_name_ is "" (which means "don't write")
 if (base_filename_selected_ && base_filename_.empty()) {
 return;
 }

 // If there's no destination file, make one before outputting
 // 没有创建文件那就创建一个文件，文件名中包含时间进程号等信息
 if (file_ == NULL) {
 // Try to rollover the log file every 32 log messages.  The only time
 // this could matter would be when we have trouble creating the log
 // file.  If that happens, we'll lose lots of log messages, of course!
 if (++rollover_attempt_ != kRolloverAttemptFrequency) return;
 rollover_attempt_ = 0;

 struct ::tm tm_time;
 localtime_r(×tamp, &tm_time);

 // The logfile's filename will have the date/time & pid in it
 ostringstream time_pid_stream;
 time_pid_stream.fill('0');
 time_pid_stream << 1900+tm_time.tm_year
 << setw(2) << 1+tm_time.tm_mon
 << setw(2) << tm_time.tm_mday
 << '-'
 << setw(2) << tm_time.tm_hour
 << setw(2) << tm_time.tm_min
 << setw(2) << tm_time.tm_sec
 << '.'
 << GetMainThreadPid();
 const string& time_pid_string = time_pid_stream.str();

 if (!CreateLogfile(time_pid_string)) {
 perror("Could not create log file");
 fprintf(stderr, "COULD NOT CREATE LOGFILE '%s'!\n",
 time_pid_string.c_str());
 return;
 }
 // 在文件的最开头写入log创建的相应信息
 // Write a header message into the log file
 ostringstream file_header_stream;
 file_header_stream.fill('0');
 file_header_stream << "Log file created at: "
 << 1900+tm_time.tm_year << '/'
 << setw(2) << 1+tm_time.tm_mon << '/'
 << setw(2) << tm_time.tm_mday
 << ' '
 << setw(2) << tm_time.tm_hour << ':'
 << setw(2) << tm_time.tm_min << ':'
 << setw(2) << tm_time.tm_sec << '\n'
 << "Running on machine: "
 << LogDestination::hostname() << '\n'
 << "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu "
 << "threadid file:line] msg" << '\n';
 const string& file_header_string = file_header_stream.str();

 const int header_len = file_header_string.size();
 fwrite(file_header_string.data(), 1, header_len, file_);
 file_length_ += header_len;
 bytes_since_flush_ += header_len;
 }

 // Write to LOG file
 if ( !stop_writing ) {
 // fwrite() doesn't return an error when the disk is full, for
 // messages that are less than 4096 bytes. When the disk is full,
 // it returns the message length for messages that are less than
 // 4096 bytes. fwrite() returns 4096 for message lengths that are
 // greater than 4096, thereby indicating an error.
 errno = 0;
 // 开始把数据写到log文件中
 fwrite(message, 1, message_len, file_);
 if ( FLAGS_stop_logging_if_full_disk &&
 errno == ENOSPC ) {  // disk full, stop writing to disk
 stop_writing = true;  // until the disk is
 return;
 } else {
 file_length_ += message_len;
 bytes_since_flush_ += message_len;
 }
 } else {
 if ( CycleClock_Now() >= next_flush_time_ )
 stop_writing = false;  // check to see if disk has free space.
 return;  // no need to flush
 }

 // See important msgs *now*.  Also, flush logs at least every 10^6 chars,
 // or every "FLAGS_logbufsecs" seconds.
 // 控制什么时候把文件内容Flush到磁盘中
 if ( force_flush ||
 (bytes_since_flush_ >= 1000000) ||
 (CycleClock_Now() >= next_flush_time_) ) {
 FlushUnlocked();
 }
}

// 这里是FlushUnlocked函数
void LogFileObject::FlushUnlocked(){
 if (file_ != NULL) {
 fflush(file_);
 bytes_since_flush_ = 0;
 }
 // Figure out when we are due for another flush.
 const int64 next = (FLAGS_logbufsecs
 * static_cast(1000000));  // in usec
 next_flush_time_ = CycleClock_Now() + UsecToCycles(next);
}
		

			从这里可以看到glog是根据内容长度和时间来控制是否Flush到磁盘中，有1000000字节没有被Flush就执行一次Flush操作，或者FLAGS_logbufsecs秒没有Flush也会执行一次Flush，这个FLAGS_logbufsecs默认是30，可以设置。
		
		

			总结
		
		

			glog通过重写std::ostream、std::stream_buf以及thread_local等技术实现了精简高效的日志输出功能，每行log语句都会创建一个LogMessage对象，通过LogMessage对象内部的stream收集需要输出的消息存到对象内部的栈内存message_text中，一行语句结束，LogMessage对象析构，析构时会把message_text中的数据写到文件和控制台里，写文件操作会每隔1000000字节或者每隔FLAGS_logbufsecs秒Flush到磁盘中。
		
		

			如何设计一个高效的log模块？
		
		

			从上述源码分析可知，glog是每次log都会执行写操作，并且写操作是等锁的，写文件本身就比较耗时，再加上等锁的时间，会阻塞当前写log的业务工作线程，所以glog在多线程中会导致应用程序性能不是特别好，所以如果能够减少阻塞工作线程的时间就可以设计出一个高效的log模块，将日志的写文件操作放在单独的线程中，参考陈硕muduo代码，log架构其实有很大改良空间。
		
		

			muduo async log日志逻辑
		
		

			muduo的异步日志是将写日志的操作放在单独的日志线程中，这里分为多个应用线程和专用的日志线程，同时有多块缓存，大概可以分为两大块缓存池，有收集日志的缓存池和专用于写日志的缓存池，收集日志的缓存池(buffer_vector)中有两块buffer，称为current_buffer和next_buffer，多个应用线程的日志都会写到current_buffer(buffer_mutex)中，当current_buffer满的时候，将current_buffer的指针存到buffer_vector中，同时current_buffer的指针指向next_buffer，这样应用线程可以继续写日志到current_buffer中，current_buffer的指针存到buffer_vector后，会通知到日志线程，这里加上锁来控制current_buffer(buffer_mutex)，写日志的缓存池叫write_buffer_vector，里面也有两块缓存newBuffer1和newBuffer2，这时再将current_buffer的指针存入buffer_vector中，这时buffer_vector中有两块缓存的指针，之后将buffer_vector和write_buffer_vector交换，buffer_vector就是空，同时current_buffer指针指向newBuffer1,next_buffer指针指向newBuffer2，释放锁(buffer_mutex)，这时log线程可以进行写操作，write_buffer_vector的大小为2，将里面的两块内存都写到文件中，同时newBuffer1和newBuffer2指针分别指向这两块内存，这样下次再执行交换操作时候write_buffer_vector和newBuffer1和newBuffer2都是空，一直循环执行这类操作，log一般都是写文件时候时间比较长，将数据memcpy到buffer中耗时较少，这样可以大幅减少等锁的时间，提升log的性能。

代码如下：
		
void AsyncLogging::append(const char* logline, int len)
{
 muduo::MutexLockGuard lock(mutex_);
 if (currentBuffer_->avail() > len)
 {
 currentBuffer_->append(logline, len);
 }
 else
 {
 buffers_.push_back(std::move(currentBuffer_));

 if (nextBuffer_)
 {
 currentBuffer_ = std::move(nextBuffer_);
 }
 else
 {
 currentBuffer_.reset(new Buffer); // Rarely happens
 }
 currentBuffer_->append(logline, len);
 cond_.notify();
 }
}

void AsyncLogging::threadFunc()
{
 assert(running_ == true);
 latch_.countDown();
 LogFile output(basename_, rollSize_, false);
 BufferPtr newBuffer1(new Buffer);
 BufferPtr newBuffer2(new Buffer);
 newBuffer1->bzero();
 newBuffer2->bzero();
 BufferVector buffersToWrite;
 buffersToWrite.reserve(16);
 while (running_)
 {
 assert(newBuffer1 && newBuffer1->length() == 0);
 assert(newBuffer2 && newBuffer2->length() == 0);
 assert(buffersToWrite.empty());

 {
 muduo::MutexLockGuard lock(mutex_);
 if (buffers_.empty())  // unusual usage!
 {
 cond_.waitForSeconds(flushInterval_);
 }
 buffers_.push_back(std::move(currentBuffer_));
 currentBuffer_ = std::move(newBuffer1);
 buffersToWrite.swap(buffers_);
 if (!nextBuffer_)
 {
 nextBuffer_ = std::move(newBuffer2);
 }
 }

 assert(!buffersToWrite.empty());

 if (buffersToWrite.size() > 2)
 {
 char buf[256];
 snprintf(buf, sizeof buf, "Dropped log messages at %s, %zd larger buffers\n",
 Timestamp::now().toFormattedString().c_str(),
 buffersToWrite.size()-2);
 fputs(buf, stderr);
 output.append(buf, static_cast(strlen(buf)));
 buffersToWrite.erase(buffersToWrite.begin()+2, buffersToWrite.end());
 }

 for (const auto& buffer : buffersToWrite)
 {
 // FIXME: use unbuffered stdio FILE ? or use ::writev ?
 output.append(buffer->data(), buffer->length());
 }

 if (buffersToWrite.size() > 2)
 {
 // drop non-bzero-ed buffers, avoid trashing
 buffersToWrite.resize(2);
 }

 if (!newBuffer1)
 {
 assert(!buffersToWrite.empty());
 newBuffer1 = std::move(buffersToWrite.back());
 buffersToWrite.pop_back();
 newBuffer1->reset();
 }

 if (!newBuffer2)
 {
 assert(!buffersToWrite.empty());
 newBuffer2 = std::move(buffersToWrite.back());
 buffersToWrite.pop_back();
 newBuffer2->reset();
 }

 buffersToWrite.clear();
 output.flush();
 }
 output.flush();
}
		

			扩展
		
		

			C++当前有两个比较好用的log第三方库easylogging++和spdlog，具体使用读者可以网上找相关资料，个人推荐spdlog，后续会对spdlog进行原理分析。