如何监控 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 gaugeroot_logger_ring_buffer_remaining_capacity 262144.0# HELP org_mybatis_logger_ring_buffer_remaining_capacity # TYPE org_mybatis_logger_ring_buffer_remaining_capacity gaugeorg_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 gaugecom_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 gaugeRocketmqClient_logger_ring_buffer_remaining_capacity 262144.0
这样,当这个值为 0 继续一段时间后(就代表 RingBuffer 满了,日志生成速度曾经远大于生产写入 Appender 的速度了),咱们就认为这个利用日志负载过高了。