logback的实验和高级拓展

作者: ChinaXieShuai | 来源:发表于2019-01-12 16:01 被阅读6次

@logback实验2.0

验证：不同的logger打印的日志中的类的全限定名称不一样、不同的日志级别打印的结果不一样、日志有效级的继承关系

在java程序中，常用的获取Logger的方式为 LoggerFactory.getLogger();通过 LoggerFactory.getLogger() 可以获取到具体的 logger 实例，名字相同则返回的 logger 实例也相同。logback的官方文档中提出以下三点特性:

不同的logger打印的日志中的类的全限定名称不一样
不同的日志级别打印的结果不一样
日志有效级的继承关系

下面的代码就可以测试出以上的三种特性

import ch.qos.logback.classic.Level;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.ResponseBody;
import org.springframework.web.bind.annotation.RestController;

/**
 * Created by shuai on 2019/1/9.
 */
@RestController
public class DemoController {

    private final static Logger log = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
    private final static Logger LOGGER = LoggerFactory.getLogger(TestController.class);

    @RequestMapping(value = "/api/v1/testlog")
    @ResponseBody
    public void testLog(@RequestParam(value = "id") Long id) {
        log.warn("打印一个warn");
        log.debug("打印一个debug");
        System.out.println(log.getName());

        LOGGER.warn("警告信息");
        LOGGER.debug("调试信息");
        System.out.println(LOGGER.getName());
        System.out.println();

        // ch.qos.logback.classic.Logger 可以设置日志的级别
        // 获取一个名为 "com.springboot.utils" 的 logger 实例
        ch.qos.logback.classic.Logger logger =
                (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.springboot.utils");
        // 设置 logger 的级别为 INFO
        logger.setLevel(Level.INFO);
        // 这条日志可以打印，因为 WARN >= INFO
        logger.warn("警告信息");
        // 这条日志不会打印，因为 DEBUG < INFO
        logger.debug("调试信息");
        System.out.println(logger.getName());
        System.out.println();

        // "com.springboot.utils.test.TestSome" 会继承 "com.springboot.utils" 的有效级别
        Logger barLogger = LoggerFactory.getLogger("com.springboot.utils.test");
        // 这条日志会打印，因为 INFO >= INFO
        barLogger.info("子级信息");
        // 这条日志不会打印，因为 DEBUG < INFO
        barLogger.debug("子级调试信息");
        System.out.println(barLogger.getName());
    }
}

结果如下：

点击放大

得出文档中的结论是正确的。

@logback实验2.1-验证logger.isDebugEnabled()对性能的影响

假设我们的日志级别设置为info，debug()方法调用后会判断日志级别是否能够打印输出，然后return。但是在调用debug()方法时，必须提供入参的参数。如果代码里有需要拼装的代码，这显然很得不偿失。
考虑到 logback-classic 实现了 SLF4J 的 Logger 接口，一些打印方法可以接收多个传参。这些打印方法的变体主要是为了提高性能以及减少对代码可读性的影响。

如下代码笔者将获取的Logger日志级别设置为INFO，所以debug级别的日志不会打印。再使用3个while循环1w次，分别执行代码测试使用的时间：

LOGGER.debug("这是实验1的日志，打印一句《天行九歌》 歌词： 任侠平生愿，" + str + "。第 " + count + " 次。");

LOGGER.debug("这是实验2的日志，打印一句《天行九歌》 歌词： 任侠平生愿，{}。第 {} 次。", str, count);

if (LOGGER.isDebugEnabled()) {
    LOGGER.debug("这是实验3的日志，打印一句《天行九歌》 歌词： 任侠平生愿，" + str + "。第 " + count + " 次。");
}

验证代码如下：

import ch.qos.logback.classic.Level;
import org.slf4j.LoggerFactory;

/**
 * Created by shuai on 2019/1/10.
 */
public class DemoController {

    public static void main(String[] args) {
        DemoController.testIsDebugEnabled();
    }


