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

#define LOG(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()
那么LOG(INFO)相当于
COMPACT_GOOGLE_LOG_INFO.stream()

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

// 这里是摘下来的极简版，实际比这复杂很多
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(const char* file, int line)
    : allocated_(NULL) {
  Init(file, line, GLOG_INFO, &LogMessage::SendToLog);
}

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<char*>(reinterpret_cast<uintptr_t>(thread_msg_data + kAlign) & ~kAlign);
        data_ = new (align_ptr) LogMessageData;
        assert(reinterpret_cast<uintptr_t>(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<time_t>(now);
    localtime_r(&data_->timestamp_, &data_->tm_time_);
    int usecs = static_cast<int>((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<unsigned int>(GetTID()) << setfill('0')
                << ' '
                << data_->basename_ << ':' << data_->line_ << "] ";
    }
    data_->num_prefix_chars_ = data_->stream_.pcount();
}

#ifdef HAVE_ALIGNED_STORAGE
static GLOG_THREAD_LOCAL_STORAGE
    std::aligned_storage<sizeof(LogMessage::LogMessageData),
                         alignof(LogMessage::LogMessageData)>::type thread_msg_data;
#else
static GLOG_THREAD_LOCAL_STORAGE
    char thread_msg_data[sizeof(void*) + sizeof(LogMessage::LogMessageData)];
#endif  // HAVE_ALIGNED_STORAGE

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<std::string>* 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_中.

LogMessage::~LogMessage() {
  Flush();// 主要功能在Flush函数中
  if (data_ == static_cast<void*>(&thread_msg_data)) {
    data_->~LogMessageData();
    thread_data_available = true;
  }
  else {
    delete allocated_;
  }
}

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

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_);
}

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);
  }
}

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);
}

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(&timestamp, &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<int64>(1000000));  // in usec
  next_flush_time_ = CycleClock_Now() + UsecToCycles(next);
}

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<int>(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();
}