SpringCloud升級之路2020.0.x版-11.Log4j2 監控相關

語言: CN / TW / HK

本系列程式碼地址:https://github.com/HashZhang/spring-cloud-scaffold/tree/master/spring-cloud-iiford

Log4j2 非同步日誌核心通過 RingBuffer 實現,如果某一時刻產生大量日誌並且寫的速度不及時導致 RingBuffer 滿了,業務程式碼中呼叫日誌記錄的地方就會阻塞。所以我們需要對 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;
    }
}

我們的微服務專案中使用了 spring boot,並且集成了 prometheus。我們可以通過將 Log4j2 RingBuffer 大小作為指標暴露到 prometheus 中,通過如下程式碼:

對應原始碼:Log4j2Configuration.java

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 的速度了),我們就認為這個應用日誌負載過高了。

其實可以通過 JMX 直接檢視動態修改 Log4j2 的各種配置,Log4j2 中暴露了很多 JMX Bean,例如通過 JConsole 可以檢視並修改:

但是,JMX 裡面包含的資訊太多,並且我們的伺服器在世界各地,遠端 JMX 很不穩定,所以我們還是通過 actuator 暴露 http 介面進行操作。

首先,要先配置 actuator 要通過 HTTP 暴露出日誌 API,我們這裡的配置是:

management:
  endpoints:
    # 不通過 JMX 暴露任何 actuator 介面
    jmx:
      exposure:
        exclude: '*'
    # 通過 JMX 暴露所有 actuator 介面
    web:
      exposure:
        include: '*'

請求介面 GET /actuator/loggers,可以看到如下的返回,可以知道當前日誌框架支援哪些級別的日誌配置,以及每個 Logger 的級別配置。

{
	"levels": [
		"OFF",
		"FATAL",
		"ERROR",
		"WARN",
		"INFO",
		"DEBUG",
		"TRACE"
	],
	"loggers": {
		"ROOT": {
			"configuredLevel": "WARN",
			"effectiveLevel": "WARN"
		},
		"org.mybatis": {
			"configuredLevel": "ERROR",
			"effectiveLevel": "ERROR"
		}
	},
	"groups": {
	}
}

如果我們想增加或者修改某一 Logger 的配置,可以通過 POST /actuator/loggers/自定義logger名稱,Body 為:

{
	"configuredLevel": "WARN"
}

我們這一節詳細分析了我們微服務框架中日誌相關的各種配置,包括基礎配置,鏈路追蹤實現與配置以及如果沒有鏈路追蹤資訊時候的解決辦法,並且針對一些影響效能的核心配置做了詳細說明。然後針對日誌的 RingBuffer 監控做了個性化定製,並且說明了通過 actuator 檢視並動態修改日誌配置。下一節我們將會開始分析基於 spring-mvc 同步微服務使用的 web 容器 - Undertow。

微信搜尋“我的程式設計喵”關注公眾號,每日一刷,輕鬆提升技術,斬獲各種offer

「其他文章」