不同类库可能使用不同日志框架,兼容难!
由于配置文件烦杂!很多同学喜欢从其他项目或网上直接闭眼复制一份。
因为不会直接导致代码 bug,测试人员也难及时发现问题,开发就没仔细考虑日志内容获取的性能开销、随意选用日志级别。
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的桥接。
知道了到底如何正确将日志输出到文件后,就该考虑如何避免日志记录成为系统性能瓶颈。这可解决,磁盘(比如机械磁盘)IO性能较差、日志量又很大的情况下,如何记录日志问题。
定义如下的日志配置,一共有两个Appender:
FILE是一个FileAppender,用于记录所有的日志; CONSOLE是一个ConsoleAppender,用于记录带有time标记的日志。
把大量日志输出到文件中,日志文件会非常大,如果性能测试结果也混在其中的话,就很难找到那条日志。所以,这里使用EvaluatorFilter对日志按照标记进行过滤,并将过滤出的日志单独输出到控制台上。该案例中给输出测试结果的那条日志上做了time标记。
配合使用标记和EvaluatorFilter,实现日志的按标签过滤。
执行程序后可以看到,记录1000次日志和10000次日志的调用耗时,分别是5.1秒和39秒
对只记录文件日志的代码,这耗时过长。
FileAppender继承自OutputStreamAppender
在追加日志时,是直接把日志写入OutputStream中,属同步记录日志
所以日志大量写入才会旷日持久。如何才能实现大量日志写入时,不会过多影响业务逻辑执行耗时而影响吞吐量呢?
使用Logback的AsyncAppender
即可实现异步日志记录。AsyncAppender类似装饰模式,在不改变类原有基本功能情况下为其增添新功能。这便可把AsyncAppender附加在其他Appender,将其变为异步。
定义一个异步Appender ASYNCFILE,包装之前的同步文件日志记录的FileAppender, 即可实现异步记录日志到文件
异步日志真的如此高性能?并不,因为这并没有记录下所有日志。
模拟慢日志记录场景: 首先,自定义一个继承自ConsoleAppender的MySlowAppender,作为记录到控制台的输出器,写入日志时休眠1秒。
队列剩余容量 < 队列长度的20%
,就会丢弃TRACE、DEBUG和INFO级日志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日志了。
可能导致OOM
默认值256就已经算很小了,且discardingThreshold设置为大于0(或为默认值),队列剩余容量少于discardingThreshold的配置就会丢弃<=INFO日志。这里的坑点有两个:
不是百分比,而是日志条数
。对于总容量10000队列,若希望队列剩余容量少于1000时丢弃,需配置为1000意味总可能会出现阻塞。
queueSize、discardingThreshold和neverBlock三参密不可分,务必按业务需求设置:
neverBlock = true
,永不阻塞discardingThreshold = 0
,即使≤INFO级日志也不会丢。但最好把queueSize设置大一点,毕竟默认的queueSize显然太小,太容易阻塞。以上日志配置最常见两个误区
再看日志记录本身的误区。
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适配的好处。