本文发自 http://www.binss.me/blog/notes-of-glog/,转载请注明出处。

glog 是 google 开源的一个日志库,能够方便的实现日志分级(INFO / WARNING / ERROR / FATAL) 和 日志归档,同时提供了 CHECK 等便捷工具,在业界有广泛的应用。使用起来很简单,无非就是:

LOG(INFO) << "Hello world";
VLOG(1) << "Hello world";

前者只有在 minloglevel 等于 0 (INFO) 时才会输出。而后者仅会在 minloglevel 等于 0 且 v >= 1 时才会输出。于是我就这样知其然而不知其所以然的情况下用了一年多,直到有一天加了行 log 导致程序性能暴降,一波排查最终发现是 glog 带来的,这才使得我不得不学习下 glog 的实现。

Bad case

我们的程序默认输出参数为:v=0 ,minloglevel=1 。

我在一个单请求需要循环上万次的循环中,加上了那么一句 log 用于调试:VLOG(0) << "Balabala"; 。显然,由于 minloglevel 不等于 0 ,这行 log 不会被输出。但这并不代表这没有开销。

根据 glog 最新的代码,VLOG 实现如下:

#define VLOG(verboselevel) LOG_IF(INFO, VLOG_IS_ON(verboselevel))
#define LOG_IF(severity, condition) \
  !(condition) ? (void) 0 : google::LogMessageVoidify() & LOG(severity)
#define VLOG_IS_ON(verboselevel) (FLAGS_v >= (verboselevel))

因此对于 VLOG(0) << "Balabala"; ,会展开成:

!(FLAGS_v >= (0)) ? (void) 0 : google::LogMessageVoidify() & LOG(INFO) << "Balabala";

由于 v 等于 0 ,于是执行的是 google::LogMessageVoidify() & LOG(INFO) << "Balabala" ,即 LOG(INFO) << "Balabala";

于是问题变成 LOG(INFO) 在 minloglevel=1 时是否有开销?

LOG 实现

根据代码,我们可以发现,当 GOOGLE_STRIP_LOG 为 0 (默认) 时,LOG(INFO) 后跟的语句始终会被执行。

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

#if GOOGLE_STRIP_LOG == 0
#define COMPACT_GOOGLE_LOG_INFO google::LogMessage( \
      __FILE__, __LINE__)
#define LOG_TO_STRING_INFO(message) google::LogMessage( \
      __FILE__, __LINE__, google::GLOG_INFO, message)
#else
#define COMPACT_GOOGLE_LOG_INFO google::NullStream()
#define LOG_TO_STRING_INFO(message) google::NullStream()
#endif

当 GOOGLE_STRIP_LOG 不为 0 时, COMPACT_GOOGLE_LOG_INFO.stream() 会转换成 NullStream::stream() 。其构造了一个 NullStream 对象(继承于 std::ostream) 并调用 LogMessage::stream 函数。函数返回了 self 。NullStream 的 operator<< 实现如下:

template<class T>
inline NullStream& operator<<(NullStream &str, const T &) { return str; }

于是 << 后跟的内容不会被输出。

当 GOOGLE_STRIP_LOG 为 0 时 ,会转换成 google::LogMessage(__FILE__, __LINE__).stream() ,其构造了一个 LogMessage 对象并调用 LogMessage::stream 函数。

LogMessage 包含一个动态分配的 LogMessageData 成员,用于保存当前 log 对象要输出的时间、输出级别、内容(message_text_)等。而 LogMessageData 又包含一个 LogStream 成员,其继承于 std::ostream ,指定了 LogMessageData::message_text_ 作为 buffer 。另外我们可以发现 LogMessageData::message_text_ 长度为 kMaxLogMessageLen+1 ,因此每条 log 的长度在编译时固定,等于 30000 。

LogMessage::steam 返回了 stream_ (LogStream) ,于是右操作数("Balabala") 会被 append 到 LogMessageData::message_text_ 。

在语句执行完后, LogMessage 作为临时对象,其析构函数会被调用:

LogMessage::~LogMessage() {
  Flush();
#ifdef GLOG_THREAD_LOCAL_STORAGE
  if (data_ == static_cast<void*>(&thread_msg_data)) {
    data_->~LogMessageData();
    thread_data_available = true;
  }
  else {
    delete allocated_;
  }
#else // !defined(GLOG_THREAD_LOCAL_STORAGE)
  delete allocated_;
#endif // defined(GLOG_THREAD_LOCAL_STORAGE)
}

