前言

在看了muduo的源码后,更加明白了大牛的代码究竟是什么样子的,十几年前的代码现在看仍是让人收获满满,遂决定在看过源码后对其做一个总结,这个途径就是博客,一来能更深刻的理解看过的内容,二来源码如果上来就没有章法的读的话是费力不讨好的,所以这一系列文章也是对后来者在阅读过程中一点帮助.

这是第一篇文章,我的计划是先把日志说明白,毕竟不管是对一个服务器还是网络库来说日志一定是一个至关重要的内容,甚至说是决定其健壮性的一个重要的评判标准,毕竟在出现问题时我们希望也需要去迅速找到问题出现的时间,地点和原因,这意味着我们需要大量的日志来支持运维工作,但是大量的日志也意味着效率的损耗,同时我们也不希望日志影响正常的eventloop的进行,毕竟这是一个涉及文件IO的操作,对于计算密集型的任务来说可以说是不可忍受的,所以一个高性能的异步日志库显得尤为重要,当前C++主流的日志库也有不少log4,boost.log等数不胜数,但是我觉得看源码并不仅仅是学习某个东西是如何写,更要理解其中的细节与编程手法,加入自己的理解,学习到除开始目标以外的东西才是.接下来开始吧.

这是重要类之间的关系图
在这里插入图片描述
先由logfile入手

class LogFile : noncopyable
{
 public:
  LogFile(const string& basename, //项目名称
          off_t rollSize, //一次最大刷新字节数
          bool threadSafe = true,//通过对写入操作加锁,来决定是否线程安全
          int flushInterval = 3, //隔多少毫秒刷新一次
          int checkEveryN = 1024);
  ~LogFile();

  void append(const char* logline, int len);
  void flush();
  bool rollFile();

 private:
  void append_unlocked(const char* logline, int len);

  static string getLogFileName(const string& basename, time_t* now);

  const string basename_;
  const off_t rollSize_;
  const int flushInterval_;
  const int checkEveryN_;

  int count_;

  std::unique_ptr<MutexLock> mutex_;
  time_t startOfPeriod_;
  time_t lastRoll_;
  time_t lastFlush_;
  std::unique_ptr<FileUtil::AppendFile> file_;

  const static int kRollPerSeconds_ = 60*60*24; //一天的秒数
};

这是logfile的主题,如引导图所见,这是与logstream沟通的一个核心类,我们来看看其中每一个成员的含义:

LogFile::LogFile(const string& basename,
                 off_t rollSize,
                 bool threadSafe,
                 int flushInterval,
                 int checkEveryN)
  : basename_(basename),
    rollSize_(rollSize),//一个文件中允许的最大字节数
    flushInterval_(flushInterval),//允许刷新的最大间隙 //可调整
    checkEveryN_(checkEveryN),//允许停留在buffer的最大日志条数
    count_(0), //目前写入的条数 最大为checkEveryN
    mutex_(threadSafe ? new MutexLock : NULL),
    startOfPeriod_(0),//记录前一天的时间 以秒记录
    lastRoll_(0), //上一此rollfile的时间 以秒记录
    lastFlush_(0) //上一次刷新的时间 以秒记录
{
  assert(basename.find('/') == string::npos); //判断文件名是否合法
  rollFile();
}

我们会在构造函数中调用roolfile

bool LogFile::rollFile()
{
  time_t now = 0;
  string filename = getLogFileName(basename_, &now); 
  //这里传递指针 可以由now得到标准时间 即Unix时间戳. 是自1970年1月1日00:00:00 GMT以来的秒数
  time_t start = now / kRollPerSeconds_ * kRollPerSeconds_; //相当于 now-(now%kRollPerSeconds_)
  
  if (now > lastRoll_) //若当前天数大于lastRoll的天数
  {
    lastRoll_ = now;
    lastFlush_ = now;
    startOfPeriod_ = start;//记录上一次rollfile的日期(天)
    file_.reset(new FileUtil::AppendFile(filename));
    //换一个文件写日志,即为了保证两天的日志不写在同一个文件中 而上一天的日志可能并未写到rollSize_大小
    return true;
  }
  return false;
}

对于getlogFilename来说则只有一点需要阐述

filename.reserve(basename.size() + 64);

