Linux基础组件之log4cpp剖析

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调用栈分析

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);
    }
}

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!
        }
    }

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()方法。推荐此方式。

示例

#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） 回滚日志每次都取读取日志文件大小 肯定不能每次读取文件大小。

FileAppender优化

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

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

FileAppender改进之glog同步日志线程

glog日志线程逻辑相对简单。
（1）积累一定数量日志再写入。
（2）超时写入。比如，第一条日志1秒的时候写入；第二条日志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

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

总结

（1）日志的树状模块输出。
（2）支持多种输出方式，每种输出方式都可以有不同的格式化。
（3）log4cpp代码结构组织。

（4）不要直接把log4cpp用在服务器中，因为log4cpp的性能稍差。