日志库log4cpp剖析：日志记录和框架分析

原创

Lion Long

发布于 2024-10-31 21:19:17

1470

发布于 2024-10-31 21:19:17

文章被收录于专栏：后端开发技术

一、log4cpp日志框架

log4cpp是个基于LGPL的开源项⽬，移植⾃Java的⽇志处理跟踪项⽬log4j，并保持了API上的⼀致。其类似的⽀持库还包括Java(log4j)，C++(log4cpp、log4cplus)，C(log4c)，python(log4p)等。

Log4cpp中最重要概念有Category（种类）、Appender（附加器）、Layout（布局）、Priority（优先级）、NDC（嵌套的诊断上下⽂）。

Log4cpp中的Category使其支持每个模块都有独立的日志的输出。Layout是格式化输出。 Log4cpp支持树状功能。也就是说一个根节点下的所有子节点模块的输出都打印到根节点模块中的输出文件里。 Log4cpp适合使用在客户端，不适合使用在服务器。Log4cpp不是批量写入模式，而是直接调用write() 进行实时写入，这样的性能就不会非常高。但是可以借鉴它的一些成熟的理念。

1.1、log4cpp下载编译

（1）下载。

wget https://sourceforge.net/projects/log4cpp/files/latest/download

（2）解压。

tar zxf log4cpp-1.1.3.tar.gz

（3）编译。

cd log4cpp 
./configure 
make 
make check 
sudo make install 
sudo ldconfig

默认安装路径：头⽂件：/usr/local/include/log4cpp 库⽂件：/usr/local/lib/

1.2、log4cpp日志级别

enum LogLevel { 
	TRACE, 
	DEBUG, 
	INFO, 
	WARN, 
	ERROR, 
	FATAL, 
	NUM_LOG_LEVELS, 
};

在使⽤⽇志库的时候要注意不同⽇志库的级别有差异，⽐如有些⽇志库 DEBUG和INFO的级别是反过来的。

1.3、log4cpp日志格式化

一般日志输出时会携带一些关注的信息，比如

20210410 14:18:15.299684Z 30836 INFO NO.1506710 Root Error Message! - log_test.cpp:17

格式包含：年月日时分秒微妙时区日志级别日志内容文件名行号。

比如Log4cpp支持的转义定义： ◼ %% - 转义字符’%’ ◼ %c - Category ◼ %d - 日期；日期可以进一步设置格式，用花括号包围，例如%d{%H:%M:%S,%l}。日期的格式符号与ANSI C函数strftime中的一致。但增加了一个格式符号%l，表示毫秒，占三个十进制位。 ◼ %m - 消息 ◼ %n - 换行符；会根据平台的不同而不同，但对用户透明。 ◼ %p - 优先级 ◼ %r - 自从layout被创建后的毫秒数 ◼ %R - 从1970年1月1日开始到目前为止的秒数 ◼ %u - 进程开始到目前为止的时钟周期数 ◼ %x - NDC ◼ %t - 线程id

1.4、log4cpp日志Loyout

log4cpp支持的日志布局有：

（1）BasicLayout::format。基本布局。它会为你添加“时间”、“优先级”、“种类”、“NDC”。相当于PatternLayout格式化为：“%R %p %c %x: %m%n”。

（2） PassThroughLayout::format。直通布局。顾名思义，这个就是没有布局的“布局”，你让它写什么它就写什么，它不会为你添加任何东西，连换行符都懒得为你加。但是，它支持自定义的布局，我们可以继承他实现自定义的日志格式。

（3） PatternLayout::format log4cpp。格式化布局，支持用户配置日志格式。它的使用方式类似C语言中的printf，使用格式化它符串来描述输出格式；目前支持的转义定义。

（4） SimpleLayout::format 。简单布局。比BasicLayout还简单的日志格式输出，它只会为你添加“优先级”的输出。相当于PatternLayout格式化为：“%p: %m%n”。

1.5、log4cpp日志输出

日志有不同的输出方式，以log4cpp为例：（1）日志输出到控制台。ConsoleAppender。（2）日志输出到本地文件。FileAppender，值得注意的是，log4cpp使用write()来输出到文件，这种方式的性能不会太高i，因为要频繁的切换用户态和内核态。这是一个可以优化的地方。（3）日志通过网络传输到远程服务器。RemoteSyslogAppender。

1.6、log4cpp日志回滚

日志库一般都具备如下功能：（1）本地日志支持最大文件限制。（2）当本地日志达到最大文件限制的时候新建一个文件。（3）每天至少一个文件。

比如log4cpp里的RollingFileAppender()。