为什么是64呢.原因是全部的日期在格式化为字符串后为64,

我们再来看看append函数

void LogFile::append(const char* logline, int len)
{
  if (mutex_)
  {
    MutexLockGuard lock(*mutex_);
    append_unlocked(logline, len);
  }
  else
  {
    append_unlocked(logline, len);
  }
}

这个函数本身可说的只有一点,就是append可被设置为logstream的默认输出函数,这里先提一下下面讲解时有个印象,更加重要的逻辑部分来自于append_unlocked

void LogFile::append_unlocked(const char* logline, int len)
{
  file_->append(logline, len);

  if (file_->writtenBytes() > rollSize_) //已写字节数是否大于规定的一次最大写入数
  {
    rollFile();
  }
  else
  {
    ++count_;//记录写入的日志条数
    if (count_ >= checkEveryN_)
    {
      count_ = 0;
      time_t now = ::time(NULL);
      time_t thisPeriod_ = now / kRollPerSeconds_ * kRollPerSeconds_;
      if (thisPeriod_ != startOfPeriod_) //天数不相同 重新生成文件
      {
        rollFile();
      }
      else if (now - lastFlush_ > flushInterval_) //如果现在和上次刷新缓冲区的时间差超过flushinterval的话 进行刷新
      {
        lastFlush_ = now;
        file_->flush();
      }
    }
  }
}

我们可以看到logfile中一个很重要的成员就是file成员,它的类是FileUtil::AppendFile,这个类其中藏着减少磁盘IO的秘密.


// not thread safe //一个处理日志写入的资源管理类
class AppendFile : noncopyable
{
 public:
  explicit AppendFile(StringArg filename); 

  ~AppendFile();

  void append(const char* logline, size_t len);

  void flush();

  off_t writtenBytes() const { return writtenBytes_; }

 private:

  size_t write(const char* logline, size_t len);

  FILE* fp_; //打开的文件指针
  char buffer_[64*1024]; //用户态缓冲区 减少文件IO的次数
  off_t writtenBytes_; //已写入字节数
};

只提两个函数构造函数与write

FileUtil::AppendFile::AppendFile(StringArg filename)
  : fp_(::fopen(filename.c_str(), "ae")),  // 'e' for O_CLOEXEC
    writtenBytes_(0) //
{ 
  assert(fp_);
  ::setbuffer(fp_, buffer_, sizeof buffer_);
  // posix_fadvise POSIX_FADV_DONTNEED ? 
}

muduo如何减少文件IO的诀窍就在这里在setbuffer与writev之间选择了setbuffer,两者均可以减少磁盘IO,setbuffer可以先把数据写到一个用户态缓冲区中,遂flush写入,writev则可提供一次写入多块数据的功能

size_t FileUtil::AppendFile::write(const char* logline, size_t len)
{
  // #undef fwrite_unlocked
  return ::fwrite_unlocked(logline, 1, len, fp_);
}

这也是一个很有意思的函数因为写文件内核中有默认的锁 fwrite_unlocked是fwrite的不加锁版本,
至于这里为什么不加锁呢,原因是这里的写入因为上层函数(logfile,asynclogging)中的锁,已经是线程安全的了

这里这两个类就结束了,可以说LogFile功能为生成文件名,AppendFile功能为写入数据,接下来我们进入数据内容的讲解

logging.h 的logger类,功能为提供日志的时间部分,我们来看看其中的一个helper类,sourcefile,这个类其实就是处理传入的路径,通过简单的处理使得后面的业务逻辑能够更简洁,不用关心这些鸡毛蒜皮的小事.

    template<int N> //非类型模板参数 构造函数可隐式转换
    SourceFile(const char (&arr)[N]) //匹配字符数组写法 因为是引用 效率更高一点
      : data_(arr),
        size_(N-1)
    {  //找到路径中的文件名 //返回第二个参数最后一次出现的位置的指针
      const char* slash = strrchr(data_, '/'); // builtin function
      if (slash)
      {
        data_ = slash + 1;
        size_ -= static_cast<int>(data_ - arr);
      }
    }

Impl

class Impl
{
 public:
  typedef Logger::LogLevel LogLevel; 
  Impl(LogLevel level, int old_errno, const SourceFile& file, int line);
  void formatTime();
  void finish();

