腾讯mars xlog源码解析

前言

  之前由于公司发展需要，app网络请求日志始终没有一个良好的分析手段，故公司成立了apm项目小组，通过AOP编程获取app网络请求日志并上报到服务端，然后通过网页多维度分析用户网络请求数据，类似听云博睿那样的工具，而日志模块通过调研最终选用了mars xlog，而xlog原有的日志格式并不符合业务需求，故需要通读xlog源码才能在其基础上进行修改，还有为什么选型xlog作为日志存储模块原因，接下来就进入mars xlog源码之旅吧。
我这里提供一个可以支持断点调试xlog的mars v1.3.0分支(针对于android平台)，基于原有cmake修改的，这样方便断点调试分析源码:
支持断点调试xlog c/c++代码的mars分支，注意是yyl_debug_xlog分支
这个分支可以直接运行调试mars/libraries/mars_xlog_sdk module:

源码解析(基于最新的v1.3.0 mars分支)

   首先，我们分析一个开源库，先从他的入口开始吧，xlog api都在com.tencent.mars.xlog.Xlog这个类中，先看看一下它有哪些方法：

  先来看看入口方法com.tencent.mars.xlog.Xlog::appenderOpen(int level, int mode, String cacheDir, String logDir, String nameprefix, int cacheDays, String pubkey);与之对应的native函数为mars/log/jni/Java2C_Xlog.cc里的Java_com_tencent_mars_xlog_Xlog_appenderOpen函数:

DEFINE_FIND_STATIC_METHOD(KXlog_appenderOpenWithMultipathWithLevel, KXlog, "appenderOpen", "(IILjava/lang/String;Ljava/lang/String;Ljava/lang/String;ILjava/lang/String;)V")
JNIEXPORT void JNICALL Java_com_tencent_mars_xlog_Xlog_appenderOpen
	(JNIEnv *env, jclass, jint level, jint mode, jstring _cache_dir, jstring _log_dir, jstring _nameprefix, jint _cache_log_days, jstring _pubkey) {
	if (NULL == _log_dir || NULL == _nameprefix) {
		return;
	}

	std::string cache_dir;
	if (NULL != _cache_dir) {
		ScopedJstring cache_dir_jstr(env, _cache_dir);
		cache_dir = cache_dir_jstr.GetChar();
	}

	const char* pubkey = NULL;
	ScopedJstring jstr_pubkey(env, _pubkey);
	if (NULL != _pubkey) {
		pubkey = jstr_pubkey.GetChar();
	}

	ScopedJstring log_dir_jstr(env, _log_dir);
	ScopedJstring nameprefix_jstr(env, _nameprefix);
	appender_open_with_cache((TAppenderMode)mode, cache_dir.c_str(), log_dir_jstr.GetChar(), nameprefix_jstr.GetChar(), _cache_log_days, pubkey);
	xlogger_SetLevel((TLogLevel)level);

}

形参暂且不管，后面用到地方再详解，上述代码中ScopedJstring 是用来将jstring转化为C能用的const char*，在析构里面自动释放引用，这样就不用每次转换时调用JNIEnv:;GetStringUTFChars 、JNIEnv::ReleaseStringUTFChars两个烦人的api了，而且还容易忘记调用ReleaseStringUTFChars而导致native引用引起的内存泄漏；我们主要看appender_open_with_cache函数的实现逻辑（源码路径为log/src/appender.cc）:

void appender_open_with_cache(TAppenderMode _mode, const std::string& _cachedir, const std::string& _logdir,
                              const char* _nameprefix, int _cache_days, const char* _pub_key) {
    assert(!_cachedir.empty());
    assert(!_logdir.empty());
    assert(_nameprefix);

    sg_logdir = _logdir;
    sg_cache_log_days = _cache_days;

    if (!_cachedir.empty()) {
        sg_cache_logdir = _cachedir;
        boost::filesystem::create_directories(_cachedir);

        Thread(boost::bind(&__del_timeout_file, _cachedir)).start_after(2 * 60 * 1000);
        // "_nameprefix" must explicitly convert to "std::string", or when the thread is ready to run, "_nameprefix" has been released.
        Thread(boost::bind(&__move_old_files, _cachedir, _logdir, std::string(_nameprefix))).start_after(3 * 60 * 1000);
    }

#ifdef __APPLE__
    setAttrProtectionNone(_cachedir.c_str());
#endif
    appender_open(_mode, _logdir.c_str(), _nameprefix, _pub_key);

}