于是调用 LogMessage::Flush :

void LogMessage::Flush() {
  if (data_->has_been_flushed_ || data_->severity_ < FLAGS_minloglevel)
    return;

  data_->num_chars_to_log_ = data_->stream_.pcount();
  data_->num_chars_to_syslog_ =
    data_->num_chars_to_log_ - data_->num_prefix_chars_;

  // Do we need to add a \n to the end of this message?
  bool append_newline =
      (data_->message_text_[data_->num_chars_to_log_-1] != '\n');
  char original_final_char = '\0';

  // If we do need to add a \n, we'll do it by violating the memory of the
  // ostrstream buffer.  This is quick, and we'll make sure to undo our
  // modification before anything else is done with the ostrstream.  It
  // would be preferable not to do things this way, but it seems to be
  // the best way to deal with this.
  if (append_newline) {
    original_final_char = data_->message_text_[data_->num_chars_to_log_];
    data_->message_text_[data_->num_chars_to_log_++] = '\n';
  }

  // Prevent any subtle race conditions by wrapping a mutex lock around
  // the actual logging action per se.
  {
    MutexLock l(&log_mutex);
    (this->*(data_->send_method_))();
    ++num_messages_[static_cast<int>(data_->severity_)];
  }
  LogDestination::WaitForSinks(data_);

  if (append_newline) {
    // Fix the ostrstream back how it was before we screwed with it.
    // It's 99.44% certain that we don't need to worry about doing this.
    data_->message_text_[data_->num_chars_to_log_-1] = original_final_char;
  }

  // If errno was already set before we enter the logging call, we'll
  // set it back to that value when we return from the logging call.
  // It happens often that we log an error message after a syscall
  // failure, which can potentially set the errno to some other
  // values.  We would like to preserve the original errno.
  if (data_->preserved_errno_ != 0) {
    errno = data_->preserved_errno_;
  }

  // Note that this message is now safely logged.  If we're asked to flush
  // again, as a result of destruction, say, we'll do nothing on future calls.
  data_->has_been_flushed_ = true;
}

如果对象的输出级别小于 FLAGS_minloglevel ,则直接返回。这回答了我们前面的问题,LOG(INFO) 在 minloglevel=1 时是有开销的,其开销包括:

  1. 构造 LogMessage ,动态分配 LogMessageData ,其包括了长度为 30000 的 buffer
  2. operator<< 右操作数的字符串被拷贝到 buffer 中

所以虽然在 LogMessage::Flush 中提前返回避免了 log 的输出,但在频繁调用的场合下依然是不小的开销。

如果对象的输出级别大于等于 FLAGS_minloglevel ,则:

  1. 判断 buffer 尾部是否有换行,如果没有,将最后一个字符替换为换行符 (真的贴心)
  2. 对全局锁 log_mutex 加锁,避免多线程下同时写 log 写乱了
  3. 调用 LogStream::send_method_ (LogMessage::SendToLog) ,将 log 输出 (写出到相应文件)
  4. 将 buffer 尾部的换行符还原回原来的字符 (真的有必要吗?)

VLOG 实现

话说回来,我们发现对于 VLOG(i) ,当 i 大于 FLAGS_v 时, VLOG_IS_ON 为 false ,于是宏展开成 (void) 0;

!(FLAGS_v >= (0)) ? (void) 0 : google::LogMessageVoidify() & LOG(INFO) << "Balabala";

可以发现右边原本要输出的 "Balabala 被拼到了三目运算符的另一个分支,根本不会被评估到,因此不会带来任何额外的性能开销。如此一来,一个不满足的 VLOG 开销就只有一个 if 判断的开销而已。

实践参考

根据以上的分析,我个人总结出以下的实践参考:

  1. 避免使用 VLOG(0) :因为它在 v=0 时等价于 LOG(INFO) ,而 LOG(INFO) 即使不输出,也是有构造开销的
  2. 对于调试用的 log,使用 VLOG(i) (i > 0) 而不是 LOG(INFO) :因为一个不满足的 VLOG 开销非常小
  3. 避免 LOG(INFO) 的 operator<< 后跟一个复杂的函数:因为这个函数总是会被评估,即使它的运行往往是没有意义的(返回值被忽略)。在这种情况下依然推荐换用 VLOG(i) (i > 0)
  4. LOG 的输出的内容不应该超过 30000 个字符:否则会被截断,除非修改 glog 代码中的 kMaxLogMessageLen ,但这又会增加每个 log 的内存开销