微信高性能线上日志系统xlog剖析

微信高性能线上日志系统xlog剖析

做移动开发的同学经常会遇到一个头疼的问题，就是当用户反馈一些问题，又比较冷僻难以复现的时候（不是Crash），常常就会陷入一筹莫展的境地。因此，很多人就研发了相关的监控系统，比如一些知名的APM来监测帧率、内存、电量等等，将这些数据进行采集、合并再上报至专门的平台供开发测试同学查看。但是这些APM往往都是粗粒度的监控，究其原因就在于如果特别精细的进行监控，线上的性能会吃不消，一些监控反而影响了用户的正常使用。

说了这么多，抛开获取数据方面的难度不提，线上监控的本质还是在于信息（日志）记录，而端上的日志记录存在一个社会主义初级阶段的供需矛盾：

即实时细粒度的日志记录的性能落差和日志的完整不丢失无法兼顾。

如果你要高性能、细粒度的记录日志，那你势必大量使用内存。而大量使用使用内存，万一没电了、程序突然崩了，这些中间态的日志还没持久化，就相当于白费了精力；而如果你想保证可靠性，那你就需要经常实时落盘。我们知道，写磁盘的行为是会设计用户态和内核态的切换，在高流畅性的要求下是绝对会影响性能了，而且这还不是你开多线程能够解决的问题。

写磁盘为什么会非常慢

现如今、几乎所有的操作系统在管理内存的时候，基本采用了页式管理的策略。即将连续的内存空间（注意空间，不是地址）换成了一个个页式大小。这样的好处有几点：

  1. 按页这种大小进行管理、可以有效的减少内存碎片的粒度。
  2. 按页加载，可以充分利用磁盘上的交换空间，使得程序使用的空间能大大超过内存限制。

当然，iOS设备上不存在交换空间，但是也依然按照页式结构进行内存管理。

回到为什么写磁盘会慢的问题上。我们一般会把内存中的数据进行持久化储存到磁盘上。但是写入磁盘并不是你想写就立刻写的，数据是通过flush的方式从内存写回到磁盘，一般有如下几种情况：

  1. 通过页的flag标记为有改动，操作系统定时将这种脏页写回到磁盘上，时机不可控。
  2. 调用用户态的写接口->触发内核态的sys_write->文件系统将数据写回磁盘。

乍一看上述第二种方式非常适合写日志，但是其包含两个非常明显的问题：

  • 文件系统处于效率不会立刻将数据写回到磁盘（比如磁道寻址由于机械操作的原因相对非常耗时），而是以Block块的形式缓存在队列中，经过排序、合并到达一定比例之后再写回磁盘。
  • 这种方式在将数据写回到磁盘时，需要经历两次拷贝。一次是把数据从用户态拷贝到内核态，需要经历上下文切换；还有一次是内核空间到硬盘上真正的数据拷贝。当切换次数过于频繁，整体性能也会下降。

基于上述这些问题，xlog采用了mmap的方案进行日志系统的设计：

mmap 是使用逻辑内存对磁盘文件进行映射，中间只是进行映射没有任何拷贝操作，避免了写文件的数据拷贝。操作内存就相当于在操作文件，避免了内核空间和用户空间的频繁切换。

除了系能耐，使用mmap还能保证日志的完整性，因为如下这些情况下回自动回写磁盘：

  • 内存不足
  • 进程 crash
  • 调用 msync 或者 munmap
  • 不设置 MAP_NOSYNC 情况下 30s-60s(仅限FreeBSD)

xlog源码分析

xlog的代码主要分为两块，面向上层的使用封装xlogger，暴露了一系列的借口。以及核心的appender和log等。

log_buffer

log_buffer其目的是封装了一个对mmap/传统内存操作的数据结构。其核心思想就是将上层的操作转换对实际开辟出来的日志缓存地址进行读写（也封装了加密压缩操作等等）。我们以写操作为例子进行剖析：