主要看这四句:

		boost::filesystem::create_directories(_cachedir);

        Thread(boost::bind(&__del_timeout_file, _cachedir)).start_after(2 * 60 * 1000);
        // "_nameprefix" must explicitly convert to "std::string", or when the thread is ready to run, "_nameprefix" has been released.
        Thread(boost::bind(&__move_old_files, _cachedir, _logdir, std::string(_nameprefix))).start_after(3 * 60 * 1000);
        appender_open(_mode, _logdir.c_str(), _nameprefix, _pub_key);

第一句呢是创建_cachedir目录，这个目录主要是存放磁盘内存映射mmap文件，这里插一下，mmap技术就是linux的零拷贝技术，传统拷贝与利用了mmap的区别：

可以看到，传统拷贝由于用户态无法直接访问内核态数据的，需用从用户buffer拷贝到内核buffer，从内核buff再拷贝到最终目标文件，经过了多次拷贝；而使用了mmap之后，只需要操作虚拟地址空间就可以读写最终目标文件了，少了很多中间拷贝操作，这样确实比传统读写操作省了很多时间；
接下来再看调用Thread的两行代码，主要是开启了两个线程，两个线程分别执行__del_timeout_file和__move_old_files两个函数指针；通过名字不难看出__del_timeout_file函数用来删除超时时间的文件，__move_old_files用来移动旧文件，但是start_after函数表示的是延时多少时间后再执行，我们知道pthread库默认并不支持延时执行，不防来看看start_after它的实现:

int start_after(long after) {
        ScopedSpinLock lock(runable_ref_->splock);

        if (isruning())return 0;
        if (0 != runable_ref_->tid && !runable_ref_->isjoined) pthread_detach(runable_ref_->tid);

        ASSERT(runable_ref_->target);
        runable_ref_->condtime.cancelAnyWayNotify();
        runable_ref_->isjoined = outside_join_;
        runable_ref_->isended = false;
        runable_ref_->aftertime = after;
        runable_ref_->iscanceldelaystart = false;
        runable_ref_->AddRef();

        int ret =  pthread_create(reinterpret_cast<thread_tid*>(&runable_ref_->tid), &attr_, start_routine_after, runable_ref_);
        ASSERT(0 == ret);

        if (0 != ret) {
            runable_ref_->isended = true;
            runable_ref_->aftertime = LONG_MAX;
            runable_ref_->RemoveRef(lock);
        }

        return ret;
    }

主要看int ret = pthread_create(reinterpret_cast<thread_tid*>(&runable_ref_->tid), &attr_, start_routine_after, runable_ref_)这一句，可以看到通过pthread库函数创建了一个线程，线程运行的函数入口为start_routine_after函数，这就奇怪了，明明直接就开启了线程，那它是怎么实现延时才执行__del_timeout_file和__move_old_files两个函数的呢？我们再来看start_routine_after它的实现：

static void* start_routine_after(void* arg) {
        init(arg);
        volatile RunnableReference* runableref = static_cast<RunnableReference*>(arg);
        pthread_cleanup_push(&cleanup, arg);

        if (!runableref->iscanceldelaystart) {
            (const_cast<RunnableReference*>(runableref))->condtime.wait(runableref->aftertime);

            if (!runableref->iscanceldelaystart)
                runableref->target->run();
        }

        pthread_cleanup_pop(1);
        return 0;
    }

注意(const_cast<RunnableReference*>(runableref))->condtime.wait(runableref->aftertime);
这一句，这时应该大家都明白了，这里wait表示等待时间，超时后才执行后面的代码，后面的代码调用最终会回调回Thread构造参数传入的函数，也就是__del_timeout_file和__move_old_files两个函数，我们再来看看wait函数是怎么实现等待的：

