muduo AsyncLoggin详解

1. 简介

用于后端日志异步处理。

2. 类与接口

// Use of this source code is governed by a BSD-style license
// that can be found in the License file.
//
// Author: Shuo Chen (chenshuo at chenshuo dot com)

#include "AsyncLogging.h"
#include "LogFile.h"
#include "Timestamp.h"

#include <stdio.h>

// https://blog.csdn.net/ma2595162349/article/details/102765004

AsyncLogging::AsyncLogging(const string& basename,
                           off_t rollSize,
                           int flushInterval)
	: flushInterval_(flushInterval),  // 日志落盘周期
	  running_(false),                // 日志线程运行标记
	  basename_(basename),            // 日志文件basename
	  rollSize_(rollSize),            // 预留的日志大小
	  thread_(std::bind(&AsyncLogging::threadFunc, this), "Logging"), // 执行该异步日志记录器的线程
	  latch_(1),
	  mutex_(),
	  cond_(mutex_),
	  currentBuffer_(new Buffer),  // 当前缓冲区
	  nextBuffer_(new Buffer),     // 预备缓冲区
	  buffers_()                   // 缓冲区队列
{
	currentBuffer_->bzero();
	nextBuffer_->bzero();
	buffers_.reserve(16);
}


// 向缓冲区追加日志信息，一般LOG_XX会通过Logger::setOutput进行输出控制来调用该append函数
void AsyncLogging::append(const char* logline, int len)
{
	MutexLockGuard lock(mutex_);
	// 如果当前buffer还有空间，就添加到当前日志
	if (currentBuffer_->avail() > len) {
		currentBuffer_->append(logline, len);
	} else {
        // 将使用完后的buffer添加到buffers_
		buffers_.push_back(std::move(currentBuffer_));

		if (nextBuffer_) { // 重新设置当前buffer
			currentBuffer_ = std::move(nextBuffer_);
		} else {
			currentBuffer_.reset(new Buffer); // 如果前端写入速度太快了，一下子把两块缓冲都用完了，那么只好分配一块新的buffer,作当前缓冲，这是极少发生的情况
		}
		 
		currentBuffer_->append(logline, len);

		// 通知日志线程，有数据可写 
		cond_.notify();
	}
}


// 线程调用的函数，主要用于周期性的flush数据到日志文件中
void AsyncLogging::threadFunc()
{
	assert(running_ == true);
	latch_.countDown();
	LogFile output(basename_, rollSize_, false);
	BufferPtr newBuffer1(new Buffer); // 这两个是后台线程的buffer
	BufferPtr newBuffer2(new Buffer);
	newBuffer1->bzero();
	newBuffer2->bzero();
	BufferVector buffersToWrite;      // 保存要写入的日志，用来和前台线程的buffers_进行swap
	buffersToWrite.reserve(16);
	while (running_) {
		assert(newBuffer1 && newBuffer1->length() == 0);
		assert(newBuffer2 && newBuffer2->length() == 0);
		assert(buffersToWrite.empty());

		{
			MutexLockGuard lock(mutex_); // 局部锁
			// 如果buffers_为空，那么表示没有数据需要写入文件，那么就等待指定的时间（注意这里没有用倒数计数器）
			if (buffers_.empty()) { // unusual usage!
				cond_.waitForSeconds(flushInterval_);   // 超时退出机制
			}

			// 无论cond是因何而醒来，无论currentBuffer_满不满，都要将currentBuffer_放到buffers_中
			// 调用移动构造，解决临时对象效率问题，同时  currentBuffer_之后被置空
			buffers_.push_back(std::move(currentBuffer_));
			// 用后台newBuffer1归还前台currentBuffer_
			currentBuffer_ = std::move(newBuffer1);
			 // 双队列，使用新的未使用的buffersToWrite交换buffers_，将buffers_中的数据在异步线程中写入LogFile中
			buffersToWrite.swap(buffers_);
			if (!nextBuffer_) {
				// 用后台newBuffer2归还前台nextBuffer_
				nextBuffer_ = std::move(newBuffer2);
			}
		}
		// 从这里是没有锁，数据落盘的时候不要加锁
		assert(!buffersToWrite.empty());

		// 如果将要写入文件的buffer列表中buffer的个数大于25，那么将多余数据删除	
		// 前端陷入死循环，拼命发送日志消息，超过后端的处理能力，会造成数据在内存中的堆积
		// 严重时引发性能问题(可用内存不足),或程序崩溃(分配内存失败)
		if (buffersToWrite.size() > 25) {
			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());   // 丢掉多余日志，以腾出内存，只保留2个buffer(默认4M)
		}

		// 将buffersToWrite的数据写入到日志中
		for (const auto& buffer : buffersToWrite) {
			// FIXME: use unbuffered stdio FILE ? or use ::writev ?
			output.append(buffer->data(), buffer->length());
		}
		output.flush();   // 保证数据落到磁盘了

		// 重新调整buffersToWrite的大小
		if (buffersToWrite.size() > 2) {
			// drop non-bzero-ed buffers, avoid trashing
			buffersToWrite.resize(2);
		}

		// 前台buffer是由newBuffer1 2 归还的。现在把buffersToWrite的buffer归还给后台buffer
		if (!newBuffer1) {
			assert(!buffersToWrite.empty());
			newBuffer1 = std::move(buffersToWrite.back());    // 复用，从buffersToWrite中弹出一个作为newBuffer1
			buffersToWrite.pop_back();
			newBuffer1->reset();
		}

		if (!newBuffer2) {
			assert(!buffersToWrite.empty());
			newBuffer2 = std::move(buffersToWrite.back());   // 复用，从buffersToWrite中弹出一个作为newBuffer2
			buffersToWrite.pop_back();
			newBuffer2->reset();
		}

		buffersToWrite.clear();

	}
	output.flush();
}