bool LogBuffer::Write(const void* _data, size_t _length) {
    // 一些异常处理，不说了
    if (NULL == _data || 0 == _length) {
        return false;
    }

    if (buff_.Length() == 0) {
        if (!__Reset()) return false;
    }

    size_t before_len = buff_.Length();
    size_t write_len = _length;

    if (is_compress_) {
        // 是否开启压缩
        cstream_.avail_in = (uInt)_length;
        cstream_.next_in = (Bytef*)_data;

        uInt avail_out = (uInt)(buff_.MaxLength() - buff_.Length());
        cstream_.next_out = (Bytef*)buff_.PosPtr();
        cstream_.avail_out = avail_out;

        if (Z_OK != deflate(&cstream_, Z_SYNC_FLUSH)) {
            return false;
        }

        write_len = avail_out - cstream_.avail_out;
    } else {
          // 1. 写入数据到mmap文件或者内存当中
        buff_.Write(_data, _length);
    }

    // 2. 检查之前尝试加密但是还剩的未能成功加密的数据长度
    before_len -= remain_nocrypt_len_;

    AutoBuffer out_buffer;
    size_t last_remain_len = remain_nocrypt_len_;

    // 3. 异步加密，更新未能加密的数据长度
    log_crypt_->CryptAsyncLog((char*)buff_.Ptr() + before_len, write_len + remain_nocrypt_len_, out_buffer, remain_nocrypt_len_);

    // 4. 将加密的文本重新写入到之前最后一次加密的数据结尾位置
    buff_.Write(out_buffer.Ptr(), out_buffer.Length(), before_len);

    // 5. 更新数据
    before_len += out_buffer.Length();
    buff_.Length(before_len, before_len);

    // 6. 添加一下加密的长度之类的辅助信息补充在真实数据之后，主要用于解密时候用
    log_crypt_->UpdateLogLen((char*)buff_.Ptr(), (uint32_t)(out_buffer.Length() - last_remain_len));

    return true;
}

不难看出，整体上就是对写入的数据进行加密，如果有压缩的需求同时进行压缩。并将修改后的数据存入真正的mmap文件/内存缓存中。

如果不能理解的话，可以看下我画的这幅图进行表示：

appender

xlog方案真正的核心实际上只有一个appender文件，本质上的思路都比较清晰，将添加日志分为同步写和异步写。异步写的方式比较常用，下文会基于这个分析。

首先是日志系统的初始化配置

assert(_dir);
assert(_nameprefix);

if (!sg_log_close) {
    __writetips2file("appender has already been opened. _dir:%s _nameprefix:%s", _dir, _nameprefix);
    return;
}

 // 1. 设置真正的添加log信息函数，供上层调用
xlogger_SetAppender(&xlogger_appender);

//mkdir(_dir, S_IRWXU|S_IRWXG|S_IRWXO);
boost::filesystem::create_directories(_dir);
tickcount_t tick;
tick.gettickcount();
__del_timeout_file(_dir);

tickcountdiff_t del_timeout_file_time = tickcount_t().gettickcount() - tick;

tick.gettickcount();

char mmap_file_path[512] = {0};
snprintf(mmap_file_path, sizeof(mmap_file_path), "%s/%s.mmap2", sg_cache_logdir.empty()?_dir:sg_cache_logdir.c_str(), _nameprefix);

bool use_mmap = false;
// 2. 尝试使用mmap
if (OpenMmapFile(mmap_file_path, kBufferBlockLength, sg_mmmap_file))  {
    sg_log_buff = new LogBuffer(sg_mmmap_file.data(), kBufferBlockLength, true, _pub_key);
    use_mmap = true;
} else {
    // 3. 失败了回退到普通内存的方案
    char* buffer = new char[kBufferBlockLength];
    sg_log_buff = new LogBuffer(buffer, kBufferBlockLength, true, _pub_key);
    use_mmap = false;
}

 4. 注意点1!!!!!!!!!!!!!!!!!!!!
if (NULL == sg_log_buff->GetData().Ptr()) {
    if (use_mmap && sg_mmmap_file.is_open())  CloseMmapFile(sg_mmmap_file);
    return;
}


5. 注意点2!!!!!!!!!!!!!!!!
AutoBuffer buffer;
sg_log_buff->Flush(buffer);

ScopedLock lock(sg_mutex_log_file);
sg_logdir = _dir;
sg_logfileprefix = _nameprefix;
sg_log_close = false;
appender_setmode(_mode);
lock.unlock();

char mark_info[512] = {0};
get_mark_info(mark_info, sizeof(mark_info));

