锁定老帖子 主题:透过JVM看Exception本质
该帖已经被评为良好帖
|
|
---|---|
作者 | 正文 |
发表时间:2011-01-03
最后修改:2011-01-03
我的观点并没有变化...
需要一些时间,把LZ说的搞明白... |
|
返回顶楼 | |
发表时间:2011-01-03
最后修改:2011-01-03
hmm,楼主坚持字节码角度分析的话,那送上下面的例子。
把楼主的代码稍微简化一下: public class ExceptionTest { public static void newObject() { new Object(); } public static void newException() { new Exception(); } public static void catchException() { try { throw new Exception(); } catch (Exception e) { } } public static void newCustomException() { new CustomException(); } public static void main(String[] args) { CustomException.class.getName(); newObject(); newException(); catchException(); newCustomException(); } } class CustomException extends Exception { @Override public Throwable fillInStackTrace() { return this; } } 在main()的开头加了句getName()是为了在那个位置上触发CustomException的加载,免得它到newCustomException()的时候才加载,方便过滤日志。 然后找个fastdebug build的HotSpot,用下面的参数来跑: java -XX:+TraceBytecodes ExceptionTest 把从main()开始到结束的部分提取出来,并忽略掉其中与类加载相关的部分之后,剩下的字节码序列(bytecode trace)是 [6872] static void ExceptionTest.main(jobject) [6872] 5377751 0 ldc_w <unresolved klass at 5> [6872] 5389978 3 invokevirtual 7 <getName> <()Ljava/lang/String;> [6872] virtual jobject java.lang.Class.getName() [6872] 5390841 0 aload_0 [6872] 5390842 1 getfield 50 <name> <Ljava/lang/String;> [6872] 5390843 4 astore_1 [6872] 5390844 5 aload_1 [6872] 5390845 6 ifnonnull 19 [6872] 5390846 9 aload_0 [6872] 5390847 10 aload_0 [6872] 5390848 11 invokespecial 51 <getName0> <()Ljava/lang/String;> [6872] 5390849 14 dup [6872] 5390850 15 astore_1 [6872] 5390851 16 putfield 50 <name> <Ljava/lang/String;> [6872] 5390852 19 aload_1 [6872] 5390853 20 areturn [6872] static void ExceptionTest.main(jobject) [6872] 5390854 6 pop [6872] 5390855 7 invokestatic 8 <newObject> <()V> [6872] static void ExceptionTest.newObject() [6872] 5390856 0 new 2 <java/lang/Object> [6872] 5390857 3 dup [6872] 5390858 4 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Object.<init>() [6872] 5390859 0 return_register_finalizer [6872] static void ExceptionTest.newObject() [6872] 5390860 7 pop [6872] 5390861 8 return [6872] static void ExceptionTest.main(jobject) [6872] 5390862 10 invokestatic 9 <newException> <()V> [6872] static void ExceptionTest.newException() [6872] 5390863 0 new 3 <java/lang/Exception> [6872] 5390864 3 dup [6872] 5390865 4 invokespecial 4 <<init>> <()V> [6872] virtual void java.lang.Exception.<init>() [6872] 5390866 0 aload_0 [6872] 5390867 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Throwable.<init>() [6872] 5390868 0 aload_0 [6872] 5390869 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Object.<init>() [6872] 5390870 0 return_register_finalizer [6872] virtual void java.lang.Throwable.<init>() [6872] 5390871 4 aload_0 [6872] 5390872 5 aload_0 [6872] 5390873 6 putfield 2 <cause> <Ljava/lang/Throwable;> [6872] 5390874 9 aload_0 [6872] 5390875 10 invokevirtual 3 <fillInStackTrace> <()Ljava/lang/Throwable;> [6872] 5390876 13 pop [6872] 5390877 14 return [6872] virtual void java.lang.Exception.<init>() [6872] 5390878 4 return [6872] static void ExceptionTest.newException() [6872] 5390879 7 pop [6872] 5390880 8 return [6872] static void ExceptionTest.main(jobject) [6872] 5390881 13 invokestatic 10 <catchException> <()V> [6872] static void ExceptionTest.catchException() [6872] 5390882 0 new 3 <java/lang/Exception> [6872] 5390883 3 dup [6872] 5390884 4 invokespecial 4 <<init>> <()V> [6872] virtual void java.lang.Exception.<init>() [6872] 5390885 0 aload_0 [6872] 5390886 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Throwable.<init>() [6872] 5390887 0 aload_0 [6872] 5390888 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Object.<init>() [6872] 5390889 0 return_register_finalizer [6872] virtual void java.lang.Throwable.<init>() [6872] 5390890 4 aload_0 [6872] 5390891 5 aload_0 [6872] 5390892 6 putfield 2 <cause> <Ljava/lang/Throwable;> [6872] 5390893 9 aload_0 [6872] 5390894 10 invokevirtual 3 <fillInStackTrace> <()Ljava/lang/Throwable;> [6872] 5390895 13 pop [6872] 5390896 14 return [6872] virtual void java.lang.Exception.<init>() [6872] 5390897 4 return [6872] static void ExceptionTest.catchException() [6872] 5390898 7 athrow [6872] 5390899 8 astore_0 [6872] 5390900 9 return [6872] static void ExceptionTest.main(jobject) [6872] 5390901 16 invokestatic 11 <newCustomException> <()V> [6872] static void ExceptionTest.newCustomException() [6872] 5390902 0 new 5 <CustomException> [6872] 5390903 3 dup [6872] 5390904 4 invokespecial 6 <<init>> <()V> [6872] virtual void CustomException.<init>() [6872] 5390905 0 aload_0 [6872] 5390906 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Exception.<init>() [6872] 5390907 0 aload_0 [6872] 5390908 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Throwable.<init>() [6872] 5390909 0 aload_0 [6872] 5390910 1 invokespecial 1 <<init>> <()V> [6872] virtual void java.lang.Object.<init>() [6872] 5390911 0 return_register_finalizer [6872] virtual void java.lang.Throwable.<init>() [6872] 5390912 4 aload_0 [6872] 5390913 5 aload_0 [6872] 5390914 6 putfield 2 <cause> <Ljava/lang/Throwable;> [6872] 5390915 9 aload_0 [6872] 5390916 10 invokevirtual 3 <fillInStackTrace> <()Ljava/lang/Throwable;> [6872] virtual jobject CustomException.fillInStackTrace() [6872] 5390917 0 aload_0 [6872] 5390918 1 areturn [6872] virtual void java.lang.Throwable.<init>() [6872] 5390919 13 pop [6872] 5390920 14 return [6872] virtual void java.lang.Exception.<init>() [6872] 5390921 4 return [6872] virtual void CustomException.<init>() [6872] 5390922 4 return [6872] static void ExceptionTest.newCustomException() [6872] 5390923 7 pop [6872] 5390924 8 return [6872] static void ExceptionTest.main(jobject) [6872] 5390925 19 return 这个日志中,每段字节码的开头都有方法名,说明该字节码指令属于哪个方法; 每行开头的方括号内是线程ID; 在字节码指令的行中,线程ID之后的是字节码计数器,也就是解释器执行到当前位置已经执行了多少条字节码。中间有不连续的地方因为把类加载的代码过滤掉了; 再后面是当前字节码在方法内的偏移量(也就是bci); 然后是字节码指令的名字,和参数(如果有的话)。 看这个bytecode trace,到底整个执行过程中都经过了那些字节码指令一目了然。 留意到Throwable.fillInStackTrace()在HotSpot里是native的,所以在5390894跟5390895之间看不到该方法的实现;而它做的事情嘛……呵呵 完整的trace日志请看附件。注意:解压后日志有211MB左右,请有所准备… |
|
返回顶楼 | |
发表时间:2011-01-03
最后修改:2011-01-03
楼主分析在理
逻辑易懂,找到性能的本质所在就可以了! 呵呵,添加点个人使用异常体会 : )
|
|
返回顶楼 | |
发表时间:2011-01-03
最后修改:2011-01-03
一个具体的问题:
之前LZ测试了一下validateInteger的执行时间,执行100000次的时间是: 字符串为非整数,验证方式1:2029725263ns 我想请教一下: 这是一个累加的时间。你之前讲过和另一个方法比,时间差200倍,我想请问,这200倍是以怎样的形式体现到应用程序中的? 我想有如下具体问题需要明确: 第一. 进行10万次调用,影不影响单次调用时间? 在并发情况下,两个线程分别调用validateInteger,会不会互相增加对方的调用时间? 第二. 在一个多线程系统中,每个线程需要调用validateInteger一次。那么,当并发量具增,会不会因为validateInteger产生性能问题?如果会,达到多少并发会产生? 这里明确一下性能问题:使用户明显感觉到程序响应时间变长了。假设一个用户对应一个线程,响应时间延迟一秒。 这里还得假设这个线程,仅有validatInteger操作。 第三. 我想第二的余量应该是相当大的。那就是结论,只有在内存中反复的调用validateInteger时,才会产生显著的,可以影响程序响应时间的情况,是不是这样呢? 我想了想,这些似乎可以测试,但是当线程多时,线程切换本身也会代来开销,这样测试必然是不准的。不知LZ有没有估算的办法? 我先做一个简单估算: 假设所有validateInteger是互斥的。 那同时有50000个线程并发调用validateInteger时,最后一个会被延迟大约1秒。假设这时用户是可以容忍的。 那可以简单估算一下当前应用有多少用户。 同时请求的有:50000个。 同时在线的有:50000*10=500000 已注册用户应达到:500000*10=5000000 |
|
返回顶楼 | |
发表时间:2011-01-03
强帖!学习一下。
话说gdpglc同学的态度感觉好多了么,呵呵。 |
|
返回顶楼 | |
发表时间:2011-01-03
最后修改:2011-01-03
gdpglc 写道 一个具体的问题:
之前LZ测试了一下validateInteger的执行时间,执行100000次的时间是: 字符串为非整数,验证方式1:2029725263ns 我想请教一下: 这是一个累加的时间。你之前讲过和另一个方法比,时间差200倍,我想请问,这200倍是以怎样的形式体现到应用程序中的? 我想有如下具体问题需要明确: 第一. 进行10万次调用,影不影响单次调用时间? 在并发情况下,两个线程分别调用validateInteger,会不会互相增加对方的调用时间? 第二. 在一个多线程系统中,每个线程需要调用validateInteger一次。那么,当并发量具增,会不会因为validateInteger产生性能问题?如果会,达到多少并发会产生? 这里明确一下性能问题:使用户明显感觉到程序响应时间变长了。假设一个用户对应一个线程,响应时间延迟一秒。 这里还得假设这个线程,仅有validatInteger操作。 第三. 我想第二的余量应该是相当大的。那就是结论,只有在内存中反复的调用validateInteger时,才会产生显著的,可以影响程序响应时间的情况,是不是这样呢? 我想了想,这些似乎可以测试,但是当线程多时,线程切换本身也会代来开销,这样测试必然是不准的。不知LZ有没有估算的办法? 我先做一个简单估算: 假设所有validateInteger是互斥的。 那同时有50000个线程并发调用validateInteger时,最后一个会被延迟大约1秒。假设这时用户是可以容忍的。 那可以简单估算一下当前应用有多少用户。 同时请求的有:50000个。 同时在线的有:50000*10=500000 已注册用户应达到:500000*10=5000000 我写的观点是:“这个方法如果调用次数不多,怎么写都无所谓,如果次数多还是不要这样用的好” 放在有用户交互的系统中,譬如你写的使用在验证方面,我觉得属于上面第一个“如果”的情况,你只要觉得代码清晰,后续维护的人好看好懂,那怎么写都无所谓。 但Java不一定只用来做WEB、ERP、MIS这些强交互式应用,譬如在ETL类的应用中,提一个这样的需求(好像在JE上看到迅雷还是腾讯有这样的面试题),给你一个10T的数据文件,每行一个字符串,判断其中有多少整数,这样用异常的写法自然就不太合适(估计用我写的那个也不合适@_@)。 但也不必悲观的说大数据量的事情找C/C++来干。有JIT的介入后,Java和C/C++本质上都是执行native code,这时拼的就是编译器输出代码的智能程度。Java JIT编译优势是在运行期能根据profiling做很多静态编译中不敢做的激进优化,大不了逆向优化退回来,但劣势是编译时间就是运行时间,不敢做耗时太长的编译优化。 另外,如果涉及到同步互斥,那异常导致方法退出时要比我楼顶描写的做更多的事情,具体见虚拟机规范: 引用 If the current frame represents an invocation of a synchronized method, the monitor acquired or reentered on invocation of the method is released or exited (respectively) as if by execution of a monitorexit instruction.
|
|
返回顶楼 | |
发表时间:2011-01-03
实例、分析俱全,LZ真不错。
用异常做流程控制还是比较损失系统性能的,有些企业系统压力不太在乎这点损失,但一些每天pv上亿的互联网站,就要斤斤计较的算计系统性能,作为程序员来讲,用硬件来弥补代码上的缺陷,不是一件值得骄傲的事情 |
|
返回顶楼 | |
发表时间:2011-01-03
强帖。。。学习了!
|
|
返回顶楼 | |
发表时间:2011-01-03
lz, 感觉你的测试用例有点问题,我修改了一下:
public void catchException() { long l = System.nanoTime(); Exception e = new Exception(); for (int i = 0; i < testTimes; i++) { try { throw e; } catch (Exception e1) { } } System.out.println("建立、抛出并接住异常对象:" + (System.nanoTime() - l)); } 这是我改正后得到的结果: 建立对象:865088 建立异常对象:12278747 建立、抛出并接住异常对象:2129125 看得出逻辑部分速度还不算慢,最慢的是建立异常对象的时间。 通过比较,和普通对象相比,多出了一个fillInStackTrace的过程,看来这个地方是性能瓶颈 通过修改方法: public void newException() { Exception e = new Exception(); long l = System.nanoTime(); for (int i = 0; i < testTimes; i++) { e.fillInStackTrace(); } System.out.println("建立异常对象:" + (System.nanoTime() - l)); } 可以验证我们的结论。fillInStackTrace是一个native方法,javadoc: Fills in the execution stack trace. This method records within this Throwable object information about the current state of the stack frames for the current thread. 显然需要和当前虚拟机执行线程的执行环境交互,导致了性能较差 |
|
返回顶楼 | |
发表时间:2011-01-03
最后修改:2011-01-03
其实LZ可以再往下细扣一下,为啥new Exception会慢,profile一看主要就是慢在一个native方法调用上fillInStackTrace。
该方法的主要作用就是获取当前线程执行栈,用于日志记录和以后分析所用 一般针对业务逻辑,其实可以不太关注具体的线程调用栈,我们大家应该关注的是业务异常message和code 所以我还是比较喜欢用异常来进行逻辑控制和返回,首先代码风格上会比较清晰 可以参考下:复写了RumtimeException的一个native方法,在测试过程中性能几乎就和if..else一样了 public static class ServiceException extends RumtimeException { @Override public Throwable fillInStackTrace() { return this; } } 具体的测试分析,可以看下我同事的测试文档 : http://www.blogjava.net/stone2083/archive/2010/07/09/325649.html |
|
返回顶楼 | |