最近在线上系统的错误日志中发现了一个现象:
代码里用log4j打印系统运行时异常堆栈信息,在错误日志中无法看到堆栈信息,只有异常信息。这对于程序员来说是一个打击,没有堆栈信息何从查bug啊。
[01-15 11:29:26] [ERROR] [org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer:524] Unexpected throwable while invoking!
后来发现这个是jdk的一个优化。JVM 为了性能会做优化,如果频繁的抛出某个异常,会重新编译,不再打印异常堆栈。
解决这个问题也比较简单,如果不想每次都去查前面的 log 去看堆栈,只要在启动参数加上 -XX:-OmitStackTraceInFastThrow,就可以禁用该优化,强制打印异常堆栈。这样可能会导致,log 文件过大,不过产线上今天之前的 log 文件都会被压缩,所以感觉问题也不大。
[01-15 16:40:09] [ERROR] [org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer:524] Unexpected throwable while invoking!
java.lang.NullPointerException
at com.iqiyi.ttbrain.recommend.selector.services.FilterService.filter2(FilterService.java:42)
at com.iqiyi.ttbrain.recommend.thrift.IFilterService$Processor$filter2.getResult(IFilterService.java:181)
at com.iqiyi.ttbrain.recommend.thrift.IFilterService$Processor$filter2.getResult(IFilterService.java:166)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.invoke(AbstractNonblockingServer.java:518)
at org.apache.thrift.server.Invocation.run(Invocation.java:18)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)