如何监控 Log4j2 异步日志遇到写入瓶颈

在之前的一篇文章中 (一次鞭辟入里的 Log4j2 异步日志输入阻塞问题的定位)，咱们详细分析了一个经典的 Log4j2 异步日志阻塞问题的定位，次要起因还是 日志文件写入慢了。并且比拟深刻的剖析了 Log4j2 异步日志的原理，最初给出了一些解决方案。

新的问题 – 如何更好的应答这种状况？

之前提出的解决方案仅仅是针对之前定位的问题的优化，然而随着业务倒退，日志量必定会更多，大量的日志可能导致写入日志成为新的性能瓶颈。对于这种状况，咱们 须要监控。

首先想到的是 过程内部采集零碎指标监控：当初服务都提倡上云，并实现云原生服务。对于云服务，存储日志很可能应用 NFS（Network File System），例如 AWS 的 EFS。这种 NFS 一动都能够动静的管制 IO 最大承载，然而服务的增长是很难预估完满的，并且高并发业务流量根本都是一瞬间达到，仅通过 IO 定时采集很难评估到真正的流量尖峰（例如 IO 定时采集是 5s 一次，然而在某一秒内忽然达到很多流量，导致过程内大多线程阻塞，这之后采集 IO 看到 IO 压力貌似不大的样子）。并且，因为线程的阻塞，导致可能咱们看到的 CPU 占用貌似也不高的样子。所以，内部定时采集指标，很难真正定位到日志流量问题。

而后咱们思考过程本人监控，裸露接口给内部监控定时查看，例如 K8s 的 pod 健康检查等等。在过程的日志写入压力过大的时候，新扩容一个实例；启动实现后，在注册核心将这个日志压力大的过程的状态设置为临时下线（例如 Eureka 置为 OUT_OF_SERVICE，Nacos 置为 PAUSED），让流量转发到其余实例。待日志压力小之后，再批改状态为 UP，持续服务。

那么如何实现这种监控呢？

监控 Log4j2 异步日志的外围 – 监控 RingBuffer

依据之前咱们剖析 Log4j2 异步日志的原理，咱们晓得其外围是 RingBuffer 这个数据结构作为缓存。咱们能够监控其残余大小的变动来判断以后日志压力。那么怎么能拿到呢？

Log4j2 异步日志与 RingBuffer 的关系

Log4j2 对于每一个 AsyncLogger 配置，都会创立一个独立的 RingBuffer，例如上面的 Log4j2 配置：

<!-- 省略了除了 loggers 以外的其余配置 -->
 <loggers>
    <!--default logger -->
    <Asyncroot level="info" includeLocation="true">
        <appender-ref ref="console"/>
    </Asyncroot>
    <AsyncLogger name="RocketmqClient" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
    <AsyncLogger name="com.alibaba.druid.pool.DruidDataSourceStatLoggerImpl" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
    <AsyncLogger name="org.mybatis" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
</loggers>

这个配置蕴含 4 个 AsyncLogger，对于每个 AsyncLogger 都会创立一个 RingBuffer。Log4j2 也思考到了监控 AsyncLogger 这种状况，所以将 AsyncLogger 的监控裸露成为一个 MBean（JMX Managed Bean）。

相干源码如下：

Server.java

private static void registerLoggerConfigs(final LoggerContext ctx, final MBeanServer mbs, final Executor executor)
        throws InstanceAlreadyExistsException, MBeanRegistrationException, NotCompliantMBeanException {

    // 获取 log4j2.xml 配置中的 loggers 标签下的所有配置值
    final Map<String, LoggerConfig> map = ctx.getConfiguration().getLoggers();
    // 遍历每个 key，其实就是 logger 的 name
    for (final String name : map.keySet()) {final LoggerConfig cfg = map.get(name);
        final LoggerConfigAdmin mbean = new LoggerConfigAdmin(ctx, cfg);
        // 对于每个 logger 注册一个 LoggerConfigAdmin
        register(mbs, mbean, mbean.getObjectName());
        // 如果是异步日志配置，则注册一个 RingBufferAdmin
        if (cfg instanceof AsyncLoggerConfig) {final AsyncLoggerConfig async = (AsyncLoggerConfig) cfg;
            final RingBufferAdmin rbmbean = async.createRingBufferAdmin(ctx.getName());
            register(mbs, rbmbean, rbmbean.getObjectName());
        }
    }
}

创立的 MBean 的类源码：RingBufferAdmin.java

public class RingBufferAdmin implements RingBufferAdminMBean {
    private final RingBuffer<?> ringBuffer;
    private final ObjectName objectName;
    //... 省略其余咱们不关怀的代码
    
    public static final String DOMAIN = "org.apache.logging.log4j2";
    String PATTERN_ASYNC_LOGGER_CONFIG = DOMAIN + ":type=%s,component=Loggers,name=%s,subtype=RingBuffer";
    
    // 创立 RingBufferAdmin，名称格局合乎 Mbean 的名称格局
    public static RingBufferAdmin forAsyncLoggerConfig(final RingBuffer<?> ringBuffer, 
            final String contextName, final String configName) {final String ctxName = Server.escape(contextName);
        // 对于 RootLogger，这里 cfgName 为空字符串
        final String cfgName = Server.escape(configName);
        final String name = String.format(PATTERN_ASYNC_LOGGER_CONFIG, ctxName, cfgName);
        return new RingBufferAdmin(ringBuffer, name);
    }
    