RollingFileAppender(
	const std::string& name,
	const std::string& filename,
	size_t maxFileSize=10*1024*1024//日志文件支持最大的大小
	unsigned int maxBackupIndex=1,//最大生成文件数量
	bool append=true,// 是否以追加的方式写入
	mode_t mode = 00644
);

1.7、log4cpp日志配置

成熟的日志文件要支持配置文件，通过修改配置文件来改变日志输出方式而不需要修改代码。比如log4cpp日志配置：

# a simple test config
#定义了3个category sub1, sub2, sub1.sub2
# category 有两个参数 日志级别,Appender
log4cpp.rootCategory=DEBUG, rootAppender
# log4cpp.category.sub1设置日志级别默认和root一致, Appender为A1
log4cpp.category.sub1=,A1
# log4cpp.category.sub2设置为INFO，Appender默认使用root的
log4cpp.category.sub2=INFO
#log4cpp.category.sub1.sub2=ERROR, A2
log4cpp.category.sub1.sub2=, A2
# 设置sub1.sub2 的additivity属性，该属性默认值为true
# 如果值为true，则该Category的Appender包含了父Category的Appender, 即是日志也从root的appender输出
# 如果值为false，则该Category的Appender取代了父Category的Appender
log4cpp.additivity.sub1=false
# sub1.sub2的日志也从sub1的appender输出
log4cpp.additivity.sub1.sub2=true 
#定义rootAppender类型和layout属性
log4cpp.appender.rootAppender=org.apache.log4cpp.ConsoleAppender
log4cpp.appender.rootAppender.layout=org.apache.log4cpp.BasicLayout
#定义A1的属性
log4cpp.appender.A1=org.apache.log4cpp.FileAppender
log4cpp.appender.A1.fileName=A1.log
log4cpp.appender.A1.layout=org.apache.log4cpp.SimpleLayout
#定义A2的属性
log4cpp.appender.A2=org.apache.log4cpp.ConsoleAppender
log4cpp.appender.A2.layout=org.apache.log4cpp.PatternLayout
#log4cpp.appender.A2.layout.ConversionPattern=The message '%m' at time 
# log4cpp.appender.A2.layout.ConversionPattern=%d %m %n
# %d 时间戳 %t 线程名 %x NDC  %p 优先级 %m log message 内容  %n 回车换行
log4cpp.appender.A2.layout.ConversionPattern=%d %p %x - %m%n

二、Log4cpp配置文件剖析

Category有2个参数：日志级别，Appender。留空说明是继承父的设置，不为空则是自己的级别。

看如下示例，定义了3个category sub1, sub2, sub1.sub2：

# a simple test config
#定义了3个category sub1, sub2, sub1.sub2
# category 有两个参数 日志级别,Appender
log4cpp.rootCategory=DEBUG, rootAppender
# log4cpp.category.sub1设置日志级别默认和root一致, Appender为A1
log4cpp.category.sub1=,A1
# log4cpp.category.sub2设置为INFO，Appender默认使用root的
log4cpp.category.sub2=INFO
#log4cpp.category.sub1.sub2=ERROR, A2
log4cpp.category.sub1.sub2=, A2
# 设置sub1.sub2 的additivity属性，该属性默认值为true
# 如果值为true，则该Category的Appender包含了父Category的Appender, 即是日志也从root的appender输出
# 如果值为false，则该Category的Appender取代了父Category的Appender
log4cpp.additivity.sub1=false
# sub1.sub2的日志也从sub1的appender输出
log4cpp.additivity.sub1.sub2=true 
#定义rootAppender类型和layout属性
log4cpp.appender.rootAppender=org.apache.log4cpp.ConsoleAppender
log4cpp.appender.rootAppender.layout=org.apache.log4cpp.BasicLayout
#定义A1的属性
log4cpp.appender.A1=org.apache.log4cpp.FileAppender
log4cpp.appender.A1.fileName=A1.log
log4cpp.appender.A1.layout=org.apache.log4cpp.SimpleLayout
#定义A2的属性
log4cpp.appender.A2=org.apache.log4cpp.ConsoleAppender
log4cpp.appender.A2.layout=org.apache.log4cpp.PatternLayout
#log4cpp.appender.A2.layout.ConversionPattern=The message '%m' at time 
# log4cpp.appender.A2.layout.ConversionPattern=%d %m %n
# %d 时间戳 %t 线程名 %x NDC  %p 优先级 %m log message 内容  %n 回车换行
log4cpp.appender.A2.layout.ConversionPattern=%d %p %x - %m%n

