• 技术文章 >Java >Java基础

    搞懂Java日志级别，重复记录、丢日志问题

    coldplay.xixicoldplay.xixi2020-12-11 17:26:34转载8203

    java基础教程栏目介绍如何解决Java日志级别等问题

    相关免费学习推荐：java基础教程

    1 日志常见错因

    1.1 日志框架繁多

    不同类库可能使用不同日志框架，兼容是个难题

    1.2 配置复杂且容易出错

    日志配置文件通常很繁杂，很多同学习惯从其他项目或网上博客直接复制份配置文件，但却不仔细研究如何修改。常见错误发生于重复记录日志、同步日志的性能、异步记录的错误配置。

    1.3 日志记录本身就有些误区

    比如没考虑到日志内容获取的代价、胡乱使用日志级别等。

    2 SLF4J

    Logback、Log4j、Log4j2、commons-logging、JDK自带的java.util.logging等，都是Java体系的日志框架，确实非常多。而不同的类库，还可能选择使用不同的日志框架。这样一来，日志的统一管理就变得非常困难。

    虽然可用log4j-over-slf4j实现Log4j桥接到SLF4J，也可使用slf4j-log4j12实现SLF4J适配到Log4j，也把它们画到了一列，但是它不能同时使用它们，否则就会产生死循环。jcl和jul同理。

    虽然图中有4个灰色的日志实现框架，但日常业务使用最多的还是Logback和Log4j，都是同一人开发的。Logback可认为是Log4j改进版，更推荐使用，基本已是主流。

    Spring Boot的日志框架也是Logback。那为什么我们没有手动引入Logback包，就可直接使用Logback？

    spring-boot-starter模块依赖spring-boot-starter-logging模块
    spring-boot-starter-logging模块自动引入logback-classic（包含SLF4J和Logback日志框架）和SLF4J的一些适配器。其中，log4j-to-slf4j用于实现Log4j2 API到SLF4J的桥接，jul-to-slf4j则是实现java.util.logging API到SLF4J的桥接。

    3 日志重复记录

    日志重复记录不但给查看日志和统计工作带来不必要的麻烦，还会增加磁盘和日志收集系统的负担。

    logger配置继承关系导致日志重复记录

    如此配置的初衷是啥呢？
    内心是想实现自定义logger配置，让应用内的日志暂时开启DEBUG级别日志记录。其实，这无需重复挂载Appender，去掉<logger>下挂载的Appender即可：

    <logger name="org.javaedge.time.commonmistakes.logging" level="DEBUG"/>

    若自定义<logger>需把日志输出到不同Appender：
    比如

    可设置<logger>的additivity属性为false，这就不会继承<root>的Appender

    错误配置LevelFilter造成日志重复

    日志到底为何重复呢？

    ThresholdFilter源码解析

    该案例我们将 ThresholdFilter 置 WARN，因此可记录WARN和ERROR级日志。

    LevelFilter

    用于比较日志级别，然后进行相应处理。


    和ThresholdFilter不同，LevelFilter仅配置level无法真正起作用。

    由于未配置onMatch和onMismatch属性，所以该过滤器失效，导致INFO以上级别日志都记录了。

    修正

    配置LevelFilter的onMatch属性为ACCEPT，表示接收INFO级别的日志；配置onMismatch属性为DENY，表示除了INFO级别都不记录：

    如此，_info.log文件只会有INFO级日志，不会再出现日志重复。

    4 异步日志提高性能?

    知道了到底如何正确将日志输出到文件后，就该考虑如何避免日志记录成为系统性能瓶颈。这可解决，磁盘（比如机械磁盘）IO性能较差、日志量又很大的情况下，如何记录日志问题。

    定义如下的日志配置，一共有两个Appender：

    FILE是一个FileAppender，用于记录所有的日志；
    CONSOLE是一个ConsoleAppender，用于记录带有time标记的日志。

    把大量日志输出到文件中，日志文件会非常大，如果性能测试结果也混在其中的话，就很难找到那条日志。所以，这里使用EvaluatorFilter对日志按照标记进行过滤，并将过滤出的日志单独输出到控制台上。该案例中给输出测试结果的那条日志上做了time标记。

    配合使用标记和EvaluatorFilter，实现日志的按标签过滤。

    执行程序后可以看到，记录1000次日志和10000次日志的调用耗时，分别是5.1秒和39秒

    对只记录文件日志的代码，这耗时过长。

    源码解析

    FileAppender继承自OutputStreamAppender

    在追加日志时，是直接把日志写入OutputStream中，属同步记录日志

    所以日志大量写入才会旷日持久。如何才能实现大量日志写入时，不会过多影响业务逻辑执行耗时而影响吞吐量呢？

    AsyncAppender

    使用Logback的AsyncAppender

    即可实现异步日志记录。AsyncAppender类似装饰模式，在不改变类原有基本功能情况下为其增添新功能。这便可把AsyncAppender附加在其他Appender，将其变为异步。

    定义一个异步Appender ASYNCFILE，包装之前的同步文件日志记录的FileAppender， 即可实现异步记录日志到文件

    异步日志真的如此高性能？并不，因为这并没有记录下所有日志。

    AsyncAppender异步日志坑

    案例

    模拟慢日志记录场景：
    首先，自定义一个继承自ConsoleAppender的MySlowAppender，作为记录到控制台的输出器，写入日志时休眠1秒。

    源码解析

    public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
	// 是否收集调用方数据
    boolean includeCallerData = false;
    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        // 丢弃 ≤ INFO级日志
        return level.toInt() <= Level.INFO_INT;
    }
    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }}public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

	// 阻塞队列：实现异步日志的核心
    BlockingQueue<E> blockingQueue;
    // 默认队列大小
    public static final int DEFAULT_QUEUE_SIZE = 256;
    int queueSize = DEFAULT_QUEUE_SIZE;
    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    // 当队列满时：加入数据时是否直接丢弃，不会阻塞等待
    boolean neverBlock = false;

    @Override
    public void start() {
       	...
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
        if (discardingThreshold == UNDEFINED)
        //默认丢弃阈值是队列剩余量低于队列长度的20%，参见isQueueBelowDiscardingThreshold方法
            discardingThreshold = queueSize / 5;
        ...
    }

    @Override
    protected void append(E eventObject) {
        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { //判断是否可以丢数据
            return;
        }
        preprocess(eventObject);
        put(eventObject);
    }

    private boolean isQueueBelowDiscardingThreshold() {
        return (blockingQueue.remainingCapacity() < discardingThreshold);
    }

    private void put(E eventObject) {
        if (neverBlock) { //根据neverBlock决定使用不阻塞的offer还是阻塞的put方法
            blockingQueue.offer(eventObject);
        } else {
            putUninterruptibly(eventObject);
        }
    }
    //以阻塞方式添加数据到队列
    private void putUninterruptibly(E eventObject) {
        boolean interrupted = false;
        try {
            while (true) {
                try {
                    blockingQueue.put(eventObject);
                    break;
                } catch (InterruptedException e) {
                    interrupted = true;
                }
            }
        } finally {
            if (interrupted) {
                Thread.currentThread().interrupt();
            }
        }
    }}

    默认队列大小256，达到80%后开始丢弃<=INFO级日志后，即可理解日志中为什么只有两百多条INFO日志了。

    queueSize 过大

    可能导致OOM

    queueSize 较小

    默认值256就已经算很小了，且discardingThreshold设置为大于0（或为默认值），队列剩余容量少于discardingThreshold的配置就会丢弃<=INFO日志。这里的坑点有两个：

    1. 因为discardingThreshold，所以设置queueSize时容易踩坑。
      比如本案例最大日志并发1000，即便置queueSize为1000，同样会导致日志丢失
    2. discardingThreshold参数容易有歧义，它不是百分比，而是日志条数。对于总容量10000队列，若希望队列剩余容量少于1000时丢弃，需配置为1000

    neverBlock 默认false

    意味总可能会出现阻塞。

    queueSize、discardingThreshold和neverBlock三参密不可分，务必按业务需求设置：

    以上日志配置最常见两个误区

    再看日志记录本身的误区。

    使用日志占位符就无需判断日志级别?

    SLF4J的{}占位符语法，到真正记录日志时才会获取实际参数，因此解决了日志数据获取的性能问题。
    这说法对吗？

    若记录DEBUG日志，并设置只记录>=INFO级日志，程序是否也会耗时1秒？
    三种方法测试：


    前俩方式都调用slowString，所以都耗时1s。且方式二就是使用占位符记录slowString，这种方式虽允许传Object，不显式拼接String，但也只是延迟（若日志不记录那就是省去）日志参数对象.toString()和字符串拼接的耗时。

    本案例除非事先判断日志级别，否则必调用slowString。
    所以使用{}占位符不能通过延迟参数值获取，来解决日志数据获取的性能问题。

    除事先判断日志级别，还可通过lambda表达式延迟参数内容获取。但SLF4J的API还不支持lambda，因此需使用Log4j2日志API，把Lombok的@Slf4j注解替换为**@Log4j2**注解，即可提供lambda表达式参数的方法：

    这样调用debug，签名Supplier<?>，参数就会延迟到真正需要记录日志时再获取：



    所以debug4并不会调用slowString方法

    只是换成Log4j2 API，真正的日志记录还是走的Logback，这就是SLF4J适配的好处。

    总结

    以上就是搞懂Java日志级别，重复记录、丢日志问题的详细内容，更多请关注php中文网其它相关文章！

    声明：本文转载于：CSDN，如有侵犯，请联系admin@php.cn删除
    专题推荐：Java 日志级别 重复记录 丢日志
    上一篇：线程池创建的四种方法是什么 下一篇：自己动手写 PHP MVC 框架(40节精讲/巨细/新人进阶必看)

    相关文章推荐

    • 详解JavaScript中的padStart()和padEnd()方法• 利用java实现提现金额到支付宝账户的功能• java面试题——异常• 详解java调用python的用法
    1/1

    PHP中文网

    首页 首页课程 课程文章文章问答 问答博客博客词典 词典手册 手册资源 资源搜索 搜索APP下载 APP下载