int wait(ScopedLock& lock, long millisecond) {
        ASSERT(lock.internal().islocked());
        struct timespec ts;
        makeTimeout(&ts, millisecond);

        int ret = 0;

        if (!atomic_cas32(&anyway_notify_, 0, 1)) {
            ret = pthread_cond_timedwait(&condition_, &(lock.internal().internal()), &ts);
        }

        anyway_notify_ = 0;

        if (ETIMEDOUT == ret || 0 == ret) return ret;

        if (EPERM == ret) ASSERT(0 == EPERM);
        else if (EINVAL == ret) ASSERT(0 == EINVAL);
        else if (0 != ret) ASSERT2(0 == ret, "%d", ret);

        return ret;
    }

这下应该明白了，调用的是pthread_cond_timedwait这个函数实现来实现等待的的,pthread_cond_timedwait的使用方法暂且不讨论，有兴趣的可以自行查询；

我们回到appender.cc的appender_open_with_cache函数，看到最后调用了appender.cc的appender_open函数，其实现：

void appender_open(TAppenderMode _mode, const char* _dir, const char* _nameprefix, const char* _pub_key) {
    assert(_dir);
    assert(_nameprefix);
    
    if (!sg_log_close) {
        __writetips2file("appender has already been opened. _dir:%s _nameprefix:%s", _dir, _nameprefix);
        return;
    }

    xlogger_SetAppender(&xlogger_appender);
    
    boost::filesystem::create_directories(_dir);
    tickcount_t tick;
    tick.gettickcount();
    Thread(boost::bind(&__del_timeout_file, _dir)).start_after(2 * 60 * 1000);
    
    tick.gettickcount();

#ifdef __APPLE__
    setAttrProtectionNone(_dir);
#endif

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

    bool use_mmap = false;
    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 {
        char* buffer = new char[kBufferBlockLength];
        sg_log_buff = new LogBuffer(buffer, kBufferBlockLength, true, _pub_key);
        use_mmap = false;
    }

    if (NULL == sg_log_buff->GetData().Ptr()) {
        if (use_mmap && sg_mmmap_file.is_open())  CloseMmapFile(sg_mmmap_file);
        return;
    }


    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(), false);
        __writetips2file("~~~~~ end of mmap ~~~~~%s\n", mark_info);
    }

    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[256] = {0};
    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);
    
    if (!sg_cache_logdir.empty()) {
        boost::filesystem::space_info info = boost::filesystem::space(sg_cache_logdir);
        snprintf(logmsg, sizeof(logmsg), "cache dir space info, capacity:%" PRIuMAX" free:%" PRIuMAX" available:%" PRIuMAX, info.capacity, info.free, info.available);
        xlogger_appender(NULL, logmsg);
    }
    
    boost::filesystem::space_info info = boost::filesystem::space(sg_logdir);
    snprintf(logmsg, sizeof(logmsg), "log dir space info, capacity:%" PRIuMAX" free:%" PRIuMAX" available:%" PRIuMAX, info.capacity, info.free, info.available);
    xlogger_appender(NULL, logmsg);

    BOOT_RUN_EXIT(appender_close);

}

乍一看这个函数稍微有点长，不急我们挑重点的看，先看
if (OpenMmapFile(mmap_file_path, kBufferBlockLength, sg_mmmap_file))这一行，看
OpenMmapFile的实现：

bool OpenMmapFile(const char* _filepath, unsigned int _size, boost::iostreams::mapped_file& _mmmap_file) {

    if (NULL == _filepath || 0 == strnlen(_filepath, 128) || 0 == _size) {
        return false;
    }

    if (IsMmapFileOpenSucc(_mmmap_file)) {
        CloseMmapFile(_mmmap_file);
    }
    
    if (_mmmap_file.is_open() && _mmmap_file.operator!()) {
        return false;
    }

    boost::iostreams::basic_mapped_file_params<boost::filesystem::path> param;
    param.path = boost::filesystem::path(_filepath);
    param.flags = boost::iostreams::mapped_file_base::readwrite;

    bool file_exist = boost::filesystem::exists(_filepath);
    if (!file_exist) {
        param.new_file_size = _size;
    }

    _mmmap_file.open(param);

    bool is_open = IsMmapFileOpenSucc(_mmmap_file);
#ifndef _WIN32
    if (!file_exist && is_open) {

        //Extending a file with ftruncate, thus creating a big hole, and then filling the hole by mod-ifying a shared mmap() can lead to SIGBUS when no space left
        //the boost library uses ftruncate, so we pre-allocate the file's backing store by writing zero.
        FILE* file = fopen(_filepath, "rb+");
        if (NULL == file) {
            _mmmap_file.close();
            boost::filesystem::remove(_filepath);
            return false;
        }

        char* zero_data = new char[_size];
        memset(zero_data, 0, _size);

        if (_size != fwrite(zero_data, sizeof(char), _size, file)) {
            _mmmap_file.close();
            fclose(file);
            boost::filesystem::remove(_filepath);
            delete[] zero_data;
            return false;
        }
        fclose(file);
        delete[] zero_data;
    }
#endif
    return is_open;
}

