Log4J,在踩坑中升级版本 您所在的位置:网站首页 log4j升级 Log4J,在踩坑中升级版本

Log4J,在踩坑中升级版本

#Log4J,在踩坑中升级版本| 来源: 网络整理| 查看: 265

基本概念 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,需要使用到下面几个包

org.apache.logging.log4j log4j-api 2.7 org.apache.logging.log4j log4j-core 2.7 org.apache.logging.log4j log4j-slf4j-impl 2.7 org.slf4j slf4j-api 1.7.21 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 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写的,我主要是重新走了一下流程,补全了图片与测试数据,并对内容做了少部分处理。



【本文地址】

公司简介

联系我们

今日新闻

    推荐新闻

    专题文章
      CopyRight 2018-2019 实验室设备网 版权所有