JDK : 1.8 Log4J : 2.x
前言
如何打印出精简、便于线上排查问题的日志,是一门艺术,不在本文的篇幅中。本文主要讲一些跟性能相关的日志实践。
在高并发场景下,业务日志往往是应用性能的一大杀手。这么说大家可能没有概念,那么看一个实际的案例。可以看Promise面向零售结算页的某个核心应用A压测过程中的火焰图:
从火焰图可以看出:该应用的CPU消耗大头是Log4j日志,CPU%消耗占比超过了50%。再参考磁盘写速度,MDC分钟级平均后的数据:峰值磁盘写速度接近100Mb/秒;如果只看秒级数据,周期性的秒级峰值可以达到近500Mb/秒(注:周期性是由Log4j刷盘策略及Buffer配置引起的)
另外,JVM GC也会消耗较大比例的CPU%。GC的CPU%消耗也是因为日志输出太大,导致堆内存很快打满频繁地GC导致的。
所以之前在该应用的性能调优实践中,仅通过业务日志优化就能得到近100%的吞吐量提升。
约定俗成
Promise系统中面向用户下单的应用,是流量最大、最为核心的应用。这些应用的特点通常是CPU密集型的,那么这些应用的日志我们有一些约定俗称的要求:
1.控制日志输出量:根据经验观察,当磁盘写> 30Mb/s 时,响应时间和吞吐量有很大影响;当磁盘写>= 100Mb/s时,响应时间和吞吐量急剧下降。单机吞吐量通常为关日志时的10%~20% 。(容器规格参考:通常是8c8g50g)
2.日志文件规划:接口出入参单独输出到一个文件;业务日志分层设计,避免所有的业务日志都输出到同一个文件,加大文件锁的竞争。
3.生成日志字符串过程中禁用:String.format、JSON或XML序列化、反射。
4.使用StringBuilder生成日志字符串,适当情况下可以考虑给一个初始的capacity,避免日志生成过程中StringBuilder底层大量的扩容、数组复制。(注:非高并发应用可以忽略这条要求)
关于第4点,可以结合JDK源码分析:
StringBuilder初始化时默认的capacity是16,从AbstractStringBuilder的源码可以看到:此时StringBuilder内部存放字符的容器char[]的长度是16。我们做工程的都知道,对于业务日志来说,这点大小的数组用来塞牙都不够。所以在append过程中必然会触发多次的数组复制(在大业务日志内容输出的应用中,我们可以很容易地在火焰图中抓到这部分的CPU%消耗)。
public final class StringBuilder
extends AbstractStringBuilder
implements java.io.Serializable, CharSequence
{
/**
* Constructs a string builder with no characters in it and an
* initial capacity of 16 characters.
*/
public StringBuilder() {
super(16);
}
public AbstractStringBuilder append(String str) {
if (str == null)
return appendNull();
int len = str.length();
ensureCapacityInternal(count + len);
str.getChars(0, len, value, count);
count += len;
return this;
}
private void ensureCapacityInternal(int minimumCapacity) {
// overflow-conscious code
if (minimumCapacity - value.length > 0) {
value = Arrays.copyOf(value,
newCapacity(minimumCapacity));
}
}
abstract class AbstractStringBuilder implements Appendable, CharSequence {
/**
* The value is used for character storage.
*/
char[] value;
/**
* Creates an AbstractStringBuilder of the specified capacity.
*/
AbstractStringBuilder(int capacity) {
value = new char[capacity];
}
最终会通过native的System.arraycopy完成数组的复制,实现StringBuilder内置容器char[]的自动扩容:
public class Arrays {
public static char[] copyOf(char[] original, int newLength) {
char[] copy = new char[newLength];
System.arraycopy(original, 0, copy, 0,
Math.min(original.length, newLength));
return copy;
}
Log4J调优
PatternLayout配置
官方文档PatternLayout,明确描述了以下几种参数(%C、%F、%l、%L、%M)对性能有影响。在高并发场景下,可以考虑禁用一些参数,如%L。
%C、%M这些参数可能对线上问题排查有帮助,可以保留使用。
有几个需要注意的地方:
•PatternLayout中的%L只对同步日志有效;
•异步日志想要在日志中输出行号,必须在Log4j xml中添加属性includeLocation="true":
<Loggers>
<Root level="info" includeLocation="true">
<AppenderRef ref="RandomAccessFile"/>
</Root>
</Loggers>
•PatternLayout中的%L 影响的是常规日志中是否打印(classname:lineNumer),而异常堆栈信息中无论如何都会带上lineNumber。
异步日志实践
首先参见Log4j官网文档“Asynchronous Loggers for Low-Latency Logging”,全异步日志的性能表现是一枝独秀的(Loggers all async),远超过同步/异步混合日志(Async Appender mixed Sync Logger)、同步日志(Sync)。
解释下全异步日志(Loggers all async)、同步/异步混合日志(Async Appender mixed Sync Logger)、同步日志(Sync)这几个概念。
同步日志(Sync)
这个很容易理解,Log4j1.x就只支持同步日志,业务线程负责执行业务逻辑和日志输出(从生成到落盘),所以性能很差(Latency和Throughput都很差)。
同步/异步混合日志(Async Appender mixed Sync Logger)
在Log4j内部处理流程中,Logger和Appender是先后顺序的两个阶段,Logger负责日志的过滤、日志事件(LogEvent)的生成,Appender负责日志事件的处理(可以落盘到文件、数据库、Kafka、Redis等等,除了官方提供的Appender还可以根据自己的需求自定义Appender)。
Log4j 2.x版本开始提供AsyncLogger和AsyncAppender,让用户自由地选择配置。如果只配置了AsyncAppender,相当于Log4j处理流程中只有后半段是异步的(通过BlockingQueue实现),前半段还是同步。这种情况可以视为同步/异步混合日志场景。
全异步日志(Loggers all async)
了解了上述两个场景后,全异步日志也就容易理解了。Log4j内部处理流程中Logger和Appender两个阶段都是异步的,并且一个JVM进程内,所有的Logger文件都配置为异步,就可以认为是符合全异步日志场景。
上文已经说过,AsyncAppender是通过BlockingQueue实现异步,而AsyncLogger则是通过Disruptor实现异步。参见下图(图片来自“log4j异步日志原理及配置”)。
那么,如何使用全异步日志呢?一个可行的实践:
① JVM启动参数中增加:
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
② 当配置AsyncLoggerContextSelector作为异步日志时,确保在Log4j xml配置中使用普通的 <root> 和 <logger> 元素。
同样以Promise面向零售结算页的某个核心应用A为例,参考之前的性能压测数据:全异步日志 比 同步/异步混合日志 的吞吐量能提升10%左右(都是禁用%L的前提下)。
从一个真实案例看EventRoute的DISCARD模式
背景
Promise面向零售结算页的某个核心应用B在性能压测过程中,发现在业务日志全开启的场景下,CPU%压到50%多再也压不上去了,磁盘IO和网络IO也都没到瓶颈点。很自然怀疑性能的阻塞点是JVM Thread Block导致了CPU性能没有被充分压榨。
于是复现该场景,通过jstack抓Thread dump:
srs_service_jstack_572410_2020-09-22-21-14-23.txt
Thread Dump分析
使用PerfMa的Java线程Dump分析打开dump文件。其它非关键信息这里不做赘述,直奔关键点:锁。
1. 可以看出,同步锁集中在log4j日志写文件,等锁线程数达到38个。基本上JSF-BZ全部被BLOCKED。
2.进一步查看持有锁的线程:JSF-BZ-20900-26-T-700,锁对象:org.apache.logging.log4j.core.appender.rolling.RollingFileManager
3.查看线程JSF-BZ-20900-26-T-700的堆栈,关键步骤有四个:
1)触发锁持有的业务代码:SiteTypeAihuishouFilter.generateMsgCode()
2)异常日志尝试向AsyncLogger对应的RingBuffer里发布(publish)一个日志事件(logEvent)
3)Log4j先进行RingBufferFull检验,当发现环形队列已满(所有slot都被日志对象占用),此时异步日志会转同步日志,由当前的业务主线程(即JSF-BZ线程)同步写磁盘。
4)因为配置了Rolling File,日志在落盘前会检查是否要Rollover(同步锁)
4.随机验证等待锁的线程堆栈,可以得出结论:这些BLOCKED的线程中的业务代码都在尝试往同一个日志文件同步写(相同的package路径,决定了同一个Logger -> Appender -> log文件)。
Log4J源码分析
分析完线程堆栈信息后,我们结合Log4j源码来验证刚才的想法:
1)异常日志的发布(publish)
logEvent尝试向RingBuffer插入(tryPublish),如果因RingBuffer已满而发布失败,则会进入handleRingBufferFull代码分支。
public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
private void publish(final RingBufferLogEventTranslator translator) {
if (!loggerDisruptor.tryPublish(translator)) {
handleRingBufferFull(translator);
}
}
...
}
2)RingBuffer Full处理
先拿到当前logEvent的EventRoute,EventRoute决定了日志事件以什么方式落到哪个目的地。它本质上是一个枚举,支持3种模式:ENQUEUE、SYNCHRONOUS、DISCARD。
先只关注SYNCHRONOUS模式,Log4J的实现是使用当前业务主线程来做日志同步写。(性能瓶颈点!一旦RingBuffer满了导致异步日志转同步日志时,就是性能停滞不前的开始)
public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
switch (eventRoute) {
case ENQUEUE:
loggerDisruptor.enqueueLogMessageInfo(translator);
break;
case SYNCHRONOUS:
logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
translator.thrown);
break;
case DISCARD:
break;
default:
throw new IllegalStateException("Unknown EventRoute " + eventRoute);
}
}
/**
* Enqueues the specified log event data for logging in a background thread.
* <p>
* This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
* unnecessary objects with each event.
*
* @param fqcn fully qualified name of the caller
* @param level level at which the caller wants to log the message
* @param marker message marker
* @param message the log message
* @param thrown a {@code Throwable} or {@code null}
*/
private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
final Message message, final Throwable thrown) {
// Implementation note: this method is tuned for performance. MODIFY WITH CARE!
final RingBufferLogEventTranslator translator = getCachedTranslator();
initTranslator(translator, fqcn, level, marker, message, thrown);
initTranslatorThreadValues(translator);
publish(translator);
}
...
3) Rolling File检查
可以看到,checkRollover方法本身就是synchronized,只有一个线程准入。就是为了防止在File Rolling的临界点,当前线程判断不需要Rolling,但是同一时钟周期内被其它线程写入日志导致了Rolling这个并发问题。
public class RollingFileManager extends FileManager {
/**
* Determines if a rollover should occur.
* @param event The LogEvent.
*/
public synchronized void checkRollover(final LogEvent event) {
if (triggeringPolicy.isTriggeringEvent(event)) {
rollover();
}
}
...
}
优化方案
在上述源码分析过程中,可看出EventRoute有3中模式:ENQUEUE、SYNCHRONOUS、DISCARD。
在高并发场景下,是可以考虑DISCARD模式。当某一个AsyncLogger对应的RingBuffer满了时,日志事件直接丢弃,不再转同步写磁盘。理由也很简单,RingBuffer的slot默认数量是256*1024,已经足够大了,如果RingBuffer还是能够被打满,说明一个问题:此时磁盘写速度已经很接近上限了,异步Flush到磁盘的速度已经远跟不上日志产生的速度。这种情况下,日志的丢弃是为了更好地保护磁盘和应用。
况且,即便所有的日志都能落到磁盘,在LogBook Agent采集过程中也还是有可能会丢失。在2020年我们与LogBook团队沟通中得知:由于LogBook Agent和业务应用部署在同一个容器内,所以它为了保护业务应用也做了一些策略:
1.采集速率>1000条/s时,多余日志丢弃
2.Agent进程内存超过300MB时,reset Agent进程
3.Agent进程CPU%超过20%时,reset Agent进程
4.单条日志大小超过10KB时,截断
5....
所以,下一步需要验证高并发场景下DISCARD模式的性能。JVM启动参数中增加(参考log4j异步注意事项):
-Dlog4j2.AsyncQueueFullPolicy=Discard
压测数据对比:
场景 | CPU% | Mem% | TPM | 磁盘写速度 |
日志精简优化前 | 50% | 50% | 68000 | 152M/s |
日志精简优化后 | 54% | 69% | 79926 | 69M/s |
日志精简优化后+DISCARD | 44% | 46% | 114453 | 153M/s |