我们看_mmmap_file.open(param);这一行代码实现，其最终是调用了boost这个c++库的mapped_file.cpp源文件的open函数，路径为mars\boost\libs\iostreams\src\mapped_file.cpp：

void mapped_file_impl::open(param_type p)
{
    if (is_open()) {
        mars_boost::throw_exception(BOOST_IOSTREAMS_FAILURE("file already open"));
        return;
    }
    p.normalize();
    open_file(p);
    map_file(p);  // May modify p.hint
    params_ = p;
}

其中 open_file§是打开文件获取文件描述符，map_file§最终也是调到了void mapped_file_impl::try_map_file(param_type p)函数：

void mapped_file_impl::try_map_file(param_type p)
{
    bool priv = p.flags == mapped_file::priv;
    bool readonly = p.flags == mapped_file::readonly;
#ifdef BOOST_IOSTREAMS_WINDOWS

    // Create mapping
    DWORD protect = priv ? 
        PAGE_WRITECOPY : 
        readonly ? 
            PAGE_READONLY : 
            PAGE_READWRITE;
    mapped_handle_ = 
        ::CreateFileMappingA( 
            handle_, 
            NULL,
            protect,
            0, 
            0, 
            NULL );
    if (mapped_handle_ == NULL) {   // modified by Tencent garryyan 2018.05.17
        cleanup_and_throw("failed create mapping");
        return;
    }

    // Access data
    DWORD access = priv ? 
        FILE_MAP_COPY : 
        readonly ? 
            FILE_MAP_READ : 
            FILE_MAP_WRITE;
    void* data =
        ::MapViewOfFileEx( 
            mapped_handle_,
            access,
            (DWORD) (p.offset >> 32),
            (DWORD) (p.offset & 0xffffffff),
            size_ != max_length ? size_ : 0, 
            (LPVOID) p.hint );
    if (!data) {
        cleanup_and_throw("failed mapping view");
        return;
    }
#else
    void* data = 
        ::BOOST_IOSTREAMS_FD_MMAP( 
            const_cast<char*>(p.hint), 
            size_,
            readonly ? PROT_READ : (PROT_READ | PROT_WRITE),
            priv ? MAP_PRIVATE : MAP_SHARED,
            handle_, 
            p.offset );
    if (data == MAP_FAILED) {
        cleanup_and_throw("failed mapping file");
        return;
    }
#endif
    data_ = static_cast<char*>(data);
}

注意BOOST_IOSTREAMS_FD_MMAP这个宏定义，其实它是mmap函数，在mars\boost\iostreams\detail\config\rtl.hpp文件中是这样定义的：

#  define BOOST_IOSTREAMS_FD_MMAP      mmap