（1）rootCategory是根根节点，sub1和sub2是rootCategory的子节点，sub1.sub2是sub1的子节点。（2）Category的additivity属性默认值为true。如果additivity属性值为true，则该Category的Appender包含了父Category的Appender, 即是日志也从root的appender输出；如果additivity属性值为false，则该Category的Appender取代了父Category的Appender。（3）appender用于定义该category的Appender的日志输出属性是ConsoleAppender还是FileAppender亦或者是RemoteSyslogAppender。（4）layout用于定义该category的Appender的布局是SimpleLayout、BasicLayout、PassThroughLayout、PatternLayout中的一种。（5）如果日志输出属性是FileAppender，那么fileName指定输出的文件名。（6）ConversionPattern用于PatternLayout的日志格式化。（7）log4cpp的category支持树状结构；可以分模块打印不同的日志文件，也可以把所有模块的日志也打印同一个文件。

读取配置文件示例代码：

#include "log4cpp/Category.hh"
#include "log4cpp/PropertyConfigurator.hh"

int main(int argc,char *argv[])
{
	//读取解析配置文件
	try
	{
		log4cpp::PropertyConfigurator::configure("./test_log4cpp.conf");
	}
	catch (log4cpp::ConfigureFailure &f)
    {
        std::cout << "Configure Problem " << f.what() << std::endl;
        return -1;
    }
    // 实例化category对象
    log4cpp::Category &root = log4cpp::Category::getRoot();
    log4cpp::Category &sub1 = log4cpp::Category::getInstance(std::string("sub1"));
    log4cpp::Category &sub2 = log4cpp::Category::getInstance(std::string("sub2"));
    log4cpp::Category &sub1_sub2 = log4cpp::Category::getInstance(std::string("sub1.sub2"));
    // 正常使用这些category对象进行日志处理。
    root.debug("root debug");
    root.info("root info");
    root.notice("root notice");
    root.warn("root warn");
    root.error("root error");
    root.crit("root crit");
    root.alert("root alert");
    root.fatal("root fatal");
    root.emerg("root emerg");
    // sub1的
    sub1.debug("sub1 debug");
    sub1.info("sub1 info");
    //...
    
	// sub2的
	sub2.debug("sub2 debug");
    sub2.info("sub2 info");
    // ...
    
	// sub.sub2的
	sub1_sub2.debug("sub1_sub2 debug");
    sub1_sub2.info("sub1_sub2 info");
    // ...

	// clean up and flush all appenders
	log4cpp::Category::shutdown();
	
	return 0;
}

主要分为几个步骤：（1）读取解析配置文件。读取出错, 完全可以忽略，可以定义一个缺省策略或者使用系统缺省策略。（2）2 实例化category对象。这些对象即使配置文件没有定义也可以使用，不过其属性继承其父category；通常使用引用可能不太方便，可以使用指针，以后做指针使用。（3）使用这些category对象进行日志处理。（4）清理并刷新所有的appenders。

三、Log4cpp调用栈分析

3.1、Category::callAppenders

遍历所有的Appender，输出日志以及是否输出到父类中。

void Category::callAppenders(const LoggingEvent& event) throw() {
    threading::ScopedLock lock(_appenderSetMutex);
    {
        if (!_appender.empty()) {
            for(AppenderSet::const_iterator i = _appender.begin();
                i != _appender.end(); i++) {
                (*i)->doAppend(event);
            }
        }
    }
    if (getAdditivity() && (getParent() != NULL)) {
        getParent()->callAppenders(event);
    }
}

3.2、FileAppender::_append

写日志到文件中，使用的write()系统接口。

void FileAppender::_append(const LoggingEvent& event) {
        std::string message(_getLayout().format(event));
        if (!::write(_fd, message.data(), message.length())) {
            // XXX help! help!
        }
    }

3.3、RollingFileAppender::_append

通过lseek() 获取文件大小，性能比较低比较低。

void RollingFileAppender::rollOver() {
    ::close(_fd);
    if (_maxBackupIndex > 0) {
        std::ostringstream filename_stream;
    	filename_stream << _fileName << "." << std::setw( _maxBackupIndexWidth ) << std::setfill( '0' ) << _maxBackupIndex << std::ends;
    	// remove the very last (oldest) file
    	std::string last_log_filename = filename_stream.str();
        // std::cout << last_log_filename << std::endl; // removed by request on sf.net #140
        ::remove(last_log_filename.c_str());
        
        // rename each existing file to the consequent one
        for(unsigned int i = _maxBackupIndex; i > 1; i--) {
            filename_stream.str(std::string());
            filename_stream << _fileName << '.' << std::setw( _maxBackupIndexWidth ) << std::setfill( '0' ) << i - 1 << std::ends;  // set padding so the files are listed in order
            ::rename(filename_stream.str().c_str(), last_log_filename.c_str());
            last_log_filename = filename_stream.str();
        }
        // new file will be numbered 1
        ::rename(_fileName.c_str(), last_log_filename.c_str());
    }
    _fd = ::open(_fileName.c_str(), _flags, _mode);
}

