一文搞懂Java日志级别,重复记录、丢日志问题

网友投稿 1089 2022-05-29

1 新手村试炼

1.1 框架烦多!

不同类库可能使用不同日志框架,兼容难!

1.2 配置复杂

由于配置文件烦杂!很多同学喜欢从其他项目或网上直接闭眼复制一份。

1.3 随意度高

因为不会直接导致代码 bug,测试人员也难及时发现问题,开发就没仔细考虑日志内容获取的性能开销、随意选用日志级别。

2 SLF4J

Logback、Log4j、Log4j2、commons-logging、JDK自带的java.util.logging等,都是Java体系的日志框架。

不同的类库,还可能选择使用不同的日志框架,导致日志统一管理困难。

SLF4J(Simple Logging Facade For Java)就为解决该问题

提供统一的日志门面API,即图中紫色部分,实现中立的日志记录API

桥接功能,蓝色部分,把各种日志框架API(绿色部分)桥接到SLF4J API。这样即便你的程序中使用各种日志API记录日志,最终都可桥接到SLF4J门面API。

适配功能,红色部分,可实现SLF4J API和实际日志框架(灰色部分)绑定。

SLF4J只是日志标准,还是需要实际日志框架。日志框架本身未实现SLF4J API,所以需前置转换。Logback就是按SLF4J API标准实现,所以才无需绑定模块做转换。

虽然可用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的桥接。

4 异步日志提高性能?

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

定义如下的日志配置,一共有两个Appender:

FILE是一个FileAppender,用于记录所有的日志;

CONSOLE是一个ConsoleAppender,用于记录带有time标记的日志。

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

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

测试代码:实现记录指定次数的大日志,每条日志包含1MB字节的模拟数据,最后记录一条以time为标记的方法执行耗时日志:

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

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

源码解析

FileAppender继承自OutputStreamAppender

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

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

AsyncAppender

使用Logback的AsyncAppender

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

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

记录1000次日志和10000次日志的调用耗时,分别是537毫秒和1019毫秒

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

AsyncAppender异步日志坑

记录异步日志撑爆内存

记录异步日志出现日志丢失

记录异步日志出现阻塞。

案例

模拟慢日志记录场景:

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

配置文件中使用AsyncAppender,将MySlowAppender包装为异步日志记录

测试代码

耗时很短但出现日志丢失:要记录1000条日志,最终控制台只能搜索到215条日志,而且日志行号变问号。

原因分析

AsyncAppender提供了一些配置参数,而当前没用对。

源码解析

includeCallerData

默认false:方法行号、方法名等信息不显示

queueSize

控制阻塞队列大小,使用的ArrayBlockingQueue阻塞队列,默认容量256:内存中最多保存256条日志

discardingThreshold

丢弃日志的阈值,为防止队列满后发生阻塞。默认队列剩余容量 < 队列长度的20%,就会丢弃TRACE、DEBUG和INFO级日志

neverBlock

控制队列满时,加入的数据是否直接丢弃,不会阻塞等待,默认是false

队列满时:offer不阻塞,而put会阻塞

neverBlock为true时,使用offer

public class AsyncAppender extends AsyncAppenderBase { // 是否收集调用方数据 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 extends UnsynchronizedAppenderBase implements AppenderAttachable { // 阻塞队列:实现异步日志的核心 BlockingQueue 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(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(); } } } }

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

一文搞懂Java日志级别,重复记录、丢日志问题

20

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

37

38

39

40

41

42

43

44

45

46

47

48

49

50

51

52

53

54

55

56

57

58

59

60

61

62

63

64

65

66

67

68

69

70

71

72

73

74

75

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

queueSize 过大

可能导致OOM

queueSize 较小

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

因为discardingThreshold,所以设置queueSize时容易踩坑。

比如本案例最大日志并发1000,即便置queueSize为1000,同样会导致日志丢失

discardingThreshold参数容易有歧义,它不是百分比,而是日志条数。对于总容量10000队列,若希望队列剩余容量少于1000时丢弃,需配置为1000

neverBlock 默认false

意味总可能会出现阻塞。

若discardingThreshold = 0,那么队列满时再有日志写入就会阻塞

若discardingThreshold != 0,也只丢弃≤INFO级日志,出现大量错误日志时,还是会阻塞

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

若优先绝对性能,设置neverBlock = true,永不阻塞

若优先绝不丢数据,设置discardingThreshold = 0,即使≤INFO级日志也不会丢。但最好把queueSize设置大一点,毕竟默认的queueSize显然太小,太容易阻塞。

若兼顾,可丢弃不重要日志,把queueSize设置大点,再设置合理的discardingThreshold

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

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

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

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

这说法对吗?

验证代码:返回结果耗时1秒

若记录DEBUG日志,并设置只记录>=INFO级日志,程序是否也会耗时1秒?

三种方法测试:

拼接字符串方式记录slowString

使用占位符方式记录slowString

先判断日志级别是否启用DEBUG。

前俩方式都调用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适配的好处。

总结

SLF4J统一了Java日志框架。在使用SLF4J时,要理清楚其桥接API和绑定。若程序启动时出现SLF4J错误提示,那可能是配置问题,可使用Maven的dependency:tree命令梳理依赖关系。

异步日志解决性能问题,是用空间换时间。但空间毕竟有限,当空间满,要考虑阻塞等待or丢弃日志。如果更希望不丢弃重要日志,那么选择阻塞等待;如果更希望程序不要因为日志记录而阻塞,那么就需要丢弃日志。

日志框架提供的参数化日志记录方式不能完全取代日志级别判断。若你的日志量很大,获取日志参数代价也很大,就要判断日志级别,避免不记录日志也要耗时获取日志参数。

API Java

版权声明:本文内容由网络用户投稿,版权归原作者所有,本站不拥有其著作权,亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容,请联系我们jiasou666@gmail.com 处理,核实后本网站将在24小时内删除侵权内容。

上一篇:【深入浅出etcd系列】3. 日志同步
下一篇:Linux面试必备20个常用命令
相关文章