这是2023年的第89篇文章 ( 本文阅读时间:15分钟 ) 01 02 避免通道拥塞 2.1 减少业务输出内容 2.2 减少系统输出内容 2.3 解耦通道依赖 03 减少看得见的业务开销 3.2 确定输出才拼接(使用参数占位符) 04 躲开看不见的系统开销 4.1 避免多余的内存资源(Garbage Free) 4.2 避免多余的计算资源(避免元信息打印) 05 总结 参考链接 [02] Log4j 配置 https://logging.apache.org/log4j/2.x/manual/configuration.html [03] Logback 配置 https://logback.qos.ch/manual/configuration.html [03] EDAS 运行时日志动态调整 https://help.aliyun.com/zh/edas/user-guide/dynamic-log-configuration-2261535简单针对上图做一个说明:当程序员在业务代码中通过 logger.info的方式对日志内容进行输出后,日志的目的地是磁盘,而在最终将日志内容刷入磁盘之前,它需要经过日志框架、亿华云JVM、Linux 文件系统的层层处理。这就好比在物流运输过程中,期间有多个经停站点,在某些站点可能还需要进行换乘。运输中用到的整个交通体系(车、司机、道路等)就是我们图中的所画的“日志通道”。根据这个图,也给出了我们进行系统性优化的思路,即:避免通道拥塞、减少看得见的业务开销、躲开看不见的系统开销。
在另外一组的测试中,我们再将不同日志大小的内容写入文件,再做类似的对比,从实验结果来看我们能得出两个简单的结论:与只写入内存的吞吐量相比,二者的吞吐量随着日志内容的变大差距越来越大。同时随着输出内容的数量变多,在磁盘场景下呈现明显的下滑趋势,随着内容的增多,呈现逐渐趋平的趋势。具体结果如下图:
上图中的测试数据是我们从一个 IO 设备提供了 400MB/s 左右的速度中获得;在 IO 没有被用满的情况下,增加写入内容尚能提升整体的写入量,但是一旦达到设备的瓶颈。继续写入将造成写入的堆积。不过两组数据均能得出相同的结论,即:更大的日志文本内容,只会导致更差的处理时间。类比到生活中运输的场景,如果我们要运输的货物非常大的时候,那么就需要我们的货车具备更大空间的、更强的动力,而且运输速度也会更慢。同时过重的货物会有动力失调,轮胎爆胎等风险。为了提高运输效率和健康度,就应该尽量避免运超大型的货物。从我们的日志场景出发,过大的日志会同样会在在 CPU、内存、IO 等资源上均会对系统产生不同程度的冲击。
根据笔者自己的经验,在将异常直接进行打印输出之前,我们可以尝试将重新遍历异常堆栈,将信息重新整理之后再输出,具体实践可参考以下几点:保留栈顶的几帧:栈顶往往包含的是最为关键的信息,是案发的第一现场,他的信息完整性显得尤为重要。保留业务栈帧:在 Java 语言中,大家会遵循给业务代码一个单独包名的实践,此时我们可以利用包名进行栈帧的过滤和保留操作。抽样打印全栈信息:这里可以根据具体的业务情况而定,需要将全栈信息进行随机输出的原因是有的时候可能会追踪到一些系统级别的 BUG 或想了解他的一些机制。全栈信息的输出有助于问题的追根溯源。压缩异常不仅能带来性能上的提升,而且还能节省大量的存储空间。
使用异步日志由于异步的方式是业务代码先把日志内容放入一个缓冲区,再由专门的线程异步刷入到文件系统中,这样可以最大限度确保业务的吞吐不受底层框架的影响。但是是否所有日志都适合异步的策略这个需要根据业务场景进行区分:常规业务日志如遇到日志丢弃的场景可能对于业务影响不会太大,但是有的场景是必须做到严格数据一致,比如 RocketMQ 的 Commit Log,因为一条日志代表着一条完整的业务消息的投递情况,他必须和业务状态的返回做到严格一致,这种情况异步方式就不是一个好的选择;在 Log4j 中,他也提供了两种方式,一种是细粒度的 Appender 级别的配置,一种是全局的配置;下图展示的是三种策略对于性能吞吐的影响:
简单解读上图:首先,同步写入的性能在所有场景中都是最低的,这个和我们常规的认知是一致的;而AsyncLogger (蓝色柱状图) 的 TPS 却能随着 Worker 的增加而增加,但 AsyncAppender只能持平 。这一点和我们常规的认知有些出入,带着这个疑虑,我们下面稍微深入的探究一下。Log4j2 AsyncAppender下面是 AsyncAppender 的配置方式,框架提供了更多的参数来做更多精细化的控制,核心参数解读如下:shutdownTimeout:等待worker线程处理日志的时间,默认为0,表示无限等待;bufferSize:缓冲队列的大小,默认为1024;blocking:是否采用阻塞式,默认为true。当队列满时,会同步等待。<Async name="Async"> <AppenderRef ref="RollingRandomAccessFile"/> <shutdownTimeout>500</shutdownTimeout> <bufferSize>1024</bufferSize> <blocking>true</blocking></Async>简单解读其设计意图:框架会先提供一个系统缓冲区来缓存即将写入的内容,但是当缓冲区满时,框架还提供了两种策略进行选择,第一种是直接丢弃,第二种是进行等待,但是具体等待多长时间也依然可以配置。Log4j2 AsyncLogger与 AsyncAppender 相比,其使用上也更为简单,只需要通过设置启动参数-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector便可全局启用异步日志。同样,AsyncLogger 也会有缓冲区的大小的设置,默认是 256K 。当超出缓冲区大小时,可以使用丢弃策略。可以通过配置参数-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO 来明确指定丢弃哪一级别的日志。值得一提的是,AsyncLogger 使用了 LMAX Disruptor的高性能队列,这是为什么 AsyncLogger 相比于 AsyncAppender 在单线程吞吐和多线程并发方面具有更好的性能的关键。LMAX Disruptor为什么相比阻塞队列性能能随线程数扩展,主要有三点:首先,解决了伪共享问题;其次,无锁的队列设计,只需CAS的开销;最后,需要明确的,对比的是该日志场景下的队列性能。<dependency> <groupId>com.lmax</groupId> <artifactId>disruptor</artifactId></dependency>与 Log4j 一样,Logback 也有着类似的策略,这里我们就不再赘述它的具体使用方式,下面的表格中,我们总结了在各种策略下的优缺点,希望在大家进行选型时能有所帮助:log4j2 AsyncLoggerlog4j2 Async Appenderlogback AsyncAppender同步日志性能最优较好较好差易用易用,只需jvm参数-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector即可启用配置较为复杂,需要配置多个AsyncAppender配置较为复杂,需要配置多个AsyncAppender易用内存压力较大较大较大较小是否会丢失日志进程退出时 或 IO 跟不上进程退出时 或 IO 跟不上进程退出时 或 IO跟不上无兼容性Appender中ThreadLocal相关的pattern、filter异常Appender中ThreadLocal相关的pattern、filter异常Appender中ThreadLocal相关的pattern、filter异常无是否受磁盘满或IO受限影响丢弃时,不受影响丢弃时,不受影响丢弃时,不受影响影响配置注意点1XxFileAppender指定immediateFlush为falseXxFileAppender指定immediateFlush为falseXxFileAppender指定immediateFlush为falseXxFileAppender指定immediateFlush为true配置注意点2设置丢弃策略-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO设置丢弃策略-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO设置丢弃策略:neverBlock为true无使用滚动日志对于操作系统而言,小文件的处理相比于大文件,从系统资源角度,大文件往往意味着更多的内存占用,更多的 I/O 操作、更苛刻的磁盘空间、更多的总线带宽等等,当任意方资源出现瓶颈时,还会带来更多的 CPU 使用进而造成系统更高的 Load。而小文件除了在上述资源角度带来更好的优化空间之外,还在运维管理上提供了更多便利,如:使用更小的磁盘、尽早归档、尽早清理磁盘空间等等。在生产实践中,适当使用滚动日志,是一项极为可观的实践,下面的例子是在 log4j 中的的配置片段,配置内容为在时间上以天滚动,大小上按 100MB 滚动,最多保留 5 个文件的策略来对日志文件进行滚动:<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/app.log" filePattern="powered_by/edas-%d{ MM-dd-yyyy}-%i.log"> <PatternLayout> <Pattern>${ commonPattern}</Pattern> </PatternLayout> <Policies> <TimeBasedTriggeringPolicy /> <SizeBasedTriggeringPolicy size="100 MB"/> </Policies> <DefaultRolloverStrategy> <max>5</max> </DefaultRolloverStrategy></RollingRandomAccessFile>
上图的测试结果,能得出以下两个结论:1)在输出字符较短时,字符串拼接比占位符快,因占位符方式需要执行占位符扫描替换过程。2)但是随着输出字符越来越大,占位符反过来比字符串拼接更快,而且越长的字符串快的越多。原因是针对长字符的输出,日志框架会有针对性的优化。在 log4j2 中,它使用 ThreadLocal 缓存并复用了StringBuilder 对象,无需每次都为大的 StringBuilder 构建一个大对象。而字符串拼接则每次都创建新的StringBuilder 对象。
需要注意的是,传统的 J2EE Web 应用程序的场景中,会有热加载的诉求,由于 Garbage Free 会缓存很多大的 StringBuilder 在 ThreadLocal 中,这在程序热加载时可能会造成潜在的内存泄漏。因此当检测到是 J2EE Web 应用程序时,log4j2 会默认禁用这项技术。如需强制开启,可在启动参数中加入 -Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true。
我们的疑问是:Why?以 Log4j2 为例,在进行 Location 计算时,是通过构建一个 Throwable 的方式拿到堆栈之后,然后再反向寻找与 Logger 同名的类所在的栈帧,再进行 Location 的获取。这个过程光听听是不是就好感人?感兴趣的同学可以查阅对应的代码,如下: public StackTraceElement calcLocation(final String fqcnOfLogger) { if (fqcnOfLogger == null) { return null; } // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace(). final StackTraceElement[] stackTrace = new Throwable().getStackTrace(); boolean found = false; for (int i = 0; i < stackTrace.length; i++) { final String className = stackTrace[i].getClassName(); if (fqcnOfLogger.equals(className)) { found = true; continue; } if (found && !fqcnOfLogger.equals(className)) { return stackTrace[i]; } } return null; }