如何監控 Log4j2 異步日誌遇到寫入瓶頸

如何監控 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 的速度了），咱們就認爲這個應用日誌負載太高了。