glog 使用心得

2020-05-31 10:19

本文发自 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 时是有开销的，其开销包括：

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

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

如果对象的输出级别大于等于 FLAGS_minloglevel ，则：

判断 buffer 尾部是否有换行，如果没有，将最后一个字符替换为换行符 (真的贴心)
对全局锁 log_mutex 加锁，避免多线程下同时写 log 写乱了
调用 LogStream::send_method_ (LogMessage::SendToLog) ，将 log 输出 (写出到相应文件)
将 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 判断的开销而已。

实践参考

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

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

本文发自 https://www.binss.me/blog/notes-of-glog/

采用知识共享署名-非商业性使用-相同方式共享 4.0 进行许可

Binsite

Bad case

LOG 实现

VLOG 实现

实践参考