void RollingFileAppender::_append(const LoggingEvent& event) {
    FileAppender::_append(event);
    off_t offset = ::lseek(_fd, 0, SEEK_END);
    if (offset < 0) {
        // XXX we got an error, ignore for now
    } else {
        if(static_cast<size_t>(offset) >= _maxFileSize) {
            rollOver();
        }
    }
}

如何判断文件大小呢：（1）简单粗暴方式，lseek()。缺点是性能差。（2）stat()方法。推荐此方式。

3.4、示例

#include "log4cpp/Category.hh"
#include "log4cpp/FileAppender.hh"
#include "log4cpp/OstreamAppender.hh"
#include "log4cpp/BasicLayout.hh"
#include "log4cpp/SimpleLayout.hh"

// 编译 g++ -o 2-test_log4cpp 2-test_log4cpp.cpp -llog4cpp
int main(int argc, char *argv[])
{
    // 1实例化一个layout 对象
    log4cpp::Layout *layout = new log4cpp::SimpleLayout();   // 有不同的layout
    // 2. 初始化一个appender 对象
    log4cpp::Appender *appender = new log4cpp::FileAppender("FileAppender",
     "./test_log4cpp.log");
    log4cpp::Appender *osappender = new log4cpp::OstreamAppender("OstreamAppender",
        &std::cout);
    // 3. 把layout对象附着在appender对象上
    appender->setLayout(layout);
    // appender->addLayout 没有addLayout，一个layout格式样式对应一个appender
    // 4. 实例化一个category对象
    log4cpp::Category &warn_log =
        log4cpp::Category::getInstance("helloworld");   // 是一个单例工厂
    // 5. 设置additivity为false，替换已有的appender
    warn_log.setAdditivity(false);
    // 5. 把appender对象附到category上
    warn_log.setAppender(appender);
    warn_log.addAppender(osappender);
    // 6. 设置category的优先级，低于此优先级的日志不被记录
    warn_log.setPriority(log4cpp::Priority::INFO);
    // 记录一些日志
    warn_log.info("Program info which cannot be wirten, helloworld = %d", 100);
    warn_log.warn("Program info which cannot be wirten, helloworld = %d", 100);
    warn_log.debug("This debug message will fail to write");
    warn_log.alert("Alert info");       // C 风格
    warn_log.log(log4cpp::Priority::CRIT, "Importance depends on context");
    // 其他记录日志方式
    warn_log.log(log4cpp::Priority::WARN, "This will be a logged warning, helloworld = %d", 100);
    warn_log.warnStream() << "This will be a logged warning, helloworld = " << 100; // C++ 风格

    log4cpp::Priority::PriorityLevel priority;
    bool this_is_critical = true;
    if (this_is_critical)
        priority = log4cpp::Priority::CRIT;
    else
        priority = log4cpp::Priority::DEBUG;
    warn_log.log(priority, "Importance depends on context");

    warn_log.critStream() << "This will show up << as "
                          << 1 << " critical message";
    // clean up and flush all appenders
    log4cpp::Category::shutdown();
    return 0;
}

四、Log4cpp日志回滚

数字越大，数据越久。当文件内容和文件数据都达到设定的阈值时，会执行如下操作（假如设置了最大文件数是5）：（1）删除数字最大的文件。删除log5.txt。（2）文件重命名。

（3）新建log文件。

五、log4cpp日志性能分析

（1）实时写入磁盘单笔 write。多行（100行）日记累积再写入 -> 累积了99行，下一行一直不来。 a.单独起一个定时器（比如1秒）去刷新。 b.同一个日志管理线程去刷新数据。注：实际glog他是累积一定的行数或者过了一定的时间间隔就让刷新。

（2）回滚日志每次都取读取日志文件大小肯定不能每次读取文件大小。

5.1、FileAppender优化

异步日志，从批量写入和超时方向的考量。

日志落盘线程，比如超过100条写入磁盘、超时一秒钟写入磁盘。

5.2、FileAppender改进之glog同步日志线程

