程序运行时动态调整日志级别的思路以及实现

背景

日志的重要性不言而喻,是我们排查问题,解决 BUG 的重要手段之一,但是在高并发环境下,又会存在悖论:
大量打印日志,消耗 I/O,导致 CPU 占用率高;减少日志,性能是下来了,但是排查问题的链路断掉了。

痛点:一方面需要借助日志可快速排查问题,另一方面要兼顾性能,二者能否得兼?
那么本文的动态日志调整实现就是为了能解决这个痛点所构思开发的。

功能特性

  • 低侵入,快速接入:以二方包(jar)的形式介入,只需要配置启用,对业务无感
  • 及时响应,随调随改:应对研发不小心在大流量入口链路打印了大量 INFO 日志,能及时调整日志级别
  • 阶梯配置支持:默认全局设置兜底,又可以支持局部 Logger 放/限流
  • 人性化操作:与操作界面,方便修改

技术实现

如下,我将以 log4j2 为实例作讲解,其它日志实现大同小异,参照实现即可。
如下是 log4j2 的配置文件示例:

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="info">
<Properties>
	// 全局参数信息
</Properties>

<appenders>
	// appender 详细配置
</appenders>

<loggers>
	// 配置 appender 指向
</loggers>
</configuration>

以往我们调整项目的日志时,要么是删除代码中的废日志,要么是修改上面的 xml 配置,针对某个包下或者类作日志级别限制,再重新打包部署生效。此时的效率是非常低的,不符个我们的诉求。
那么如何实现动态调整呢,首先想到的是 xml 调整日志级别后是如何生效的?xml 本身就是一些配置信息, log 的实现类读取 xml 信息动态修改日志级别,有没有可能我们在程序中直接去调用 log4j 内部的封装方法,绕过 xml 不就好了?

动态调整日志级别

源码查看:详细源码我已放在 github dynamic-logger-util,可自行查看。

顺着思路,查看 log4j 源码后,发现确实可行,如下即是调整日志方法的实现代码:

// 获取日志上下文
LoggerContext logContext = LoggerContext.getContext(false);
Configuration configuration = logContext.getConfiguration();
LoggerConfig loggerConfig = configuration.getRootLogger();
loggerConfig.setLevel(level);

// 生效
logContext.updateLoggers();

获取当前的 LoggerContext 后,再获取 configuration,当前的配置即是 xml 内的配置转换过来的,再获取 root logger, 即对应 xml 中的配置如下:

 <Root level="info">
    <AppenderRef ref="..."/>
    <AppenderRef ref="..."/>
</Root>

其中 level 即是我们需要更改的日志级别,可供选择的日志级别如下(参照 org.apache.logging.log4j.Level):

OFF, FATAL, ERROR, WARN, INFO, DEBUG, TRACE, ALL;

如上我们已经可以更改全局日志级别,那么比如我想只更改某个类内的日志级别如何实现呢?

LoggerContext logContext = LoggerContext.getContext(false);
if (logContext.hasLogger(name)) {
    // 精确匹配
    Logger logger = logContext.getLogger(name);
    logger.setLevel(newLevel);
    flag = true;
} else {
    // 正则匹配
    Collection<Logger> loggers = logContext.getLoggers();
    for (Logger logger : loggers) {
        if (Pattern.matches(name, logger.getName())) {
            logger.setLevel(newLevel);
            flag = true;
        }
   

通过获取的 logContext 获取相应的 logger 即可设置当前的类对应的日志级别,对应的程序代码如下:

// name = com.jifuwei.dynamic.logger.DynamicLoggerConfiguration
private static final org.slf4j.Logger  = LoggerFactory.getLogger(DynamicLoggerConfiguration.class);

如上,已经知道了如何动态修改日志 api,那么如何去动态触发修改呢?

配置触发

触发更新的机制很多,我们梳理如下:

如上能满足我们需求的,最最简答方便的就是配置中心,现在都是微服务,大部分都是通过中心配置去通知各个系统信息变更,配置中心都具备完善的界面和功能,可满足我们实时变更下发通知,又能灰度部署,减少出错,简直是动态配置的最佳搭档。

配置中心的选型非常多,我将以 Apollo 为例,演示如何触发日志级别变更。我将配置 Key 设计如下:

// 全局控制日志级别
key: log_level val=OFF/FATAL/ERROR/WARN/INFO/DEBUG/TRACE/ALL

// 局部控制日志级别
key: log_level_detail

val:
{
	"com.jifuwei.demo.Test1": "ERROR", // 每个 logger 都可配置自己专属的日志级别
	"com.jifuwei.demo.Test2": "OFF",
	"com.jifuwei.demo.Test3": "INFO",
}

关键实现如下:

public void init() {
    // 初始化风控监听action配置
    String level = apolloConfig.getProperty(LOGGER_LEVEL, Level.ERROR.name());
    setRootLoggerLevel(Level.valueOf(level));

    // 注册监听
    apolloConfig.addChangeListener(this);
}

public void onChange(ConfigChangeEvent changeEvent) {
    if (changeEvent.changedKeys().contains(LOGGER_LEVEL)) {
        String newValue = changeEvent.getChange(LOGGER_LEVEL).getNewValue();
        try {
            setRootLoggerLevel(Level.valueOf(newValue));
        } catch (Exception e) {
            log.error("loggerLevel onChange error", e);
        }
    }
    if (changeEvent.changedKeys().contains(LOGGER_LEVEL_DETAIL)) {
        String newValue = changeEvent.getChange(LOGGER_LEVEL_DETAIL).getNewValue();
        try {
            parseLoggerConfig(newValue);
        } catch (Exception e) {
            log.error("loggerLevel detail onChange error", e);
        }
    }
}

初始化时即从 apollo config 获取当前全局日志级别及局部日志级别,其次在注册监听器,此时只需要在 apollo 配置界面设置如上 key ,则程序会立即收到更新并重新设置相应的日志级别。

本文所有源码都放在了 github 仓库: GitHub - jifuwei/dynamic-logger-util ,可随时查看/索取/使用,有问题随时提问。

总结

通过 xml 修改日志级别去追查 api 方法,找到可用的方法后再去设计如何触发方法调用。按照这一思路,就解决了动态调整日志级别的问题。在生产发生大量异常,可对日志进行降级,不至于 I/O 升高导致 CPU 爆满,从而导致用户体验卡顿问题。


原文: 动态调整日志级别思路&实现 | 是咕咕鸡 (jifuwei.github.io)
作者: 是咕咕鸡 (jifuwei.github.io)

1 Like