3. 一般流程

前端线程（使用LOG_XX所在线程）有两个Buffer（currentBuffer_ nextBuffer_）和一个Buffer队列buffers_；
后端线程（AsyncLogging::start运行线程）有两个Buffer（newBuffer1 newBuffer2）和一个Buffer队列BufferVector

前端线程使用LOG_XX宏定义记录日志信息，宏会调用Logger构造函数生成匿名Logger对象并返回该对象的impl_.stream_，stream_为LogStream的引用，此时LOG_XX << …会调用LogStream重载的<<将日志信息存入LogStream内部Buffer，Logger对象析构时会取出内部impl_.stream_的Buffer，并由g_output控制输出到特定文件，一般该输出控制会调用AsyncLogging::append，append操作该两Buffer一队列时要加锁mutex_因为后端线程也会操作。前端append将日志信息加到currentBuffer_ ，currentBuffer_ 写满时会被移动到队列buffers_并通知后端线程落盘，此时前端备用nextBuffer_会变为currentBuffer_ 同时nextBuffer_会被置空，后端线程抢到mutex_接收到前端线程的通知或者等待了1个落盘周期会将currentBuffer_ （无论多少数据）移动到buffers_然后用newBuffer1和newBuffer2归还currentBuffer_ 和nextBuffer_空间，currentBuffer_ 和nextBuffer_都用完的概率很小，若确实出现该情况前端线程会申请新的空间给currentBuffer_ ，后端线程在接收到前端线程的通知或者等待了1个落盘周期同时会将buffers_交换到BufferVector落盘，若发现BufferVector消息堆积超过25个Buffer则会丢掉后面23个Buffer，复用留下2个Buffer归还newBuffer1和newBuffer2空间。

4. 使用

//
//  test_asynclog.cc
//  test_asynclog
//
//  Created by blueBling on 22-3-31.
//  Copyright (c) 2022年blueBling. All rights reserved.
//


#include "AsyncLogging.h"
#include "Logging.h"
#include "TimeStamp.h"

#include <iostream>

using std::cout;
using std::endl;

#define LOG_NUM 5000000 // 总共的写入日志行数

static AsyncLogging *g_asyncLog = NULL;

static void asyncOutput(const char *msg, int len)
{
	g_asyncLog->append(msg, len);
}

int test_asynclog() {

	off_t kRollSize = 1 * 1000 * 1000;	  // 只设置1M

	char logfile[128] = "async_log_";
	AsyncLogging log(logfile, kRollSize, 1);
	Logger::setOutput(asyncOutput);
	g_asyncLog = &log;
	log.start();        // 启动日志写入线程


	Timestamp begin_time = Timestamp::now();
	cout << "begin time: " << begin_time.toFormattedString(false) << endl;
	
	for (int i = 0; i < LOG_NUM; i++) {
		LOG_INFO << "NO." << i << " Root Error Message!"; // 47个字节
	}

	log.stop();
	
	Timestamp end_time = Timestamp::now();
	cout << "end time: " << end_time.toFormattedString(false) << endl;
	

	double consume_time = timeDifference(end_time, begin_time);

	cout << "need " << consume_time << "(s)  ops:" <<  (LOG_NUM / (consume_time)) << "/s" << endl;


	return 0;
}

int main() {

	test_asynclog();

	return 0;
}

输出结果：

begin time: 20220420 06:21:31
end time: 20220420 06:21:42
need 11.3246(s)  ops:441515/s

log文件内容：
20220420 06:21:31.593032Z 67098 INFO NO.0 Log Info Message! - test_asynclog.cc:43

5. 源码

Github