关于log4j2.xml的异步日志性能疑问

Question

由于生产线上日志打印量非常大，除了减少不必要的日志打印外，还想看看能够做哪方面的优化。
看到很多帖子说log4j2.xml里配置异步日志，性能会更高。于是我在本地尝试测试。但发现结果并不如人意。不使用异步的方式打印反而更快，无论是对多线程还是单线程。不知道是不是我的测试方法有问题。下面贴代码
log4j2.xml<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info">
<Appenders>
<Console name="CONSOLE" target="SYSTEM_OUT">
<PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
</Console>
<!--文件会打印出所有信息，这个log每次运行程序会自动清空，由append属性决定，这个也挺有用的，适合临时测试用 -->
<File name="TEMP" fileName="D:\upm_interface2.log" append="false">
<PatternLayout pattern="%d %-5p [%t] %C{1.} (%F:%L) - %m%n" />
</File>
<!--这个会打印出所有的信息，每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档 -->
<RollingFile name="ROLLING"
fileName="d:/logs/testlog4j2/upm_interfaceTest.log" filePattern="d:/logs/testlog4j2/upm_interface_%d{yyyy-MM-dd}-%i.log.gz">
<PatternLayout pattern="%d %p %c{1.} [%t] %m%n" />
<Policies>
<!-- ====比 如，modulate=true，interval=4hours，那么假设上次封存日志的时间为01:00，则下次封存日志的时间为04:00，之后的封存时间依次为08:00，12:00 -->
<TimeBasedTriggeringPolicy modulate="true"
interval="24" />
<SizeBasedTriggeringPolicy size="2024MB" />
</Policies>
</RollingFile> <Async name="ASYNC">
<!-- <AppenderRef ref="CONSOLE" /> -->
<AppenderRef ref="ROLLING" />
</Async>
</Appenders>
<Loggers>
<!--制定输出com.foo包中的logger, 忽略其他logger <Logger name="com.richinfo" level="info"> 
<AppenderRef ref="ROLLING"/> </Logger> -->
<Root level="info">
<AppenderRef ref="ASYNC" />
</Root>
</Loggers>
</Configuration>关键是<Loggers> 标签里面的<Roo>标签  如果是<AppenderRef ref="ASYNC" />则代表使用异步方式，如果是<AppenderRef ref="ROLLING" />则代表不是异步。然后我写了个测试代码  分别是多线程的  和 单线程的。
package com.test;import java.util.concurrent.CountDownLatch;import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;public class Log4jTest {    private static final Logger LOG = LogManager.getLogger(Log4jTest.class);    private static String[] INFO = {
            "test info test info test info test info test info test info test info test info test info test info test info test info test info test info test info test info",
            "test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug test debug",
            " test error test error test error test error test error test error test error test error test error test error test error test error test error test error test error test error",
            " test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn test warn" };    final static CountDownLatch l = new CountDownLatch(100);    public static void main(String[] agrs) {        test1();
    }    public static void test1() {
        int count = 100;
        long begin = System.currentTimeMillis();
        for (int i = 0; i < count; ++i) {
            new Thread(new Runnable() {
                @Override
                public void run() {
                    for (int i = 0; i < 10000; i++) {
                        LOG.error("[" + Thread.currentThread().getName() + "," + i + "]" + INFO[i % 4]
                                + System.currentTimeMillis());
                    }
                    l.countDown();
                }
            }).start();
        }
        try {
            System.out.println("waiting");
            l.await();
            LOG.error("FINISH. COST : " + (System.currentTimeMillis() - begin));
            System.out.println("finishing:" + ((System.currentTimeMillis() - begin) * 0.001f) + "s");
        } catch (InterruptedException e) {
            LOG.error("ERROR");
        }    }    public static void test2() {        long begin = System.currentTimeMillis();
        for (int i = 0; i < 5000000; i++) {
            LOG.error("[" + Thread.currentThread().getName() + "," + i + "]" + INFO[i % 4] + System.currentTimeMillis());
        }
        System.out.println("waiting");
        LOG.error("FINISH. COST : " + (System.currentTimeMillis() - begin));
        System.out.println("finishing:" + ((System.currentTimeMillis() - begin) * 0.001f) + "s");    }
}
test1方法是多线程   开100个线程，每个线程打印10000条 所有线程执行完毕后记录时间  异步日志打印耗时12S左右  非异步日志打印9S左右test2方法是单线程方法  打印500万条数据。异步日志打印耗时平均40多S，而非异步耗时平均30多秒。 疑惑  是不是测试方式不对呢？求解答

Answer 1

日志可以首先控制输出范围，比如产线一般WARN甚至ERROR级别。这个一般中小项目够用了，除非并发很大，数据量业务量很大。
其次专门的日志管理。

Answer 2

遇到同样的问题，官网中AsyncAppender下有一句话，这个appender默认使用ArrayBlockingQueue，多线程容易发生锁的争用影响效率，建议使用AsyncLoggers的方式。官方提供的testcase里使用AsyncAppender柱状图显示效率也一般，而AsyncLoggers明显效率提升。可参考http://logging.apache.org/log4j/2.x/manual/appenders.html#AsyncAppender