Log4J，在踩坑中升级版本
基本概念
Commons-logging
apache最早提供的日志的门面接口。避免和具体的日志方案(log4j、logback等)直接耦合。类似于JDBC的api接口，具体的的JDBC driver实现由各数据库提供商实现。JCL的思想也是想通过统一接口解耦，将日志方案的实现与日志接口分离。
但是Apache Commons Logging的动态绑定并不是总能成功。解决方法之一就是在程序部署时静态绑定指定的日志工具，这就是slf4j产生的原因。
slf4j
slf4j跟JCL一样，slf4j也是只提供log接口，具体的实现是在打包应用程序时所放入的绑定器（名字为 slf4j-XXX-version.jar）来决定，XXX 可以是log4j12, jdk14, jcl, nop等，他们实现了跟具体日志工具（比如 log4j）的绑定及代理工作。举个例子：如果一个程序希望用log4j日志工具，那么程序只需针对slf4j-api接口编程，然后在打包时再放入log4j-slf4j-impl.jar等相关包就可以了。
比如我们的系统，使用了slf4j+log4j，需要使用到下面几个包
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.7.21</version>
</dependency>
Log4j、Logback
Log4j
Apache的一个开放源代码项目，通过使用Log4j，我们可以控制日志信息输送的目的地是控制台、文件、GUI组件、甚至是套接口服务器、NT的事件记录器、UNIX Syslog守护进程等；用户也可以控制每一条日志的输出格式；通过定义每一条日志信息的级别，用户能够更加细致地控制日志的生成过程。这些可以通过一个 配置文件来灵活地进行配置，而不需要修改程序代码。
LogBack
Logback是由log4j创始人设计的又一个开源日记组件。logback当前分成三个模块：logback-core,logback- classic和logback-access。logback-core是其它两个模块的基础模块。logback-classic是log4j的一个改良版本。此外logback-classic完整实现slf4j API使你可以很方便地更换成其它日记系统如log4j或JDK14 Logging。logback-access访问模块与Servlet容器集成提供通过Http来访问日记的功能。
Log4j与LogBack比较
LogBack作为一个通用可靠、快速灵活的日志框架，将作为Log4j的替代和SLF4J组成新的日志系统的完整实现。LOGBack声称具有极佳的性能，“ 某些关键操作，比如判定是否记录一条日志语句的操作，其性能得到了显著的提高。这个操作在LogBack中需要3纳秒，而在Log4J中则需要30纳秒。 LogBack创建记录器（logger）的速度也更快：13微秒，而在Log4J中需要23微秒。更重要的是，它获取已存在的记录器只需94纳秒，而 Log4J需要2234纳秒，时间减少到了1/23。跟JUL相比的性能提高也是显著的”。 另外，LOGBack的所有文档是全面免费提供的，不象Log4J那样只提供部分免费文档而需要用户去购买付费文档。
Log4j版本升级
对于Log4j的使用场景，肯定是多线程并发的情况。一个new FileOutputStream对象表示一个打开文件对象。那么当多个线程使用同一个FileOutputStream对象写文件时，就需要进行同步操作。
可以把一个FileAppender对象理解成维护了一个打开文件对象，当Logger在多线程情况下把日志写入文件时，需要对Appender进行同步，也就是说对Logger加锁，保证使用同一个Logger对象时，一次只有一个线程使用这个FileAppender来写文件，避免了多线程情况下写文件错误。
log4j 1.x版本的锁
Hierarchy.java，多个线程使用同一个Logger时，加锁。
public void callAppenders(LoggingEvent event) {
int writes = 0;
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
AppenderSkeleton.java，多个线程使用同一个Appender时，对Appender加锁
public synchronized void doAppend(LoggingEvent event) {
if(closed) {
LogLog.error("Attempted to append to closed appender named ["+name+"].");
return;
}
if(!isAsSevereAsThreshold(event.getLevel())) {
return;
}
Filter f = this.headFilter;
FILTER_LOOP:
while(f != null) {
switch(f.decide(event)) {
case Filter.DENY: return;
case Filter.ACCEPT: break FILTER_LOOP;
case Filter.NEUTRAL: f = f.getNext();
}
}
this.append(event);
}
这几个锁在高并发的情况下对系统的性能影响很大，会阻塞掉业务进程，特别是在for循环里加锁的方式很不可取。而日志收集工作应该是作为一个辅助功能，不能影响主业务功能。
log4j 2.3的线程切换
Log4j 2使用了新一代的基于LMAX Disruptor的无锁异步日志系统。在多线程的程序中，异步日志系统吞吐量比Log4j 1.x和logback高10倍，而时间延迟更低。
听起来很美，是不是？
发现这个问题的原因是我们线上出了一次故障，当一次网络异常，导致上游不断重试并发请求量特别高时，cpu利用率跑到了4000%，服务完全恢复不过来了，一开始以为是GC的原因导致服务出问题了。后来在线下进行复现，查看GC发现没啥异常，但是发现了如下的数据
dstat
usr 占用不高，sys 占用超高，同时csw(context switch) 达到1200w，一次csw 大约耗费1000ns，已经逼近cpu的极限。
jstack -l 43911> 43911.log
grep tid 43911.log | wc -l
12312
grep RUNNABLE 43911.log | wc -l
53
总线程12312，处于runnable的只有53个，看看这些线程在干什么
"pool-6-thread-14380" prio=10 tid=0x00007f7087594000 nid=0x53e1 runnable [0x00007f6b67bfc000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:502)
at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.callAppendersFromAnotherThread(AsyncLoggerConfigHelper.java:342)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:114)
......
grep "LockSupport.java:349" 43911.log | wc -l
11536
线程都跑在LockSupport.java:349，
unsafe.park(false, 1);
1 nano = 10^-9s, 推测大量线程频繁的短时间sleep造成了大量的线程切换，做个实验：
public static void contextSwitchTest(int threadCount) throws Exception {
ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
for (int i = 0; i < threadCount; i++) {
executorService.execute(new Runnable() {
@Override
public void run() {
while (true) {
LockSupport.parkNanos(1);
}
}
});
}
executorService.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
}
在一台搭载了两个E5-2670 v3 @ 2.30GHz的机器上测试这段代码，在threadCount达到600后，测试跑起来后立即发现上下文切换到百万级别，推测被印证。
原因找到了，接下来看看出问题是log生产速度怎么样：通过不断地ls -al error.log/business.log，发现Log的生成速度才几MB/s,远没有达到磁盘的极限200M/s，再做个测试：
private static void loggerSpeedTest(int threadCount) throws Exception {
ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
for (int i = 0; i < threadCount; i++) {
executorService.execute(new Runnable() {
@Override
public void run() {
while (true) {
LOGGER.error("test log4j2 logging speed", new UnsupportedOperationException());
}
}
});
}
executorService.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
}
线程少的时候速度还行，线程一多很慢，问题找到了，但什么造成的这个问题呢，顺着stacktrace挖一挖：
AsyncLoggerConfig.callAppenders()
@Override
protected void callAppenders(final LogEvent event) {
// populate lazily initialized fields
event.getSource();
event.getThreadName();
// pass on the event to a separate thread
if (!helper.callAppendersFromAnotherThread(event)) {
super.callAppenders(event);
}
}
AsyncLoggerConfigHelper.callAppendersFromAnotherThread()
public boolean callAppendersFromAnotherThread(final LogEvent event) {
// TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
final Disruptor<Log4jEventWrapper> temp = disruptor;
if (temp == null) { // LOG4J2-639
LOGGER.fatal("Ignoring log event after log4j was shut down");
return true;
}
// LOG4J2-471: prevent deadlock when RingBuffer is full and object
// being logged calls Logger.log() from its toString() method
if (isAppenderThread.get() == Boolean.TRUE //
&& temp.getRingBuffer().remainingCapacity() == 0) {
// bypass RingBuffer and invoke Appender directly
return false;
}
// LOG4J2-639: catch NPE if disruptor field was set to null after our check above
try {
LogEvent logEvent = event;
if (event instanceof RingBufferLogEvent) {
logEvent = ((RingBufferLogEvent) event).createMemento();
}
logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
// Note: do NOT use the temp variable above!
// That could result in adding a log event to the disruptor after it was shut down,
// which could cause the publishEvent method to hang and never return.
disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
} catch (final NullPointerException npe) {
LOGGER.fatal("Ignoring log event after log4j was shut down.");
}
return true;
}
RingBuffer.publishEvent()
@Override
public <A, B> void publishEvent(EventTranslatorTwoArg<E, A, B> translator, A arg0, B arg1){
final long sequence = sequencer.next();
translateAndPublish(translator, sequence, arg0, arg1);
}
MultiProducerSequencer.next()
@Override
public long next(int n){
if (n < 1){
throw new IllegalArgumentException("n must be > 0");
}
long current;
long next;
do{
current = cursor.get();
next = current + n;
long wrapPoint = next - bufferSize;
long cachedGatingSequence = gatingSequenceCache.get();
if (wrapPoint > cachedGatingSequence || cachedGatingSequence > current){
long gatingSequence = Util.getMinimumSequence(gatingSequences, current);
if (wrapPoint > gatingSequence){
LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy?
continue;
}
gatingSequenceCache.set(gatingSequence);
}else if (cursor.compareAndSet(current, next)){
break;
}
}while (true);
return next;
}
整个流程下来就是说在消费速度跟不上生产速度的时候，生产线程做了无限重试，重试间隔为1 nano，这个1 nano 会导致线程被频繁休眠／唤醒，造成kernal cpu 利用率高，context switch已经达到了cpu的极限，进而导致写log的线程的线程获取cpu时间少，吞吐量下降。
查了下log4j的bug，发现：https://github.com/apache/logging-log4j2/commit/7a7f5e4ed1ce8a27357a12a06d32ca2b04e5eb56
if this fails because the queue is full, then fall back to asking AsyncEventRouter what to do with the event，
把log4j2版本切到2.7， 跑一下上面的测试，发现性能上来了， context swtich也有了数量级的下降，看看怎么办到的：
AsyncLoggerConfig.callAppenders()
@Override
protected void callAppenders(final LogEvent event) {
populateLazilyInitializedFields(event);
if (!delegate.tryEnqueue(event, this)) {
final EventRoute eventRoute = delegate.getEventRoute(event.getLevel());
eventRoute.logMessage(this, event);
}
}
AsyncLoggerConfigDisruptor.getEventRoute()
@Override
public EventRoute getEventRoute(final Level logLevel) {
final int remainingCapacity = remainingDisruptorCapacity();
if (remainingCapacity < 0) {
return EventRoute.DISCARD;
}
return asyncQueueFullPolicy.getRoute(backgroundThreadId, logLevel);
}
DefaultAsyncQueueFullPolicy.getRoute()
@Override
public EventRoute getRoute(final long backgroundThreadId, final Level level) {
// LOG4J2-1518: prevent deadlock when RingBuffer is full and object being logged calls
// Logger.log in application thread
// See also LOG4J2-471: prevent deadlock when RingBuffer is full and object
// being logged calls Logger.log() from its toString() method in background thread
return EventRoute.SYNCHRONOUS;
}
没有了park，被block的线程没有一直被调度，context switch减少了，kernel cpu下降了，真正获取到lock的线程获得了更多的cpu用来干活了。
log4j的性能
一想到性能，有哪些是对java程序影响大的呢？ 我们直观地会认为反射、编解码，这些东西对性能影响比较大。
使用JProfiler进行分析后，一些结果却让人吃惊不小，最耗CPU的居然是以下函数
InetSocketAddress.getHostName()
Log.info
String.format
String.replace
Gson.fromJson
把log关闭后，InetSocketAddress.getHostName()的居然占到了惊人的27%！
当然，性能并不是最重要的指标，相比于日志能带来的定位线上问题的好处，这一点性能的损耗其实不值一提，毕竟业务开发中，效率和稳定性才是最重要的。
参考文档
java日志，需要知道的几件事
本文中关于log4j 2.3的主要内容其实是我mentor写的，我主要是重新走了一下流程，补全了图片与测试数据，并对内容做了少部分处理。
posted on 2017-04-23 11:02 flystar32 阅读(23221) 评论(1) 编辑 收藏 举报
