高并发场景下的一些日志实践

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配置中使用普通的 和 元素。





同样以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 {
    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 {
    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.
     * 
     * 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
 

压测数据对比：