可观测性进化之路(一)- 日志

814 阅读5分钟

系列前言

这是一个新开的系列,总结我这一年以来,对观测系统的一些理念和经验。根据我的观察,大部分互联网公司,对这一块的重视是严重不足的,公司不会招一名观测专家。观测是大家一直以来习以为常的短板,这个系列希望能分享出我对可观测性的实践和理念,给大家一些启发和经验。

希望日后看到系统观测工程师成为公司的标配,越懂得怎么去观测的人,越能了解问题的本质。可观测性系统能够帮到每一个人成长。

本系列将通过可观测性三大件:日志、链路、监控来作为顺序。

认真看完,你一定会有所收获。

目录

  1. 日志的作用。
  2. 日志的原理。
  3. 打日志的正确姿势。
  4. 日志性能问题。

日志的作用

日志是与应用最接近的部分,方便记录流程,记录异常的详情,以及发生时的上下文。

而日志的问题,在于它是原子的,每一条日志之间没有实质上的关联。所以我们需要人为地在日志中埋入一些如链路 ID、用户 ID、IP、订单 ID、RPC 调用方名称等,将他们串联起来,看起来才会有意义。

日志的原理

日志门面是什么

Logging Facade 日志门面,Facade 在这里其实就是接口的意思,类似 Java 里的 interface,也就是一套 API,其中是基本上不包含任何具体实现的。

在 Java 里最流行的 Slf4j(Simple Logging Facade for Java) 就是一套日志门面,一般用 Logback、Log4j2 来作为具体实现。

日志框架的结构

日志框架一般包括以下功能:

  1. 对接日志门面。也可以不对接,自己实现一套类似的。如 Skywalking 中自己搞了一套简易的: logging - Skywalking
  2. 格式化日志。让用户自定义输出的格式,还有 %timestamp、%thread 之类的实现。
  3. 输出日志。一般有 System.out、文件,还支持用户自己拓展输出到 Kafka、ElasticSearch 之类的。

日志的性能问题

由于日志门面看起来很简单轻巧,很多人误以为打日志是件没什么开销的事。实际上,打日志本身是一件开销非常大的动作,在整个过程中会将字符串多产生很多份。

下面做个小小的实验,看看日志框架输出字符串到底会多申请多少内存(以下日志框架为 Logback 1.2.3):

@SneakyThrows
public void test() {
    // 不想看实验过程可以直接看最后
    ThreadMXBean threadMXBean = (ThreadMXBean) ManagementFactory.getThreadMXBean();
    long threadId = Thread.currentThread().getId();

    // 小技巧,通过 com.sun.management.ThreadMXBean.getThreadAllocatedBytes() 能获取到线程所申请的内存。
    // 初始化线程内存
    long threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    long lastBytes = threadAllocatedBytes;

    // sout 本身会产生一定内存,在这里是 144 bytes
    System.out.println(threadAllocatedBytes - lastBytes);
    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);

    // 输出:144 。即上边 sout 产生的内存
    System.out.println(threadAllocatedBytes - lastBytes);
    lastBytes = threadAllocatedBytes;

    // 这里会产生 48byte,40 个 byte 是 String 对象本身的固定开销,8 个 byte 是字符串本身的。
    // 由于内存对齐策略,1 字符和 4 字符都是 8 byte
    String msg = String.valueOf("****");
    
    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    
    // 输出: 192。减去一次 sout 的开销 144,msg 字符串本身是 48 byte。
    System.out.println(threadAllocatedBytes - lastBytes);
    lastBytes = threadAllocatedBytes;

    // 正式打日志了,输出到控制台
    // 输出格式为 [%p][%d{yyyy-MM-dd HH:mm:ss.SSS}][%X{trace.type}][%X{trace.id}][%X{trace.extra}][%t][%logger{50}] %m%n
    log.info(msg);

    threadAllocatedBytes = threadMXBean.getThreadAllocatedBytes(threadId);
    
    // 输出: 3440。除去 sout 产生的 144 bytes,日志本身会产生 3296bytes,约 3.2K
    System.out.println(threadAllocatedBytes - lastBytes);
}

结论: 日志输出(打到控制台)过程产生的内存开销为 3296bytes,是用户字符串本身的 68 倍(按 String 对象计算),或者 412 倍(按字符串本身算)。当然这个不算太科学,因为日志格式本身有固定的开销,倍数可能随着用户字符串增多而降低。

更不可思议的在后面,如果给日志加上行号(格式中加 %line),输出一次日志会产生多少内存?

8960 Bytes

值得一提的是,用 Log4j2 开启全异步模式、Garbage Free 模式,在无行号情况下,日志开销是 0。 不愧是 log4j2。

