Unit Test中Logback 性能测试及优化

发现问题

Technorati Tags: unit test,logback,io,performance 系统使用Logback作为日志记录，但是在执行Unit Test的时候，运行速度降低了一个数量级，没用时 0.0n，用了之后变成 0.n，看如下三个测试用例： 1. 不写Log语句（包括初始化语句）2. 加上Log语句，没有配置文件（logback.xml, logback-test.xml）3. 加上配置文件最快时间和最慢时间有25倍的差距

分析问题

分析下来主要是Logback在读取配置文件的时候消耗IO了时间，做了和外部的交互。虽然对于服务运行，这个级别的时间消耗影响不是很大，而且这个读取配置文件只是一次性消耗，运行以后就不再读了（其实可以配置）。但是对于Unit Test，首先，使单元测试变为一个“不纯”的单元测试，因为和外界进行了交互（IO）。其次，每次跑单个测试都得做这么一次IO的话，总体累计起来也是非常可观的。如果使用TDD，Unit Test跑得慢，会降低开发节奏，影响开发效率[Feathers]给单元测试下了一个极好的定义： 单元测试应该跑起来很快，如果不快，那她们就不是单元测试。每秒钟应该至少能够运行100个测试。从上面的测试数据来看，只有第一个测试是能达到这个速度的级别。注：如果多个Unit Test作为一个Test Suite一起跑的话，这种IO消耗也只有一次，但是我们平时开发面对的更多的是单个Unit Test的执行，所以我们要尽量降低单个Unit Test的执行时间。 但是log语句又不能不写，Unit Test又不能不做，纠结，纠结啊

解决问题

在Logback的Manual中找到：Logback可以通过编程方式或者配置文件来配置Logback采取下面的步骤进行自我配置：尝试在classpath下查找文件logback-test.xml如果文件不存在，则查找文件logback.xml如果两个文件都不存在，logback用BasicConfigurator自动对自己进行配置，这回导致记录输出到控制台。注：来源于The Logback Manual 查看Logback的代码，发现是一个叫ContextInitializer的类来进行初始化的。重写这个类，改变其逻辑，让他不再读XML配置文件。在Test路径下建一个类 ， ch.qos.logback.classic.util.ContextInitializer ，将原来的代码全部考过来，做如下修改修改URL url = null; 如下所示：

1:   public void autoConfig() throws JoranException {

2:     StatusListenerConfigHelper.installIfAsked(loggerContext);

3:     //Commented by jianhua, eliminate io expense for reading config file when run the unit test

4:     //Just use the BasicConfigurator for unit test.

5:     URL url = null;

6:     //URL url = findURLOfDefaultConfigurationFile(true);

7:     if (url != null) {

8:       configureByResource(url);

9:   } else {

10:       BasicConfigurator.configure(loggerContext);

11:   }

12: }

这样就不会去读XML配置文件而直接使用BasicConfigurator注意 一定要是在Test路径下重写这个类，因为是在Test目录下重写的，所以不会影响正式代码的Log配置。最后结果和测试2差不多，和不写Log还是相差了6倍左右，暂时可以接受，不去深究了，洗洗睡了。按照Logback自己的说法，创建一个logger只要13ms,读取存在的logger只要94纳秒，显然在这儿他达不到，参考：LOGBack: Evolving Java Logging针对dao的“集成单元测试”，顺便也重写了一下BasicConfigurator，原来只配了root的Logger，默认级别应该是Debug吧，总之输出了很多不必要的Log，消耗了很多额外时间。现在在BasicConfigurator中添加两个Logger，将Log配置写在代码中，不用去做额外的IO了。

public static void configure(LoggerContext lc) {

StatusManager sm = lc.getStatusManager();[/code]

if(sm != null)  {

sm.add(new InfoStatus("Setting up default configuration.", lc));

}

ConsoleAppender<ILoggingEvent> ca = new ConsoleAppender<ILoggingEvent>();

ca.setContext(lc);

ca.setName("console");

PatternLayoutEncoder pl = new PatternLayoutEncoder();

pl.setContext(lc);

pl.setPattern("%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n");

pl.start();

ca.setEncoder(pl);

ca.start();

Logger rootLogger = lc.getLogger(Logger.ROOT_LOGGER_NAME);

rootLogger.addAppender(ca);

    Logger log1 = lc.getLogger("org.dbunit");

    log1.setLevel(Level.INFO);

    Logger log2 = lc.getLogger("org.hibernate");

    log2.setLevel(Level.WARN);

}

效果也不错，单个测试的时间只有原来的一半。