菜鸟笔记
提升您的技术认知

日志级别_Java 日志实践:简明配置、日志抽样和级别动态修改

广告平台的业务逻辑比较复杂,一次竞价请求,可能有几千个候选广告,最终的胜出者就那么几个。其他那些广告为什么没有曝光的机会呢?

经常被运营问这样的问题,而运营同学又往往是因为广告主问他们。如果没有一份详细的日志,就没有办法回答。

但是,上千的候选广告被淘汰,如果每一个广告被淘汰的原因都写入日志,不说磁盘空间爆炸,还影响程序的整体性能

另外,测试环境一般会输出 DEBUG 级别的日志,在生产环境肯定不能输出 DEBUG 级别,这也涉及到日志级别和环境的关系

有时候线上有问题,想要查一下 DEBUG 日志,因为当前日志级别高于 DEBUG 没法查,那要专门部署一个版本吗?

这里分享下我在日志实践中采用的方法

JAVA

日志配置

很多同学不注意日志的配置,自己的业务在输出日志,引入的二方库,三方库也在输出日志,导致日志文件里一大堆垃圾信息

一般来说,我们希望自己的业务输出 INFO 级别的日志,其他库的日志到 ERROR 级别就行了。

我的实践是将日志级别整体设置到 ERROR,再将自身业务的日志级别设为 INFO,实例如下

<logger name="com.refusea.xxx">  <level value="INFO" />logger><logger name="com.someone.xxx">  <level value="WARN" />logger><root level="ERROR">  <appender-ref ref="INFO_FILE" />  <appender-ref ref="ERROR_FILE" />root>

用 MDC 跟踪业务日志

slf4j 是事实上的日志标准,其支持 MDC,其实本质就是利用 ThreadLocal 来保存你的业务 id,在每一次日志打印时都自动输出,这样可以通过业务 id 将多个日志串起来,方便日志查看

日志配置如下

"INFO_FILE"   <encoder>    <pattern>%nopex%date %level [%logger] %mdc{sid:--} - %msg%npattern>    <charset>UTF-8charset>  encoder></appender>

注意日志格式配置里的 %mdc{sid:--},这里用 %mdc 来映射你存储在 MDC 里的变量,后面的 :-- 是当 MDC 里没有对应变量时输出的默认值(-)

代码里 MDC 里存放数据如下

MDC.put("sid", sessionId);

你只需要在接收到请求的第一时间将 sessionId 存储到 MDC,后续业务日志里就自动打印出这个 sessionId 了,当然,因为是基于 ThreadLocal 的,如果你的业务在某个环节需要使用多线程,使用了多线程的那部分处理逻辑的 MDC 里是没有这个 sid 的

这种因为多线程导致 MDC 失效的问题,目前没有很好的解决方法,有的文章表示可以自定义线程池,我的做法是在多线程的第一行代码里手动将 sid 存入 MDC

在业务处理结束时,应该清除 MDC,代码如下

MDC.remove("sid");

根据环境自动设置日志级别

默认情况下,我们的日志级别设为 INFO,直接上生产环境没有问题。但是在开发和测试环境,想要用 DEBUG 级别,该怎么做呢?

我有个同事的解决办法是预先写了多个日志配置文件,分别设定不同的级别,在程序启动时,根据当前配置中心的配置加载不同的配置文件

我的做法是程序启动时修改日志级别,比如我的业务代码都在 com.refusea.xxx 包下,那么启动时如果是开发测试环境,我会修改日志级别到 DEBUG,代码示意如下

@Componentpublic class EnvHelper {
        // 是否生产环境    private final boolean       online;    public EnvHelper() {
            // 基于注册中心提供的工具类, 判断当前环境        String env = Env.getEnvironmental();        online = env != null && env.startsWith("online");        // 非生产环境, 修改日志级别到 DEBUG        if (!online) {
              ch.qos.logback.classic.Logger rootLogger = (ch.qos.logback.classic.Logger) LoggerFactory              .getLogger("com.refusea.xxx");          rootLogger.setLevel(Level.DEBUG);        }    }    /** 是否生产环境 */    public boolean isOnline() {
            return online;    }}

这里比较关键的就是在程序启动时判断出当前的环境,我司的配置中心提供了工具类来判断,如果采用开源的配置中心方案,应该也都有类似的功能

如果没有用配置中心或者配置中心不支持获取环境信息怎么办呢?我觉得只能用笨方法了,比如在配置文件里列出开发/测试环境的 ip 地址,启动时根据自身 ip 来判断;或者在启动时通过给 jvm 传递参数的方式

日志抽样和动态级别

业务日志太多,全部打印出来系统性能顶不住,磁盘空间也顶不住,所以通常都是以 DEBUG 级别输出日志,生产环境用 INFO 级别,但是生产环境完全不输出日志,遇到问题就干瞪眼。

我的解决办法是抽样,比如说每 10000 次请求,打印一次完整的日志,这就要求我的日志输出语句不能直接用 log.debug 的形式

首先,我会有个 Session 类,该类会全程跟随我的业务逻辑,作为参数传给几乎所有方法,在这个类的构造方法里抽样决定本次日志是否打印,代码示意

public static interface Trackable {
        boolean isTracking();}
public class Session implements Trackable {
        private static final int cycle  = 1000;    private static final AtomicInteger counter = new AtomicInteger(0);    private final boolean tracking;    private final String id;    public Session(String id) {
            this.id = id;        // 每 10000 次跟踪一次日志        this.tracking = (counter.incrementAndGet() % 10000 == 0);                this.mdc();    }    @Override     public boolean isTracking() {
            return tracking;    }    public void mdc() {
            MDC.put("sid", id);    }    public void clearMdc() {
            MDC.remove("sid");    }}

在打印日志时,根据 session.tracking 属性来决定调用 debug 还是 info 方法,这个可以封装一个工具类,如下示意

public final class TrackUtil {
          public static final void track(Trackable trackable, Logger log, String format, Object... arg) {
            if (trackable.isTracking()) {
                log.info(format, arg);        } else if (log.isDebugEnabled()) {
                log.debug(format, arg);        }    }}

运行时修改日志级别

前面提到日志级别根据环境自动调整时,我的同事是使用了多个配置文件,在配置中心配置使用哪个配置文件。

这个方法有个缺点,就是在配置中心修改了配置文件后,影响当前环境的所有服务器,比如我们的生产环境是基于机房的,一个机房的服务器使用同一个环境配置。

而实际工作中,想要将日志级别短暂的调整为 DEBUG,只希望修改某一台服务器

我的做法是通过 http 接口来发送修改日志级别的请求,在服务器上直接使用 curl 访问即可,为了安全,该接口会判断请求是否本机发起,如果不是本机发起是不会修改日志级别的

修改方法和启动时将级别从 INFO 调为 DEBUG 是一样的,就不重复了

为了避免修改了日志级别后忘记还原,程序还会跑一个调度任务,每隔 3 分钟检查当前日志级别,如果当前日志级别为 DEBUG 且持续时间超过阈值,会自动将日志级别重设为 INFO