主要看参数handle_，这个是上面 open_file(param_type p)函数打开的文件描述符，对应cachedir中的mmap文件，调用BOOST_IOSTREAMS_FD_MMAP 的返回值void* data就是这个handle_对应的mmap文件的内存映射虚拟起始地址，将其赋值给mapped_file_impl对象的数据域data_，那么这个data_怎么使用呢？我们可以看到
mapped_file_source对象的数据域pimpl_指向这个mapped_file_impl对象，mapped_file对象的数据域delegate_指向这个mapped_file_source对象，而appender.cc的sg_mmmap_file指向这个mapped_file对象，调用sg_mmmap_file.data()就是指向这个mmap文件的内存映射虚拟地址，我们看回appender.cc的appender_open函数，通过调用sg_log_buff = new LogBuffer(sg_mmmap_file.data(), kBufferBlockLength, true, pub_key)实例化一个LogBuffer对象，并将文件内存映射地址赋值给LogBuffer的数据域PtrBuffer buff_的parray，也就是这时parray_指向的就是这个data_指针所指向的地址（磁盘文件的内存映射虚拟地址），以后的读写操作都是对parray_进行的；
既然磁盘文件的内存映射虚拟地址传递了LogBuffer的PtrBuffer buff_，我们不妨来看看LogBuffer类的结构：

GetData()函数就是返回带有磁盘文件的内存映射虚拟地址的PtrBuffer指针；
Flush()函数是将PtrBuffer buff_的parray_（磁盘文件的内存映射虚拟地址）所指向的内容memcpy到传入的AutoBuffer类型里，一般是在mmap转存xlog文件时会调用Flush()函数，然后将AutoBuffer的内容写入xlog文件(通过调用appender.cc里的__log2file函数转存);
Write()有两个重载函数，分别为bool Write(const void* _data, size_t _inputlen, AutoBuffer& _out_buff)和 bool Write(const void* _data, size_t _length)，返回值都是bool类型，第一个比第二个多了个AutoBuffer参数，它主要是将void* _data数据处理后（加密编码这类）赋值给AutoBuffer；
而第二个Write函数则是直接将void* _data数据处理后memcpy给PtrBuffer的磁盘文件内存映射虚拟地址，也就是写入mmap磁盘文件了;
其他几个函数有兴趣的可以自行了解，这里暂且不深究了；
到这里我们应该明白了，所有的mmap数据读写都是通过这个LogBuffer的封装实现的，而这个
LogBuffer只有一个实例保存在appender.cc文件的static LogBuffer* sg_log_buff 指针中;
回到appender.cc的appender_open函数，可以看到开启了内存映射后，调用了
sg_log_buff->Flush(buffer) 将mmap文件数据读入内存buffer，判断是否需要转存xlog文件，后面的代码就是写入一些固定数据到mmap文件的头部了，初始化的逻辑也到此结束；

  初始化逻辑我们基本看明白了，我们再来看看写入日志数据的逻辑，来验证下是不是所有的mmap文件数据读写都是使用这个static LogBuffer* sg_log_buff 指针;
  xlog的日志写入有这几种level：LEVEL_VERBOSE LEVEL_DEBUG LEVEL_INFO LEVEL_WARNING LEVEL_ERROR LEVEL_FATAL ，不过他们都有统一的native接口，就是logWrite2(int level, String tag, String filename, String funcname, int line, int pid, long tid, long maintid, String log) native方法，我们主要看他的native实现逻辑：

DEFINE_FIND_STATIC_METHOD(KXlog_logWrite2, KXlog, "logWrite2", "(ILjava/lang/String;Ljava/lang/String;Ljava/lang/String;IIJJLjava/lang/String;)V")
JNIEXPORT void JNICALL Java_com_tencent_mars_xlog_Xlog_logWrite2
  (JNIEnv *env, jclass, int _level, jstring _tag, jstring _filename,
		  jstring _funcname, jint _line, jint _pid, jlong _tid, jlong _maintid, jstring _log) {

	if (!xlogger_IsEnabledFor((TLogLevel)_level)) {
		return;
	}

	XLoggerInfo xlog_info;
	gettimeofday(&xlog_info.timeval, NULL);
	xlog_info.level = (TLogLevel)_level;
	xlog_info.line = (int)_line;
	xlog_info.pid = (int)_pid;
	xlog_info.tid = LONGTHREADID2INT(_tid);
	xlog_info.maintid = LONGTHREADID2INT(_maintid);

	const char* tag_cstr = NULL;
	const char* filename_cstr = NULL;
	const char* funcname_cstr = NULL;
	const char* log_cstr = NULL;

	if (NULL != _tag) {
		tag_cstr = env->GetStringUTFChars(_tag, NULL);
	}

	if (NULL != _filename) {
		filename_cstr = env->GetStringUTFChars(_filename, NULL);
	}

	if (NULL != _funcname) {
		funcname_cstr = env->GetStringUTFChars(_funcname, NULL);
	}

	if (NULL != _log) {
		log_cstr = env->GetStringUTFChars(_log, NULL);
	}

	xlog_info.tag = NULL == tag_cstr ? "" : tag_cstr;
	xlog_info.filename = NULL == filename_cstr ? "" : filename_cstr;
	xlog_info.func_name = NULL == funcname_cstr ? "" : funcname_cstr;

	xlogger_Write(&xlog_info, NULL == log_cstr ? "NULL == log" : log_cstr);

	if (NULL != _tag) {
		env->ReleaseStringUTFChars(_tag, tag_cstr);
	}

	if (NULL != _filename) {
		env->ReleaseStringUTFChars(_filename, filename_cstr);
	}

	if (NULL != _funcname) {
		env->ReleaseStringUTFChars(_funcname, funcname_cstr);
	}

	if (NULL != _log) {
		env->ReleaseStringUTFChars(_log, log_cstr);
	}
}