行号问题

先提出一个问题,日志框架如何知道是哪个类在打日志?

答案很简单,因为我们主动告诉了它:

private static final Logger log = LoggerFactory.getLogger(XyzService.class);

每个 logger 中我们都主动传入了 class。

那行号是怎么来的?

拿 Logback 举例,如果在日志格式中要求输出行号,会触发 LineOfCallerConverter

public class LineOfCallerConverter extends ClassicConverter {

    public String convert(ILoggingEvent le) {
        StackTraceElement[] cda = le.getCallerData();
        if (cda != null && cda.length > 0) {
            return Integer.toString(cda[0].getLineNumber());
        } else {
            return CallerData.NA;
        }
    }

}

为了获取行号,它需要抛出一个异常 Throwable,从异常中获取到栈信息 new Throwable().getStackTrace(),再根据传入的类名称,选择栈中对应的类:

public static StackTraceElement[] extract(Throwable t, String fqnOfInvokingClass, final int maxDepth, List<String> frameworkPackageList) {
    if (t == null) {
        return null;
    }

    StackTraceElement[] steArray = t.getStackTrace();
    StackTraceElement[] callerDataArray;

    int found = LINE_NA;
    for (int i = 0; i < steArray.length; i++) {
        if (isInFrameworkSpace(steArray[i].getClassName(), fqnOfInvokingClass, frameworkPackageList)) {
            // the caller is assumed to be the next stack frame, hence the +1.
            found = i + 1;
        } else {
            if (found != LINE_NA) {
                break;
            }
        }
    }

也就是说,每打一条日志,背后都会抛出一个异常并爬栈,众所周知,爬栈的开销很大。

结合内存火焰图看看,不开行号: 截屏2021-08-23 下午11.04.28.png

开启行号: 截屏2021-08-23 下午11.06.03.png

可以看到,在不开行号时,内存使用占比 90% 的 Calendar.getDisplayName()。开启行号之后,占比只剩 28%。也就是说,内存开销多出了 221%。这还没算 CPU 开销,实际上 CPU 的开销也很高。

综上所述,线上是决不能开行号的。

顺便一提,内存火焰图是神级项目 async-profiler,用命令 /profiler.sh -e alloc -t -d 30 -f result.html $pid 采集的。

阻塞线程

不论是 Logback 还是 Log4j2,都有可能阻塞用户线程。比如输出源是 System.out 时,因为要获取同一把锁,当竞争激烈时,阻塞会非常严重。

所以要注意,用户线程输出日志时,是否开启了异步模式。

打日志的正确姿势

选择框架

能选择 Log4j2 ,不选 Logback。 Log4j2 拥有 GC Free 模式,可以大幅减少内存申请,减少因日志输出导致的 GC。之后会出一篇详细的文章介绍这是如何做到的,对我们写代码也有一些启发。

开启 Garbage Gree 模式

很多人选对了框架,但是没开启全异步模式,等于啥也没干。

// 开启后就是 all async 模式了 System.setProperty("log4j2.contextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");

// 异步缓存的大小,不宜设置的太大,日志内容大的时候容易 OOM。默认 4096 System.setProperty("log4j2.asyncLoggerRingBufferSize", "2048");

// 防止阻塞用户线程,塞不进去的日志直接扔掉 System.setProperty("log4j2.AsyncQueueFullPolicy", "Discard"); System.setProperty("AsyncLogger.SynchronizeEnqueueWhenQueueFull", "false");

日志配置:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="30">

    <Appenders>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <!-- 输出日志的格式 -->
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
        </Console>

        <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile" fileName="${jojo:logging.file.path}" immediateFlush="false" append="false">
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <Logger name="root" level="info" includeLocation="false">
            <AppenderRef ref="RandomAccessFile"/>
            <!-- 线上要关闭输出到控制台,这里也填 RandomAccessFile 就可以,最好通过配置决定。 -->
            <AppenderRef ref="${isAppenderToStdout}"/>
        </Logger>
    </Loggers>
</Configuration>

参考 Log4j - Asynchronous Loggers for Low-Latency LoggingLog4j - Garbage-free Steady State Logging

选择输出源

最好输出到文件,相比 Kafka、UDP、HTTP 之类的方式,磁盘的 IO 更值得信任稳定性更强。

而输出到控制台就不用说了,直接 PASS。

尾声

日志篇(一)完,本篇探讨了日志的作用、性能开销,以及正确的打日志姿势。如果有不清晰的地方可以在下方评论,我随时补充。这个系列是决心要做到够全够精,言之有物的。

点赞过 100,继续更下期。