分析

在巨大的调用量下，日志输出也有可能成为一定的瓶颈。我在动态调整应用某个Logger的日志级别时产生了大量额外的日志，发现CPU也会有肉眼可见的飙升，但是理论上来说打日志影响的主要是磁盘IO，不应该对CPU有肉眼可见的影响。在对应用进行CPU火焰图分析时，可以很明显的看到某些日志会有平顶的情况，也很能说明问题所在，贴图如下：

这是一条Logback info级别日志的输出，并没有带上任何异常信息，但是占绝对主导的调用是两个和stack trace相关内容：

  1. java.lang.Throwable#fillInStackTrace：Throwable对象构造方法中会使用的native方法
  2. java.lang.Throwable#getStackTrace：获取调用堆栈信息

原因也可以在图中看到，它们的上层方法是ch.qos.logback.classic.pattern.LineOfCallerConverter#convert，很明显是在获取行号，看一下具体代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
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
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;
        }
    }

}

public class LoggingEvent implements ILoggingEvent {
  
    // ... something ...
    
    public StackTraceElement[] getCallerData() {
        if (callerDataArray == null) {
            // 这里new了一个Throwable出来
            callerDataArray = CallerData
                            .extract(new Throwable(), fqnOfLoggerClass, loggerContext.getMaxCallerDataDepth(), loggerContext.getFrameworkPackages());
        }
        return callerDataArray;
    }
  
    // ... something ... 
}

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

        // stacktrace获取、处理
        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;
                }
            }
        }

        // we failed to extract caller data
        if (found == LINE_NA) {
            return EMPTY_CALLER_DATA_ARRAY;
        }

        int availableDepth = steArray.length - found;
        int desiredDepth = maxDepth < (availableDepth) ? maxDepth : availableDepth;

        callerDataArray = new StackTraceElement[desiredDepth];
        for (int i = 0; i < desiredDepth; i++) {
            callerDataArray[i] = steArray[found + i];
        }
        return callerDataArray;
    }
  
    // ... something ...
}

这是Logback的具体实现，Log4j在获取相关信息时也是类似的，每次打日志获取行号都要new一个Throwble对象然后getStackTrace，getStackTrace得到一个数组，看代码也可以发现数组中的每个对象（StackTraceElement）都是需要调用native方法来获取，是一个循环调用。这是一个比较重的操作，获取行号相对来说很费资源。至于为什么能拿到行号，本质上是因为字节码中有个LineNumberTable属性，将字节码偏移地址与java行对应起来，所以可以获取。

查看代码和官方文档，可以发现不仅仅是行号，类名、方法名、文件名的输出都会导致抽取日志输出时的stack trace，其实说白了这些都是方法调用的额外信息，要么运行时动态获取，要么编译期额外写入。Logback的代码里称之为Caller Data，而Log4j2的文档中称这些为Location infomation。单就这一个点来说，Log4j2的文档和逻辑处理要优于Logback，在Logback的文档中仅仅是在Pattern Layout配置说明中相关项的尾部带上一句提醒：Generating the xxx information is not particularly fast. Thus, its use should be avoided unless execution speed is not an issue. 。而Log4j2的文档有两处都给予了单独的额外提醒，其一是Pattern Layout配置的尾部，其二是异步日志的相关说明，内容也不算多，直接贴出异步日志的相关说明：

If one of the layouts is configured with a location-related attribute like HTML locationInfo, or one of the patterns %C or $class, %F or %file, %l or %location, %L or %line, %M or %method, Log4j will take a snapshot of the stack, and walk the stack trace to find the location information.

This is an expensive operation: 1.3 - 5 times slower for synchronous loggers. Synchronous loggers wait as long as possible before they take this stack snapshot. If no location is required, the snapshot will never be taken.

However, asynchronous loggers need to make this decision before passing the log message to another thread; the location information will be lost after that point. The performance impact of taking a stack trace snapshot is even higher for asynchronous loggers: logging with location is 4 - 20 times slower than without location. For this reason, asynchronous loggers and asynchronous appenders do not include location information by default.

You can override the default behaviour in your logger or asynchronous appender configuration by specifying includeLocation="true".

Log4j2在异步日志输出时默认不会带上这些信息，用户需要手动显式指明开启，原因说的也很明白：用异步日志的主要理由就是消除日志输出的所带来的的额外延迟，但是这些位置信息的抽取占了日志输出整个过程消耗的很大一块且必须同步处理，很明显这和异步输出的目标是有矛盾的。很多时候Logback的异步输出感觉不到任何效果也是因为这个，所以如果要使用异步日志，这就是一个不能忽略的点。

此外我之前在翻找Github时还发现了一个scala的日志库，号称在编译期处理了这些额外的信息，带来了极致的性能，但是我没有具体用过，感兴趣可以看看。

使用建议

  1. 避免使用行号、类名、方法名等，当然这些信息对于日志体验是有很大提升，尤其是对于一些三方库的日志输出，在多处输出内容相似的情况下，没有这些信息容易导致找不到具体是哪里打的。所以尽量每个日志输出要能够有唯一标识，也可以针对量大的日志单独设置日志格式，去除行号输出。
  2. 同样道理，避免高频次的new Throwable().getStackTrace调用，输出堆栈的日志的频率不能太高。抛出异常、打印异常堆栈也需要构造相关调用的频率不能过高。
  3. 虽然相对比较“重”，但也不必过于计较，相对于具体业务逻辑，这个操作损耗可能并不显眼，真的出现瓶颈了再处理也不迟，CPU总是要有冗余的，硬件摆在那不用白不用。相比于什么安全漏洞，这也就是毛毛雨吧。
  4. 异步日志一定要避免使用这些信息，否则使用异步日志的优势会被大量蚕食。