  Timestamp time_; //提供当前时间 可得到1970年到现在的毫秒数与生成标准时间字符串
  LogStream stream_; //后面单独说
  LogLevel level_; //当前日志级别
  int line_; //日志行数 由__line__得到
  SourceFile basename_; //日志所属文件名 //由__file__与sourcefile_helper类得到
};

我们来看看Impl的构造函数,现在我们先把stream_当做一个流(它本来就是流),数据可以写到我们想让它到的地方,先讨论logger的部分

Logger::Impl::Impl(LogLevel level, int savedErrno, const SourceFile& file, int line)
  : time_(Timestamp::now()),
    stream_(),
    level_(level), 
    line_(line),
    basename_(file)
{
  formatTime();
  CurrentThread::tid();
  stream_ << T(CurrentThread::tidString(), CurrentThread::tidStringLength());
  stream_ << T(LogLevelName[level], 6);
  if (savedErrno != 0)
  {
    stream_ << strerror_tl(savedErrno) << " (errno=" << savedErrno << ") ";
  }
}

const char* LogLevelName[Logger::NUM_LOG_LEVELS] = //constexper
{
  "TRACE ",
  "DEBUG ",
  "INFO  ",
  "WARN  ",
  "ERROR ",
  "FATAL ",
};

说完formatTime再总结:

void Logger::Impl::formatTime()
{
  int64_t microSecondsSinceEpoch = time_.microSecondsSinceEpoch(); //可得到由1970到现在时刻的微秒数
  //秒数与微秒数
  time_t seconds = static_cast<time_t>(microSecondsSinceEpoch / Timestamp::kMicroSecondsPerSecond);
  int microseconds = static_cast<int>(microSecondsSinceEpoch % Timestamp::kMicroSecondsPerSecond);
  
   /*效率提升的地方,t_lastSecond为__thread变量,
   意味着如果此次写入与上次写入在同一秒内,不必再生成一次重复的字符串*/
  if (seconds != t_lastSecond)
  {
    t_lastSecond = seconds;
    struct tm tm_time;
    if (g_logTimeZone.valid())
    {
      tm_time = g_logTimeZone.toLocalTime(seconds);
    }
    else
    {
      ::gmtime_r(&seconds, &tm_time); // FIXME TimeZone::fromUtcTime
    }

    //t_time同样是__thread的
    int len = snprintf(t_time, sizeof(t_time), "%4d%02d%02d %02d:%02d:%02d",
        tm_time.tm_year + 1900, tm_time.tm_mon + 1, tm_time.tm_mday,
        tm_time.tm_hour, tm_time.tm_min, tm_time.tm_sec);
    assert(len == 17); (void)len;
  }

  if (g_logTimeZone.valid())
  {
    Fmt us(".%06d ", microseconds); //Fmt是一个helper类
    assert(us.length() == 8);
    stream_ << T(t_time, 17) << T(us.data(), 8);
  }
  else
  {
    Fmt us(".%06dZ ", microseconds);
    assert(us.length() == 9);
    stream_ << T(t_time, 17) << T(us.data(), 9);
  }
}

这其中最有意思的当属__thread变量进行的优化了.如果两次写入在同一秒内,我们不必再生成一个时间字符串,只需要管微妙部分即可

这样看来在Impl的构造中我们已经完成了每一条日志信息的时间,线程ID,日志等级的信息.那我们再来看看析构函数完成了哪些

Logger::~Logger()
{
  impl_.finish();
  const LogStream::Buffer& buf(stream().buffer()); 
  g_output(buf.data(), buf.length());
  if (impl_.level_ == FATAL)
  {
    g_flush();
    abort();
  }
}

void Logger::Impl::finish()
{
  stream_ << " - " << basename_ << ':' << line_ << '\n';
}

我们可以看到析构部分首先写入了文件名与行数,这样一来,我们只剩日志内容部分还未写入日志了,
如何在此时把日志写入文件,在我看源码的时候深深的思考了这个问题,可能一般我们的做法就是直接把流与写入文件绑定,一个强耦合的关系会使得整个日志只能在同步与异步之间选择一个,那如何全都要呢,答案就是设置一个回调,在muduo中的体现就是g_output,还记得我们前面在logfile中提到的append吗,那就可以当做g_output的回调,从而达到写同步日志的目的,异步日志我们则可改变回调为异步日志的接口即可.异步日志我们在源码解析< 2>中分析.不得不说使用一个中间层来回调的当时确实使得整个程序的结构更加明朗,确实值得我们学习.