主要是这一行xlogger_Write(&xlog_info, NULL == log_cstr ? “NULL == log” : log_cstr)他的调用去到了static void __appender_async(const XLoggerInfo* _info, const char* _log) 这个函数：

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;

    if (sg_log_buff->GetData().Length() >= kBufferBlockLength*1/3 || (NULL!=_info && kLevelFatal == _info->level)) {
       sg_cond_buffer_async.notifyAll();
    }

}

const char* _log就是由java层传入native的日志字符串，通过调用 log_formater(_info, _log, log_buff)来格式化字符串，日志格式定制化工作主要是通过修改log_formater函数实现来实现个性化日志格式的函数存在于mars\mars\log\src\formater.cc源码内：

void log_formater(const XLoggerInfo* _info, const char* _logbody, PtrBuffer& _log) {
   static const char* levelStrings[] = {
       "V",
       "D",  // debug
       "I",  // info
       "W",  // warn
       "E",  // error
       "F"  // fatal
   };

   assert((unsigned int)_log.Pos() == _log.Length());

   static int error_count = 0;
   static int error_size = 0;

   if (_log.MaxLength() <= _log.Length() + 5 * 1024) {  // allowd len(_log) <= 11K(16K - 5K)
       ++error_count;
       error_size = (int)strnlen(_logbody, 1024 * 1024);

       if (_log.MaxLength() >= _log.Length() + 128) {
           int ret = snprintf((char*)_log.PosPtr(), 1024, "[F]log_size <= 5*1024, err(%d, %d)\n", error_count, error_size);  // **CPPLINT SKIP**
           _log.Length(_log.Pos() + ret, _log.Length() + ret);
           _log.Write("");

           error_count = 0;
           error_size = 0;
       }

       assert(false);
       return;
   }

   if (NULL != _info) {
       const char* filename = ExtractFileName(_info->filename);
       char strFuncName [128] = {0};
       ExtractFunctionName(_info->func_name, strFuncName, sizeof(strFuncName));

       char temp_time[64] = {0};

       if (0 != _info->timeval.tv_sec) {
           time_t sec = _info->timeval.tv_sec;
           tm tm = *localtime((const time_t*)&sec);
#ifdef ANDROID
           snprintf(temp_time, sizeof(temp_time), "%d-%02d-%02d %+.1f %02d:%02d:%02d.%.3ld", 1900 + tm.tm_year, 1 + tm.tm_mon, tm.tm_mday,
                    tm.tm_gmtoff / 3600.0, tm.tm_hour, tm.tm_min, tm.tm_sec, _info->timeval.tv_usec / 1000);
#elif _WIN32
           snprintf(temp_time, sizeof(temp_time), "%d-%02d-%02d %+.1f %02d:%02d:%02d.%.3d", 1900 + tm.tm_year, 1 + tm.tm_mon, tm.tm_mday,
                    (-_timezone) / 3600.0, tm.tm_hour, tm.tm_min, tm.tm_sec, _info->timeval.tv_usec / 1000);
#else
           snprintf(temp_time, sizeof(temp_time), "%d-%02d-%02d %+.1f %02d:%02d:%02d.%.3d", 1900 + tm.tm_year, 1 + tm.tm_mon, tm.tm_mday,
                    tm.tm_gmtoff / 3600.0, tm.tm_hour, tm.tm_min, tm.tm_sec, _info->timeval.tv_usec / 1000);
#endif
       }

       // _log.AllocWrite(30*1024, false);
       int ret = snprintf((char*)_log.PosPtr(), 1024, "[%s][%s][%" PRIdMAX ", %" PRIdMAX "%s][%s][%s, %s, %d][",  // **CPPLINT SKIP**
                          _logbody ? levelStrings[_info->level] : levelStrings[kLevelFatal], temp_time,
                          _info->pid, _info->tid, _info->tid == _info->maintid ? "*" : "", _info->tag ? _info->tag : "",
                          filename, strFuncName, _info->line);

       assert(0 <= ret);
       _log.Length(_log.Pos() + ret, _log.Length() + ret);
       //      memcpy((char*)_log.PosPtr() + 1, "\0", 1);

       assert((unsigned int)_log.Pos() == _log.Length());
   }

   if (NULL != _logbody) {
       // in android 64bit, in strnlen memchr,  const unsigned char*  end = p + n;  > 4G!!!!! in stack array

       size_t bodylen =  _log.MaxLength() - _log.Length() > 130 ? _log.MaxLength() - _log.Length() - 130 : 0;
       bodylen = bodylen > 0xFFFFU ? 0xFFFFU : bodylen;
       bodylen = strnlen(_logbody, bodylen);
       bodylen = bodylen > 0xFFFFU ? 0xFFFFU : bodylen;
       _log.Write(_logbody, bodylen);
   } else {
       _log.Write("error!! NULL==_logbody");
   }

   char nextline = '\n';

   if (*((char*)_log.PosPtr() - 1) != nextline) _log.Write(&nextline, 1);
}