    // 获取 RingBuffer 的大小
    @Override
    public long getBufferSize() {return ringBuffer == null ? 0 : ringBuffer.getBufferSize();
    }
    // 获取 RingBuffer 残余的大小
    @Override
    public long getRemainingCapacity() {return ringBuffer == null ? 0 : ringBuffer.remainingCapacity();
    }
    public ObjectName getObjectName() {return objectName;}
}

咱们能够通过 JConsole 查看对应的 MBean：

其中 2f0e140b 为 LoggerContext 的 name。

Spring Boot + Prometheus 监控 Log4j2 RingBuffer 大小

咱们的微服务项目中应用了 spring boot，并且集成了 prometheus。咱们能够通过将 Log4j2 RingBuffer 大小作为指标裸露到 prometheus 中，通过如下代码：

import io.micrometer.core.instrument.Gauge;
import io.micrometer.prometheus.PrometheusMeterRegistry;
import lombok.extern.log4j.Log4j2;
import org.apache.commons.lang3.StringUtils;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.jmx.RingBufferAdminMBean;
import org.springframework.beans.factory.ObjectProvider;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.actuate.autoconfigure.metrics.export.ConditionalOnEnabledMetricsExport;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.event.ContextRefreshedEvent;
import org.springframework.context.event.EventListener;

import javax.annotation.PostConstruct;
import javax.management.ObjectName;
import java.lang.management.ManagementFactory;

@Log4j2
@Configuration(proxyBeanMethods = false)
// 须要在引入了 prometheus 并且 actuator 裸露了 prometheus 端口的状况下才加载
@ConditionalOnEnabledMetricsExport("prometheus")
public class Log4j2Configuration {
    @Autowired
    private ObjectProvider<PrometheusMeterRegistry> meterRegistry;
    // 只初始化一次
    private volatile boolean isInitialized = false;

    // 须要在 ApplicationContext 刷新之后进行注册
    // 在加载 ApplicationContext 之前，日志配置就曾经初始化好了
    // 然而 prometheus 的相干 Bean 加载比较复杂，并且随着版本更迭改变比拟多，所以就间接偷懒，在整个 ApplicationContext 刷新之后再注册
    // ApplicationContext 可能 refresh 屡次，例如调用 /actuator/refresh，还有就是多 ApplicationContext 的场景
    // 这里为了简略，通过一个简略的 isInitialized 判断是否是第一次初始化，保障只初始化一次
    @EventListener(ContextRefreshedEvent.class)
    public synchronized void init() {if (!isInitialized) {
            // 通过 LogManager 获取 LoggerContext，从而获取配置
            LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false);
            org.apache.logging.log4j.core.config.Configuration configuration = loggerContext.getConfiguration();
            // 获取 LoggerContext 的名称，因为 Mbean 的名称蕴含这个
            String ctxName = loggerContext.getName();
            configuration.getLoggers().keySet().forEach(k -> {
                try {
                    // 针对 RootLogger，它的 cfgName 是空字符串，为了显示难看，咱们在 prometheus 中将它命名为 root
                    String cfgName = StringUtils.isBlank(k) ? "" : k;
                    String gaugeName = StringUtils.isBlank(k) ? "root" : k;
                    Gauge.builder(gaugeName + "_logger_ring_buffer_remaining_capacity", () ->
                    {
                        try {return (Number) ManagementFactory.getPlatformMBeanServer()
                                    .getAttribute(new ObjectName(
                                            // 依照 Log4j2 源码中的命名形式组装名称
                                            String.format(RingBufferAdminMBean.PATTERN_ASYNC_LOGGER_CONFIG, ctxName, cfgName)
                                            // 获取残余大小，留神这个是严格辨别大小写的
                                    ), "RemainingCapacity");
                        } catch (Exception e) {log.error("get {} ring buffer remaining size error", k, e);
                        }
                        return -1;
                    }).register(meterRegistry.getIfAvailable());
                } catch (Exception e) {log.error("Log4j2Configuration-init error: {}", e.getMessage(), e);
                }
            });
            isInitialized = true;
        }
    }
}

减少这个代码之后，申请 /actuator/prometheus 之后，能够看到对应的返回：

// 省略其余的
# HELP root_logger_ring_buffer_remaining_capacity  
# TYPE root_logger_ring_buffer_remaining_capacity gauge
root_logger_ring_buffer_remaining_capacity 262144.0
# HELP org_mybatis_logger_ring_buffer_remaining_capacity  
# TYPE org_mybatis_logger_ring_buffer_remaining_capacity gauge
org_mybatis_logger_ring_buffer_remaining_capacity 262144.0
# HELP com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity  
# TYPE com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity gauge
com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity 262144.0
# HELP RocketmqClient_logger_ring_buffer_remaining_capacity  
# TYPE RocketmqClient_logger_ring_buffer_remaining_capacity gauge
RocketmqClient_logger_ring_buffer_remaining_capacity 262144.0

这样，当这个值为 0 继续一段时间后（就代表 RingBuffer 满了，日志生成速度曾经远大于生产写入 Appender 的速度了），咱们就认为这个利用日志负载过高了。