再提一点,logstream与logger的联系就在于析构函数中的stream().buffer(),我们先看看logstream,这个类就是日志库的一个钥匙.

class LogStream : noncopyable
{
  typedef LogStream self;
 public:
  typedef detail::FixedBuffer<detail::kSmallBuffer> Buffer;

	......一串输出运算符的重载

  void append(const char* data, int len) { buffer_.append(data, len); }
  const Buffer& buffer() const { return buffer_; }
  void resetBuffer() { buffer_.reset(); }

	
 private:
  void staticCheck();

  template<typename T>
  void formatInteger(T); //用于数字转字符串 但使用了一个更快的方法,值得在其他项目上借鉴 当然tostring().c_str()也可.

  Buffer buffer_;

  static const int kMaxNumericSize = 32;
};

随便看一个重载

  self& operator<<(const string& v)
  {
    buffer_.append(v.c_str(), v.size());
    return *this;
  }

我们可以看到其实就是把数据放入缓冲区,仅此而已,这样在去看logger的析构函数,就算是彻底搞懂了同步库中同步日志的的过程,异步日志我们放在下一篇讲解,这一篇先阐述整体的逻辑.

最后看看如何调用

#define LOG_TRACE if (muduo::Logger::logLevel() <= muduo::Logger::TRACE) \
  muduo::Logger(__FILE__, __LINE__, muduo::Logger::TRACE, __func__).stream()
#define LOG_DEBUG if (muduo::Logger::logLevel() <= muduo::Logger::DEBUG) \
  muduo::Logger(__FILE__, __LINE__, muduo::Logger::DEBUG, __func__).stream()
#define LOG_INFO if (muduo::Logger::logLevel() <= muduo::Logger::INFO) \
  muduo::Logger(__FILE__, __LINE__).stream()
#define LOG_WARN muduo::Logger(__FILE__, __LINE__, muduo::Logger::WARN).stream()
#define LOG_ERROR muduo::Logger(__FILE__, __LINE__, muduo::Logger::ERROR).stream()
#define LOG_FATAL muduo::Logger(__FILE__, __LINE__, muduo::Logger::FATAL).stream()
#define LOG_SYSERR muduo::Logger(__FILE__, __LINE__, false).stream()
#define LOG_SYSFATAL muduo::Logger(__FILE__, __LINE__, true).stream()

一系列宏函数就可以支持了,

调用方法,使用muduo/muduo/base/tests/LogFile_test.cc代码

#include "muduo/base/LogFile.h"
#include "muduo/base/Logging.h"

#include <unistd.h>

std::unique_ptr<muduo::LogFile> g_logFile;

void outputFunc(const char* msg, int len)
{
  g_logFile->append(msg, len);
}

void flushFunc()
{
  g_logFile->flush(); 
}

int main(int argc, char* argv[])
{
  char name[256] = { 0 };
  strncpy(name, argv[0], sizeof name - 1);
  g_logFile.reset(new muduo::LogFile(::basename(name), 200*1000));
  
  muduo::Logger::setOutput(outputFunc);
  muduo::Logger::setFlush(flushFunc);

  muduo::string line = "1234567890 abcdefghijklmnopqrstuvwxyz ABCDEFGHIJKLMNOPQRSTUVWXYZ ";

  for (int i = 0; i < 10000; ++i)
  { 
    LOG_INFO << line << i;

    usleep(1000);
  }
}

如果上面都认真看了的话,这个样例应该是让人醍醐灌顶的,基本阐述清楚了同步日志的全部内容.

可能细心的朋友发现Data,TimeZone,等类并没有分析,因为我觉得哪些在我们需要使用时拿来用即可,我们重点应该放在逻辑处理上,所以没有讲解.

小结

在看完这部分的源码后在我看来其实是有修改的部分的,比如每条日志我们都需要创建一个logfile对象,那我们何不把它设置为单例呢?第三篇中讲解我对于源码的几处修改的想法与实现.

参考:
https://www.zhihu.com/question/37640953