    /**
     * 关于LOGGER.isDebugEnabled()的性能测试
     */
    public static void testIsDebugEnabled() {
        ch.qos.logback.classic.Logger LOGGER =
                (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(DemoController.class);
        LOGGER.setLevel(Level.INFO);
        int count = 0;
        String str = "一叶边舟莲波涟";
        long t1 = System.currentTimeMillis();
        System.out.println("实验1，开始时间为: " + t1 + " ms");
        while (count < 100000) {
            count++;
            LOGGER.debug("这是实验1的日志，打印一句《天行九歌》 歌词： 任侠平生愿，" + str + "。第 " + count + " 次。");
        }
        long t2 = System.currentTimeMillis();
        System.out.println("实验1，结束时间为: " + t2 + " ms");
        System.out.println("实验1，花费时间为: " + (t2 - t1) + " ms");
        System.out.println();

        count = 0;
        long t5 = System.currentTimeMillis();
        System.out.println("实验2，开始时间为: " + t5 + " ms");
        while (count < 100000) {
            count++;
            LOGGER.debug("这是实验2的日志，打印一句《天行九歌》 歌词： 任侠平生愿，{}。第 {} 次。", str, count);
        }
        long t6 = System.currentTimeMillis();
        System.out.println("实验2，结束时间为: " + t6 + " ms");
        System.out.println("实验2，花费时间为: " + (t6 - t5) + " ms");
        System.out.println();

        count = 0;
        long t3 = System.currentTimeMillis();
        System.out.println("实验3，开始时间为: " + t3 + " ms");
        while (count < 100000) {
            count++;
            if (LOGGER.isDebugEnabled()) {
                LOGGER.debug("这是实验3的日志，打印一句《天行九歌》 歌词： 任侠平生愿，" + str + "。第 " + count + " 次。");
            }
        }
        long t4 = System.currentTimeMillis();
        System.out.println("实验3，结束时间为: " + t4 + " ms");
        System.out.println("实验3，花费时间为: " + (t4 - t3) + " ms");

    }

}

实验结果为:

点击查看大图

得出官方文档中的结论是正确的。官方文档的结论，原文翻译如下：
对于一些 Logger 如下输出日志：

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

会产生构建消息参数的成本，是因为需要将整数转为字符串，然后再将字符串拼接起来。但是我们是不需要关心 debug 信息是否被记录（强行曲解作者的意思）。

为了避免构建参数带来的损耗，可以在日志记录之前做一个判断，如下：

if(logger.isDebugEnabled()) { 
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

在这种情况下，如果 logger没有开启 debug 模式，不会有构建参数带来的性能损耗。换句话说，如果 logger 在 debug 级别，将会有两次性能的损耗，一次是判断是否启用了 debug 模式，一次是打印 debug 日志。在实际应用当中，这种性能上的损耗是可以忽略不计的，因为它所花费的时间小于打印一条日志的时间的 1%。

更好的选择

有一种更好的方式去格式化日志信息。假设 entry 是一个 Object 对象：

Object entry = new SomeObject();
logger.debug("The entry is {}", entry);

只有在需要打印 debug 信息的时候，才会去格式化日志信息，将 '{}' 替换成 entry 的字符串形式。也就是说在这种情况下，如果禁止了日志的打印，也不会有构建参数上的性能消耗。

下面两行输出的结果是一样的，但是一旦禁止日志打印，第二个变量的性能至少比第一个变量好上 30 倍。

logger.debug("The new entry is " + entry + ".");
logger.debug("The new entry is {}", entry);

使用两个参数的例子如下：

logger.debug("The new entry is {}, It replaces {}.", entry, oldEntry);

如果需要使用三个或三个以上的参数，可以采用如下的形式：

Object[] paramArray = {newVal, below, above};
logger.debug("Value {} was inserted between {} and {}.", paramArray);

@logback实验3.0-验证修改logback配置文件后，自动加载并生效

以下代码有两个入口，分别是：

POST：/log/test/change 修改logback的配置文件
GET：/log/test/out 查看logback的配置文件内容

先设置一个每2秒执行一次的定时器，打印INFO级别和WARN级别的日志，日志级别设置为INFO。再通过POST接口/log/test/change将日志级别改为WARN，看看修改后打印日志的变化。修改日志级别只需要将logback配置文件中的<root level="INFO">这一行改为<root level="WARN">即可。下面的对应的代码和配置文件：

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
import ch.qos.logback.core.status.Status;
import com.alibaba.fastjson.JSONArray;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RestController;

import java.io.BufferedInputStream;
import java.io.ByteArrayOutputStream;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.net.URL;
import java.net.URLConnection;
import java.util.ArrayList;
import java.util.List;

/**
 * Created by shuai on 2019/1/10.
 */
@RestController
public class TestController {
    private final static Logger LOGGER = LoggerFactory.getLogger(TestController.class);
    private final static String XML_FILE_TYPE = ".xml";

    @RequestMapping(value = "/log/test/status", method = RequestMethod.GET)
    public String d() throws IOException {
        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        List<Status> list = context.getStatusManager().getCopyOfStatusList();
        List<String> r = new ArrayList<String>();
        for (Status s : list) {
            r.add(s.getMessage());
        }
        return JSONArray.toJSONString(r);
    }

    private static int count = 0;

    /**
     * 每2秒打印一次 WARN 和 INFO 级别的日志
     */
    @Scheduled(cron = "0/2 * * * * *")
    public void execute() {
        LOGGER.warn("WARN级别,第{}次，当前时间为 {}", count++, System.currentTimeMillis());
        LOGGER.info("INFO级别,第{}次，当前时间为 {}", count++, System.currentTimeMillis());
    }

    /**
     * 修改当前logback的配置文件内容
     * @param body 配置文件
     * @return
     * @throws IOException
     */
    @RequestMapping(value = "/log/test/change", method = RequestMethod.POST)
    public String change(@RequestBody String body) throws IOException {
        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        if (context == null) {
            LOGGER.info("Empty LoggerContext context");
            return "Empty LoggerContext context";
        }
        ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(context);
        if (configurationWatchList == null) {
            LOGGER.info("Empty ConfigurationWatchList in context");
            return "Empty ConfigurationWatchList in context";
        }
        URL mainConfigurationURL = configurationWatchList.getMainURL();
        if (mainConfigurationURL == null) {
            LOGGER.info("Empty URL mainConfigurationURL");
            return "Empty URL mainConfigurationURL";
        }
        if (!mainConfigurationURL.toString().endsWith(XML_FILE_TYPE)) {
            LOGGER.info("mainConfigurationURL.toString() Method Result Is Not EndWith .XML");
            return "mainConfigurationURL.toString() Method Result Is Not EndWith .XML";
        }
        //写入logback配置文件
        FileOutputStream outputStream = new FileOutputStream(mainConfigurationURL.getFile());
        outputStream.write(body.getBytes());
        outputStream.close();
        //读取logback配置文件
        URLConnection urlConnection = mainConfigurationURL.openConnection();
        InputStream inputStream = urlConnection.getInputStream();
        BufferedInputStream bis = new BufferedInputStream(inputStream);
        ByteArrayOutputStream buf = new ByteArrayOutputStream();
        int result = bis.read();
        while (result != -1) {
            buf.write((byte) result);
            result = bis.read();
        }
        inputStream.close();
        bis.close();
        buf.close();
        return buf.toString();
    }


    /**
     * 查看当前的logback的配置文件内容
     * @return
     * @throws IOException
     */
    @RequestMapping(value = "/log/test/out", method = RequestMethod.GET)
    public String out() throws IOException {
        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        if (context == null) {
            LOGGER.info("Empty LoggerContext context");
            return "Empty LoggerContext context";
        }
        ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(context);
        if (configurationWatchList == null) {
            LOGGER.info("Empty ConfigurationWatchList in context");
            return "Empty ConfigurationWatchList in context";
        }
        URL mainConfigurationURL = configurationWatchList.getMainURL();
        if (mainConfigurationURL == null) {
            LOGGER.info("Empty URL mainConfigurationURL");
            return "Empty URL mainConfigurationURL";
        }
        if (!mainConfigurationURL.toString().endsWith(XML_FILE_TYPE)) {
            LOGGER.info("mainConfigurationURL.toString() Method Result Is Not EndWith .XML");
            return "mainConfigurationURL.toString() Method Result Is Not EndWith .XML";
        }
        //读取logback配置文件
        URLConnection urlConnection = mainConfigurationURL.openConnection();
        InputStream inputStream = urlConnection.getInputStream();
        BufferedInputStream bis = new BufferedInputStream(inputStream);
        ByteArrayOutputStream buf = new ByteArrayOutputStream();
        int result = bis.read();
        while (result != -1) {
            buf.write((byte) result);
            result = bis.read();
        }
        String str = buf.toString();
        inputStream.close();
        bis.close();
        buf.close();
        return str;
    }

}

当前的logback.xml文件内容为:

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="4 seconds">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

日志结果为：

点击查看大图
可以看到图片下方的日志只是打印了WARN级别的日志，INFO级别的日志不再打印，得出结论 配置已经生效。

@logback实验3.1-对部分日志通过配置输出到指定的位置

在业务上我们有时候需要对某些日志进行特定的分析，比如说某个类里面的日志我需要指定输入到foo.log文件中，后期会用来做分析。logback的官方文档中就提供了这样的功能，官方文档翻译如下：

root logger 通过 <root> 元素来进行配置。它只支持一个属性——level。它不允许设置其它任何的属性，因为 additivity 并不适用 root logger。而且，root logger 的名字已经被命名为 "ROOT"，也就是说也不支持 name 属性。level 属性的值可以为：TRACE、DEBUG、INFO、WARN、ERROR、ALL、OFF，但是不能设置为 INHERITED 或 NULL。
跟 <logger> 元素类似，<root> 元素可以包含 0 或多个 <appender-ref> 元素。

还是以上面的每2秒执行一次的定时任务打印的日志作为例子，我们在配置文件中配置：将com.springboot.controller.TestController的日志打印到foo.log文件中，其余配置不变。修改后的配置文件如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="4 seconds">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>foo.log</file>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
            <outputPatternAsHeader>true</outputPatternAsHeader>
        </encoder>
    </appender>

    <logger name="com.springboot.controller.TestController" level="INFO" >
        <appender-ref ref="FILE"/>
    </logger>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

启动程序后，定时任务会自动在控制台打印日志，并且根据配置，会往文件foo.log中打印日志。
结果如下：

点击查看大图

@logback实验4.0-验证重写Appender，监控ERROR级别的错误日志

验证：通过继承 AppenderBase 可以编写你自己的 appender。它支持处理过滤器，状态信息，以及其它大多数 appender 共享的功能。子类仅仅只需要实现 append(Object eventObject) 方法。

第四章中讲到了很多种 logback 提供的 appender，比较实用的有 DBAppender 和 SMTPAppender。分别将 logger 日志插入数据库和发送邮件，但是DBappender需要自己建立数据源连接池，而 SMTPAppender 仅仅只在它的循环缓存区中保留最后 256 个日志事件，当缓存区快要满的时候丢掉旧的日志事件，都存在一定的局限性。
一个业务处理比较频繁的系统中，每天会产生成千上万的日志数据，其中需要开发人员特别注意是一般是ERROR级别的日志，当出现ERROR级别的日志，大多数情况下需要开发人员去介入查看系统当时的业务异常情况。开发者即不希望漏掉错误日志，也不希望错误日志时效性太差。比较常用的做法是将所有的服务日志打印全部收集起来，并解析日志的内容，将ERROR级别的日志解析出来，并发送邮件通知开发者。但是收集、解析、存储、邮件报警等一系列的操作在日志量很大的情况下，处理起来比较麻烦（当然也是有解决方案的）。有没有一种即能够稳定、实时的接收到系统的ERROR日志又不影响性能的方案呢？此处就可以用到重写Appender这个方案。
重写的Appender可以实现只收集ERROR级别的日志，并且发送邮件提醒开发者。
方案：当日志级别为ERROR时，重写的Appender 发送http请求将error日志发送到日志收集服务，并存储到数据库中，日志收集服务再通过定时任务每隔一段时间(根据业务实际情况配置时间)发送收集到的error日志给对应服务的开发者，这样既能减轻client端的压力，日志的稳定性和时效性也会大大增加。

配置和代码如下：

    <appender name="ERRORLOG" class="com.springboot.log.ErrorLogMonitorHttpAppender">
        <url>http://localhost:8080/api/v1/addlog</url>
        <env>test</env>
        <localSystemName>someOneProjectName</localSystemName>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
        <encoder charset="UTF-8">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
        </encoder>
    </appender>

import ch.qos.logback.core.AppenderBase;
import ch.qos.logback.core.encoder.Encoder;
import com.springboot.http.HttpClientUtil;
import com.springboot.utils.IpUtils;
import com.springboot.vo.LogVO;

import java.io.ByteArrayOutputStream;
import java.util.concurrent.LinkedBlockingQueue;

/**
 * Created by shuai on 2019/1/3.
 */
public class ErrorLogMonitorHttpAppender<E> extends AppenderBase<E> {

    private String url;
    private String localSystemName;
    private String env;
    private LinkedBlockingQueue<E> queue = new LinkedBlockingQueue<E>(512);
    protected Encoder<E> encoder;
    private ByteArrayOutputStream byteArrayOutputStream;
    private HttpClientUtil httpClientUtil;

    public LinkedBlockingQueue<E> getQueue() {
        return queue;
    }

    public void setQueue(LinkedBlockingQueue<E> queue) {
        this.queue = queue;
    }

    public Encoder<E> getEncoder() {
        return encoder;
    }

    public void setEncoder(Encoder<E> encoder) {
        this.encoder = encoder;
    }

    public String getUrl() {
        return url;
    }

    public void setUrl(String url) {
        this.url = url;
    }

    public String getLocalSystemName() {
        return localSystemName;
    }

    public void setLocalSystemName(String localSystemName) {
        this.localSystemName = localSystemName;
    }

    public String getEnv() {
        return env;
    }

    public void setEnv(String env) {
        this.env = env;
    }

    public void start() {
        if (isStarted()) {
            addError(" Has been launched。 Don't create again！");
            return;
        }
        started = true;
        httpClientUtil = HttpClientUtil.getHttpClientUtil();
        new Thread(
                new Runnable() {
                    @Override
                    public void run() {
                        send();
                    }
                }
        ).start();
    }

    protected void send() {
        while (true) {
            try {
                E event = queue.take();
                byteArrayOutputStream = new ByteArrayOutputStream();
                this.encoder.init(byteArrayOutputStream);
                this.encoder.doEncode(event);
                byte[] byteArray = byteArrayOutputStream.toByteArray();
                LogVO logVO = new LogVO();
                logVO.setEnv(env);
                logVO.setBody(new String(byteArray, "utf-8"));
                logVO.setLocalIp(IpUtils.getRealIp());
                logVO.setLocalSystemName(localSystemName);
                //发送日志给日志收集服务
                httpClientUtil.doPostVO(url, null, logVO, "utf-8", 5000, 5000);
            } catch (Throwable t) {
                addError("send errorLog Exception:", t);
            }
        }
    }


    @Override
    protected void append(E eventObject) {
        if (eventObject != null) {
            try {
                queue.offer(eventObject);
            } catch (Throwable t) {
                addError("offer LinkedBlockingQueue error:", t);
            }
        }
    }
}

@logback实验4.1-验证logback中异步打印AsyncAppender的includeCallerData配置对性能的影响

如下是 AsyncAppender 的一些属性：

属性名	类型	描述
queueSize	`int`	队列的最大容量，默认为 256
discardingThreshold	`int`	默认，当队列还剩余 20% 的容量时，会丢弃级别为 TRACE, DEBUG 与 INFO 的日志，仅仅只保留 WARN 与 ERROR 级别的日志。想要保留所有的事件，可以设置为 0
includeCallerData	`boolean`	获取调用者的数据相对来说比较昂贵。为了提高性能，默认情况下不会获取调用者的信息。默认情况下，只有像线程名或者 MDC 这种"便宜"的数据会被复制。设置为 true 时，appender 会包含调用者的信息
maxFlushTime	`int`	根据所引用 appender 队列的深度以及延迟， `AsyncAppender` 可能会耗费长时间去刷新队列。当 `LoggerContext` 被停止时， `AsyncAppender stop` 方法会等待工作线程指定的时间来完成。使用 maxFlushTime 来指定最大的刷新时间，单位为毫秒。在指定时间内没有被处理完的事件将会被丢弃。这个属性的值的含义与 Thread.join(long) 相同
neverBlock	`boolean`	默认为 false，在队列满的时候 appender 会阻塞而不是丢弃信息。设置为 true，appender 不会阻塞你的应用而会将消息丢弃

上述为logback的官方文档的翻译，文中对includeCallerData属性官方建议不要开启，会对性能有影响。下面我们就来做个试验，验证此配置对应性能效率的影
响。

试验内容：

设定两个同样配置的异步打印的AsyncAppender，其中一个将includeCallerData属性设置为true

对两个AsyncAppender分别打印相同的一行日志，分别记录打印10w条日志和100w条日志花费的时间

试验环境

JDK : 1.8
电脑配置：

电脑配置

logback.xml文件配置如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="4 seconds">

    <!--包含调用者信息的日志-->
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>/Users/shuai/Desktop/myIncludeCallerData.log</file>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
        </encoder>
    </appender>
    <appender name="CONSOLE_ASYNC_FILE_TRUE" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>3000</discardingThreshold>
        <queueSize>10000</queueSize>
        <!--获取调用者的信息配置-->
        <includeCallerData>true</includeCallerData>
        <appender-ref ref="FILE"/>
    </appender>
    <!--引用CONSOLE_ASYNC_FILE_TRUE，并命名为includeCallerData，在程序中获取-->
    <logger name="includeCallerData" level="info">
        <appender-ref ref="CONSOLE_ASYNC_FILE_TRUE"/>
    </logger>

    <!--不包含调用者信息的日志-->
    <appender name="FILE_NO" class="ch.qos.logback.core.FileAppender">
        <file>/Users/shuai/Desktop/my.log</file>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} | %X{tracker_id} | %X{localIp} |[%t]:[%p]|[%c:%L] - %m %n</pattern>
        </encoder>
    </appender>
    <appender name="CONSOLE_ASYNC_FILE_FALSE" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>3000</discardingThreshold>
        <queueSize>10000</queueSize>
        <appender-ref ref="FILE_NO"/>
    </appender>
    <!--引用CONSOLE_ASYNC_FILE_FALSE，并命名为notIncludeCallerData，在程序中获取-->
    <logger name="notIncludeCallerData" level="info">
        <appender-ref ref="CONSOLE_ASYNC_FILE_FALSE"/>
    </logger>