glog日志线程逻辑相对简单。（1）积累一定数量日志再写入。（2）超时写入。比如，第一条日志1秒的时候写入；第二条日志3秒的时候写入。跟上一次刷新超过一定的时间，也会把所有的缓存日志刷新磁盘中。

这种方式支持批量写入，但不是最好的解决方案。

5.3、异步写入性能测试

#include <iostream>
#include <sys/time.h>
#include <stdint.h>
#include <log4cpp/Category.hh>
#include <log4cpp/OstreamAppender.hh>
#include <log4cpp/BasicLayout.hh>
#include <log4cpp/Priority.hh>
#include <log4cpp/StringQueueAppender.hh>
#include <log4cpp/threading/Threading.hh>
using namespace std;

#define LOG_NUM 50000         // 总共的写入日志行数
#define LOG_WRITE_NUM    10000  // 多久写入一次日志
#define LOG_FLUSH_NUM   10000   // 多久flush一次
static uint64_t get_tick_count()
{
    struct timeval tval;
    uint64_t ret_tick;
    
    gettimeofday(&tval, NULL);
    
    ret_tick = tval.tv_sec * 1000L + tval.tv_usec / 1000L;
    return ret_tick;
}
// g++  -g -o 5-StringQueueAppender 5-StringQueueAppender.cpp -llog4cpp -lpthread
int main(int argc, char* argv[])
{
     log4cpp::StringQueueAppender* strQAppender = new log4cpp::StringQueueAppender("strQAppender");
    strQAppender->setLayout(new log4cpp::BasicLayout());
    
    log4cpp::Category& root = log4cpp::Category::getRoot();
    root.addAppender(strQAppender);
    root.setPriority(log4cpp::Priority::DEBUG);
    
    root.error("Hello log4cpp in a Error Message!");
    root.warn("Hello log4cpp in a Warning Message!");
    
    cout<<"Get message from Memory Queue!"<<endl;
    cout<<"-------------------------------------------"<<endl;

    uint64_t begin_time = get_tick_count();
    std::cout << "begin_time: " << begin_time << std::endl;
    for (int i = 0; i < LOG_NUM; i++)
    {
        string strError;
        ostringstream oss;
        oss<<"NO." << i<<" Root Error Message!";        // 47字节 * 10000 = 470000=470k
        strError = oss.str();
        root.error(strError);
    }
    uint64_t end_time = get_tick_count();
    std::cout << "end_time: " << end_time << std::endl;
    std::cout << "need the time: " << end_time << " " << begin_time << ", " << end_time - begin_time << "毫秒\n" ;

    queue<string>& myStrQ = strQAppender->getQueue();
    std::string bufString;
    int bufCount = 0;
    int flush_count = 0;

    std::cout << "\nRollingFileAppender-----------------> "<< std::endl;
     begin_time = get_tick_count();
    std::cout << "begin_time: " << begin_time << std::endl;
    FILE *file = fopen("StringQueueAppender.log", "wt");
    log4cpp::threading::Mutex _appenderSetMutex;
    while(!myStrQ.empty())
    {
        log4cpp::threading::ScopedLock lock(_appenderSetMutex);
        off_t offset = fseek(file, 0, SEEK_END);
        offset = offset;
        // cout<<myStrQ.front();
        // std::cout << "append\n";
        bufString.append(myStrQ.front().c_str(), myStrQ.front().size());    // 拷贝5000000
        // std::cout << "append2\n";
        if(++bufCount >= LOG_WRITE_NUM) 
        {
            bufCount = 0;
            // std::cout << myStrQ.front() << std::endl;
            fwrite(bufString.c_str(), bufString.size(), 1, file);
            bufString.clear();
        }

        if(++flush_count >= LOG_FLUSH_NUM) 
        {
            flush_count = 0;
             fflush(file);
        }

        myStrQ.pop();
    }
    fwrite(bufString.c_str(), bufString.size(), 1, file);
    fclose(file);
    end_time = get_tick_count();
    int64_t ops = LOG_NUM;
    ops = ops * 1000 /(end_time - begin_time);
    std::cout << "need the time: " << end_time << " " << begin_time << ", " << end_time - begin_time << "毫秒" << ", ops = " << ops << "ops/s\n" ;
    log4cpp::Category::shutdown();    
    return 0;
}

测试结果：

Get message from Memory Queue!
-------------------------------------------
begin_time: 1665467762532
end_time: 1665467762580
need the time: 1665467762580 1665467762532, 48毫秒

RollingFileAppender-----------------> 
begin_time: 1665467762580
need the time: 1665467762608 1665467762580, 28毫秒, ops = 1785714ops/s

性能上比同步写入大得多。