if (buffer.Ptr()) {
    __writetips2file("~~~~~ begin of mmap ~~~~~\n");
    __log2file(buffer.Ptr(), buffer.Length());
    __writetips2file("~~~~~ end of mmap ~~~~~%s\n", mark_info);
}

 6. 添加一些关于xlog自身的信息
tickcountdiff_t get_mmap_time = tickcount_t().gettickcount() - tick;


char appender_info[728] = {0};
snprintf(appender_info, sizeof(appender_info), "^^^^^^^^^^" __DATE__ "^^^" __TIME__ "^^^^^^^^^^%s", mark_info);

xlogger_appender(NULL, appender_info);
char logmsg[64] = {0};
snprintf(logmsg, sizeof(logmsg), "del time out files time: %" PRIu64, (int64_t)del_timeout_file_time);
xlogger_appender(NULL, logmsg);

snprintf(logmsg, sizeof(logmsg), "get mmap time: %" PRIu64, (int64_t)get_mmap_time);
xlogger_appender(NULL, logmsg);

xlogger_appender(NULL, "MARS_URL: " MARS_URL);
xlogger_appender(NULL, "MARS_PATH: " MARS_PATH);
xlogger_appender(NULL, "MARS_REVISION: " MARS_REVISION);
xlogger_appender(NULL, "MARS_BUILD_TIME: " MARS_BUILD_TIME);
xlogger_appender(NULL, "MARS_BUILD_JOB: " MARS_TAG);

snprintf(logmsg, sizeof(logmsg), "log appender mode:%d, use mmap:%d", (int)_mode, use_mmap);
xlogger_appender(NULL, logmsg);

BOOT_RUN_EXIT(appender_close);

有几点需要特别注意点：

  • 注意点1: 如果我们尝试打开mmap成功了，但是mmap对应的数据地址是NULL，那我们必须停止映射。因为NULL所代表的地址处于内核态，一旦映射了，势必造成Crash。
  • 注意点2：使用mmap的情况下，如果上次应用断电了、Crash，日志的信息还是存在的，但是并不一定能及时的转换成我们想要的日志文件。因此我们首先检查下mmap文件里面有没有数据，有的话先把这部分转换成日志。

而通过上层添加的日志，都会通过之前的xlogger_appender进行调用，进而往下层的__appender_async 记录日志。

__appender_async

__appender_async 需要和其异步dump线程一起搭配看，是两段非常有意思的代码，它涉及了一个将mmap/内存数据写回到磁盘的策略。

首先是添加日志：

static void __appender_async(const XLoggerInfo* _info, const char* _log) {
    ScopedLock lock(sg_mutex_buffer_async);
    if (NULL == sg_log_buff) return;

    char temp[16*1024] = {0};       //tell perry,ray if you want modify size.
    PtrBuffer log_buff(temp, 0, sizeof(temp));
    log_formater(_info, _log, log_buff);

    if (sg_log_buff->GetData().Length() >= kBufferBlockLength*4/5) {
       int ret = snprintf(temp, sizeof(temp), "[F][ sg_buffer_async.Length() >= BUFFER_BLOCK_LENTH*4/5, len: %d\n", (int)sg_log_buff->GetData().Length());
       log_buff.Length(ret, ret);
    }

    if (!sg_log_buff->Write(log_buff.Ptr(), (unsigned int)log_buff.Length())) return;

     // mmap/内存超出一定限度就写通知异步线程写回到文件中。
    if (sg_log_buff->GetData().Length() >= kBufferBlockLength*1/3 || (NULL!=_info && kLevelFatal == _info->level)) {
       sg_cond_buffer_async.notifyAll();
    }
}

其次是异步线程Dump成日志

static void __async_log_thread() {
    while (true) {

        ScopedLock lock_buffer(sg_mutex_buffer_async);

        if (NULL == sg_log_buff) break;

        AutoBuffer tmp;
        sg_log_buff->Flush(tmp);
        lock_buffer.unlock();

        if (NULL != tmp.Ptr())  __log2file(tmp.Ptr(), tmp.Length());

        if (sg_log_close) break;

        sg_cond_buffer_async.wait(15 * 60 *1000);
    }
}

不难看出，整个日志的主要策略就是利用mmap将日志写入到磁盘映射上，当超过三分之一的时候通知异步线程去写日志。

这样就利用了mmap的实时性、完整性打造了一个逻辑非常清晰易懂的日志，整体架构图如下：