    <root level="INFO">
    </root>
</configuration>

实验类如下：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

/**
 * Created by shuai on 2019/1/22.
 */
@RestController
public class TestPerformanceController {

    @RequestMapping(value = "/api/test/per/data")
    public void tr(@RequestParam(value = "t") int t) {
        t = t == 0 ? 10000 : t;
        notIncludeCallerData(t);
        includeCallerData(t);
    }

    public void notIncludeCallerData(int t) {
        Logger LOGGER = LoggerFactory.getLogger("notIncludeCallerData");
        long t1 = System.currentTimeMillis();
        int count = 0;
        while (count < t) {
            LOGGER.info("没有调用者信息的日志，打印当前的count[{}],打印一行日志,时间[{}]", count, System.currentTimeMillis());
            ++count;
        }
        LOGGER.info("没有调用者信息的日志，当前打印完成,花费时间为[{}]", System.currentTimeMillis() - t1);
        System.out.println("没有调用者信息的日志，当前打印完成,花费时间为[ "+ (System.currentTimeMillis() - t1) +" ms]");
    }

    public void includeCallerData(int t) {
        Logger LOGGER = LoggerFactory.getLogger("includeCallerData");
        long t1 = System.currentTimeMillis();
        int count = 0;
        while (count < t) {
            LOGGER.info("有调用者信息的日志，打印当前的count[{}],打印一行日志,时间[{}]", count, System.currentTimeMillis());
            ++count;
        }
        LOGGER.info("有调用者信息的日志，当前打印完成,花费时间为[{}]", System.currentTimeMillis() - t1);
        System.out.println("有调用者信息的日志，当前打印完成,花费时间为[ "+ (System.currentTimeMillis() - t1) +" ms]");
    }
}

看看10w条日志的结果：

点击查看答题

有调用方信息的logger打印10w条日志，花费的时间为： 9109 ms
无调用方信息的logger打印10w条日志，花费的时间为： 50 ms

再看看100w条日志的结果：

点击查看大图

有调用方信息的logger打印100w条日志，花费的时间为： 89509 ms
无调用方信息的logger打印100w条日志，花费的时间为： 316 ms

再看看1000w条日志的结果：

千万日志数据
有调用方信息的logger打印100w条日志，花费的时间为： 861911 ms
无调用方信息的logger打印100w条日志，花费的时间为： 2376 ms

以上得出，异步打印的Appender:ch.qos.logback.classic.AsyncAppender中的配置了<includeCallerData>true</includeCallerData>会花费更多的时间，日志打印的效率差360多倍。一个千万用户级别互联网产品，每五分钟请求量最高如果在15w最低在1w，平均每次请求会产生10条日志，那server端日志一天约有4亿条日志数据，即便分成10个实例，每个实例也会有4千万条日志。所以线上日志输出，最好不要开启此配置，官方文档中的建议可以采纳。

logback的实验和高级拓展

@logback实验2.0

结果如下：

@logback实验2.1-验证logger.isDebugEnabled()对性能的影响

更好的选择

@logback实验3.0-验证修改logback配置文件后，自动加载并生效

@logback实验3.1-对部分日志通过配置输出到指定的位置

@logback实验4.0-验证重写Appender，监控ERROR级别的错误日志

@logback实验4.1-验证logback中异步打印AsyncAppender的includeCallerData配置对性能的影响

试验内容：

试验环境

看看10w条日志的结果：

再看看100w条日志的结果：

再看看1000w条日志的结果：

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

logback