failed to open log file_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                         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

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

LOG(INFO)<

我们上面看到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<: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_中.

将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(&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(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进行原理分析。

▼更多精彩推荐，请关注我们▼

代码精进之路

  代码精进之路，我们一起成长！