可以看到主要是通过库函数snprintf来实现字符串格式化的，如果想自定义日志内容，可以修改这个来实现；
回到__appender_async函数，注意格式化完成后的字符串是存放在PtrBuffer log_buff(temp, 0, sizeof(temp))这个log_buff内的，可能你也注意了，上面LogBuffer对象也有个PtrBuffer数据域，但是注意这两个PtrBuffer是不一样的，LogBuffer里的PtrBuffer是存放磁盘文件内存映射虚拟指针地址，而这里的PtrBuffer是存放格式化后的字符串，后面一行代码：

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

这个则是将PtrBuffer log_buff格式化后的字符串写入到LogBuffer里的PtrBuffer内的指针parray_指向的地址，也就是写入到磁盘文件内存映射虚拟指针地址，继续跟进PtrBuffer的Write函数:

void PtrBuffer::Write(const void* _pBuffer, size_t _nLen, off_t _nPos) {
    ASSERT(NULL != _pBuffer);
    ASSERT(0 <= _nPos);
    ASSERT((unsigned int)_nPos <= Length());
    size_t copylen = min(_nLen, max_length_ - _nPos);
    length_ = max(length_, copylen + _nPos);
    memcpy((unsigned char*)Ptr() + _nPos, _pBuffer, copylen);
}

调用Ptr() 就是获取磁盘文件内存映射虚拟指针地址，_nPos就是当前数据写入的地址（实际上_nPos是通过PtrBuffer::Pos()来获取pos_的值），因为Ptr()获取的地址是文件起始地址，所以需要偏移量，否则会覆盖原来的数据，_pBuffer和copylen就分别是写入的数据和长度了，写完数据后则通过PtrBuffer::Seek()函数来改变pos_的值；回到__appender_async函数，看到sg_log_buff->Write(…)调用后就判断是否需要将mmap文件转存xlog，转存的话是通过 sg_cond_buffer_async.notifyAll()调用来唤醒转存线程执行转存逻辑;

上面就是java层调用com.tencent.mars.xlog.Log::d()的最终执行位置了，基本上mars xlog的初始化以及写日志就是这个逻辑了，后面有时间再分析下mmap日志转存xlog逻辑、加密逻辑以及LogBuffer、PtrBuffer其他函数逻辑