背景

经常看到说不建议在catch中使用printStackTrace()打印异常，虽然它也能将异常堆栈输出到控制台或日志。

下面是一个简单异常打印代码

public class TestPrintStackTrace {

    public static void main(String[] args) {
        try {
            System.out.println("异常前");
            exception();
        }catch (Exception e){
            e.printStackTrace();
        }
        System.out.println("异常后");
    }

    public static void exception() throws Exception{
        System.out.println("异常发生");
        throw new Exception();
    }
}

在我运行的结果中会有多种输出情况

• 情况1

java.lang.Exception
	at com.fang.java.exception.Test.exception(Test.java:24)
异常前
	at com.fang.java.exception.Test.main(Test.java:14)
异常发生
异常后

• 情况2

异常前
异常发生
异常后
java.lang.Exception
	at com.fang.java.exception.TestPrintStackTrace.exception(TestPrintStackTrace.java:24)
	at com.fang.java.exception.TestPrintStackTrace.main(TestPrintStackTrace.java:14)

• 情况3

java.lang.Exception
异常前
	at com.fang.java.exception.TestPrintStackTrace.exception(TestPrintStackTrace.java:24)
	at com.fang.java.exception.TestPrintStackTrace.main(TestPrintStackTrace.java:14)
异常发生
异常后

问题很明显了，就是printStackTrace()打印出的堆栈日志跟正常输出或者业务代码执行日志是交错混合在一起的，在并发大日志输出多的情况下，查看异常日志就变更的非常困难，因为一块日志都不在一起了。

原因

那么为什么会造成这个现象呢，先看一下printStackTrace()在Throwable中的实现

//默认调用了传入System.err的实现
//System.err代表一个输出流，系统还默认有System.in、System.out
public void printStackTrace() {
	printStackTrace(System.err);
}

//通过WrappedPrintStream将PrintStream包装了一下
public void printStackTrace(PrintStream s) {
    printStackTrace(new WrappedPrintStream(s));
}

System.err的定义是在System类中，可以看到我们平时使用的System.out是通过FileOutputStream实现的，System.err也是一个不同的FileInputStream

FileInputStream fdIn = new FileInputStream(FileDescriptor.in);
FileOutputStream fdOut = new FileOutputStream(FileDescriptor.out);
FileOutputStream fdErr = new FileOutputStream(FileDescriptor.err);
setIn0(new BufferedInputStream(fdIn));
setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding")));
setErr0(newPrintStream(fdErr, props.getProperty("sun.stderr.encoding")));

接下来看下WrappedPrintStream的实现

//该包装类是很关键的，其中lock方法是返回给输出时使用的锁
//真是该锁保证了，在一个输出流上的输出是顺序的
private static class WrappedPrintStream extends PrintStreamOrWriter {
    private final PrintStream printStream;

    WrappedPrintStream(PrintStream printStream) {
        this.printStream = printStream;
    }

    Object lock() {
        return printStream;
    }

    void println(Object o) {
        printStream.println(o);
    }
}

最后看下printStackTrace的具体实现

//传入WrappedPrintStream
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);
    }
}

总结

printStackTrace()默认使用了System.err输出流进行输出，与System.out是两个不同的输出流，那么在打印时自然就形成了交叉。再就是输出流是有缓冲区的，所以对于什么时候具体输出也形成了随机。

看到这里就明白了，如果想简单的让输出顺序话，给printStackTrace()指定一个输出流就可以了，例如printStackTrace(System.out)

异常前
异常发生
java.lang.Exception
	at com.fang.java.exception.TestPrintStackTrace.exception(TestPrintStackTrace.java:24)
	at com.fang.java.exception.TestPrintStackTrace.main(TestPrintStackTrace.java:14)
异常后

在项目中一般都是使用logback、log4j这类框架统一打印日志，好处多多。