打印异常栈信息的过程和影响

遇到报错总是控制台或日志里输出一堆异常栈信息，那么JVM是怎么输出的呢？这个过程消耗性能吗？

在使用avenger框架时候看到一个屏蔽RPC接口超时打印线程栈信息的配置项，看了源码发现只是将超时异常转换成一个AvengerException自定义异常。

问了同事说这样避免在RPC接口超时，很多线程都去打印异常栈信息引发锁竞争。

在Throwable中可以看到这个就是打印线程栈信息的代码。

private void printStackTrace(PrintStreamOrWriter s) {
    // Guard against malicious overrides of Throwable.equals by
    // using a Set with identity equality semantics.
    Set<Throwable> dejaVu =
        Collections.newSetFromMap(new IdentityHashMap<Throwable, Boolean>());
    dejaVu.add(this);

    synchronized (s.lock()) {
        // Print our stack trace
        s.println(this);
        StackTraceElement[] trace = getOurStackTrace();
        for (StackTraceElement traceElement : trace)
            s.println("\tat " + traceElement);

        // Print suppressed exceptions, if any
        for (Throwable se : getSuppressed())
            se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION, "\t", dejaVu);

        // Print cause, if any
        Throwable ourCause = getCause();
        if (ourCause != null)
            ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, "", dejaVu);
    }
}

其中StackTraceElement对象是代表每一个栈帧的类。里面封装了每个执行函数名字。

其中getStackTraceDepth()和getStackTraceElement(i)是JVM函数。其实native方法不一定是系统调用，只是执行一段C代码，

这段C代码在class文件编译时应该已经链接到文件中了，所以对操作系统来说会直接执行汇编代码，可能会更快。

/**
 * The stack trace, as returned by {@link #getStackTrace()}.
 *
 * The field is initialized to a zero-length array.  A {@code
 * null} value of this field indicates subsequent calls to {@link
 * #setStackTrace(StackTraceElement[])} and {@link
 * #fillInStackTrace()} will be be no-ops.
 *
 * @serial
 * @since 1.4
 */
private StackTraceElement[] stackTrace = UNASSIGNED_STACK;

private synchronized StackTraceElement[] getOurStackTrace() {
    // Initialize stack trace field with information from
    // backtrace if this is the first call to this method
    if (stackTrace == UNASSIGNED_STACK ||
        (stackTrace == null && backtrace != null) /* Out of protocol state */) {
        int depth = getStackTraceDepth();
        stackTrace = new StackTraceElement[depth];
        for (int i=0; i < depth; i++)
            stackTrace[i] = getStackTraceElement(i);
    } else if (stackTrace == null) {
        return UNASSIGNED_STACK;
    }
    return stackTrace;
}

回到输出异常信息的地方，看到s.lock()，s是System.err的包装类，System.err是一个PrintStream对象。为什么要给输出流上锁呢?

因为System.err是全局的异常输出流，很多线程都共用。当然会有并发，当输出缓冲区写一半混入另一个线程的数据就会导致错乱信息。

private void printStackTrace(PrintStreamOrWriter s) {
    // Guard against malicious overrides of Throwable.equals by
    // using a Set with identity equality semantics.
    Set<Throwable> dejaVu =
        Collections.newSetFromMap(new IdentityHashMap<Throwable, Boolean>());
    dejaVu.add(this);
    synchronized (s.lock()) {
        用给定的输出流打印线程异常栈信息
   }
}

所以回到一开始的场景，avenger框架屏蔽RPC异常超时的接口的异常栈信息打印而是换成自定义异常打印。

default <Context extends RequestPipelineContext> Throwable adaptError(Context requestPipelineContext, Throwable e) {
    //老的方式
    if (!requestPipelineContext.isShieldTimeOutStack()) {
        return e;
    }
    boolean isRpcTimeout = e.getClass().equals(TimeoutException.class)
            || (e.getClass().equals(RpcException.class) && StringUtils.contains(e.getMessage(), RpcException.REQUEST_TIMEOUT));
    return isRpcTimeout ? this.convertToShieldStackAvengerRuntimeException(e) : e;
}
default Throwable convertToShieldStackAvengerRuntimeException(Throwable e) {
    // 如果不转换，就会把e的cause异常栈信息全部打印出来，增加打印性能消耗。这里转换缩减打印字符串成本，最后还是要抢printStream锁
    // 因为日志框架要调用Throwable.printStackTrace(PrintStream)，传入自己的输出流对象
    // 另外Log4j的实现中，是异步追加事件，由异步线程处理事件打印的
    return new AvengerRuntimeException(e.getClass().getName() + " shield stack to " + e.getMessage());
}

在别人的优化案例中也提到了大量日志输出会增加服务压力，首先大量日志打印造成大量线程争抢PrintStream流的独占锁，线程需要调用线程栈信息。然后大量日志string在内存中构造等待刷盘，这也会增加内存压力，导致young GC偏高或频繁。

在我们自己实际案例中也有，转转卖场双十一压测时，发现一个接口耗时偏高500ms+，经排查是打印大量日志（一次打印2个屏幕的量）。后来加了开关，不打印日志时，RT就降了下来。