-
1. Re: Javassist instrumented classes Performance
chiba Jul 9, 2003 2:51 PM (in response to cmanzana)This result seems weird... I'll check this.
Basically, the overhead due to Javassist
is quite small. -
2. Re: Javassist instrumented classes Performance
chiba Jul 11, 2003 1:49 AM (in response to cmanzana)I tested but could not see any substantial
differences between the two instrumentations.
Also, the generated bytecode was quite
the same between the two.
I ran the program on JDK1.4.1/WindowsXP
(only client VM), Linux (client and server
VM), and JDK1.4.0/Solaris (client and server VM).
I also used JDK1.3.1 on Solaris (client and server
VM) but the result was the same. -
3. Re: Javassist instrumented classes Performance
cmanzana Aug 16, 2003 9:03 AM (in response to cmanzana)Hi,
I don't really know what can I be doing wrong
I've the following classes:package com.test; public class TestClassBean { public String getMessage() { for( long i = 0; i < 5000000L; i++ ) { Math.sqrt(i); } return myMessage; } public void setMessage( String msg ) { myMessage = msg; } private String myMessage; }
package com.test; public class Checker { public static void main( String args[] ) throws Exception { long start = System.currentTimeMillis(); TestClassBean tc = new TestClassBean(); tc.setMessage( "Hi there" ); for( int i = 0; i < 10; i++ ) { tc.getMessage(); } System.out.println( "End of execution" ); long elapsed = System.currentTimeMillis() - start; System.out.println( "elapsed: " + elapsed + " ms" ); } }
without using javassist the previous code runs in ~3 seconds
when using javassist with the previous class:for( int i = 0; i < methods.length; i++ ) { if ( !methods.isEmpty() && !Modifier.isNative( methods.getModifiers() ) ) { methods.insertAfter( "System.out.println( \"Hello\" );", true ); } }
it runs in ~8 seconds
here is the dissambled code:public class TestClassBean { public TestClassBean() { // 0 0:aload_0 // 1 1:invokespecial #11 <Method void Object()> // 2 4:return } public String getMessage() { // 0 0:lconst_0 // 1 1:lstore_1 // 2 2:goto 15 // 3 5:lload_1 // 4 6:l2d // 5 7:invokestatic #23 <Method double Math.sqrt(double)> // 6 10:pop2 // 7 11:lload_1 // 8 12:lconst_1 // 9 13:ladd // 10 14:lstore_1 // 11 15:lload_1 // 12 16:ldc2w #24 <Long 0x4c4b40L> // 13 19:lcmp // 14 20:iflt 5 // 15 23:aload_0 // 16 24:getfield #27 <Field String myMessage> // 17 27:areturn } public void setMessage(String msg) { // 0 0:aload_0 // 1 1:aload_1 // 2 2:putfield #27 <Field String myMessage> // 3 5:return } private String myMessage; }
with javassist:public class TestClassBean { public TestClassBean() { // 0 0:aload_0 // 1 1:invokespecial #11 <Method void Object()> // 2 4:return } public String getMessage() { // 0 0:lconst_0 // 1 1:lstore_1 // 2 2:goto 15 // 3 5:lload_1 // 4 6:l2d // 5 7:invokestatic #23 <Method double Math.sqrt(double)> // 6 10:pop2 // 7 11:lload_1 // 8 12:lconst_1 // 9 13:ladd // 10 14:lstore_1 // 11 15:lload_1 // 12 16:ldc2w #24 <Long 0x4c4b40L> // 13 19:lcmp // 14 20:iflt 5 // 15 23:aload_0 // 16 24:getfield #27 <Field String myMessage> // 17 27:jsr 40 // 18 30:areturn // 19 31:astore 5 // 20 33:aconst_null // 21 34:jsr 40 // 22 37:aload 5 // 23 39:athrow // 24 40:astore_3 // 25 41:astore 4 // 26 43:getstatic #40 <Field PrintStream System.out> // 27 46:ldc1 #42 <String "Hello"> // 28 48:invokevirtual #47 <Method void PrintStream.println(String)> // 29 51:aload 4 // 30 53:ret 3 } public void setMessage(String msg) { // try 0 9 handler(s) 9 // 0 0:aload_0 // 1 1:aload_1 // 2 2:putfield #27 <Field String myMessage> // 3 5:jsr 17 // 4 8:return // finally // 5 9:astore 4 // 6 11:jsr 17 // 7 14:aload 4 // 8 16:athrow // 9 17:astore_2 // 10 18:aconst_null // 11 19:astore_3 // 12 20:getstatic #49 <Field PrintStream System.out> // 13 23:ldc1 #50 <String "Hello"> // 14 25:invokevirtual #52 <Method void PrintStream.println(String)> // 15 28:ret 2 } private String myMessage; }
this is happening in Windows XP JDK1.3 and JDK1.3.1
(in JDK1.4.1 it seems to work without problems)
p.s.: sorry that it took me so long to reply... -
4. Re: Javassist instrumented classes Performance
chiba Aug 17, 2003 2:18 AM (in response to cmanzana)Your benchmark seems unfortunately not appropriate
for capturing the overhead of Javassist. Your code
inserts System.out.println() into the loop body but
executing println() takes long time. So I think your
benchmark result showed how println() is slow.
My experiment showed that the overhead of Javassist
is less than a few nano seconds for every
instrumentation. -
5. Re: Javassist instrumented classes Performance
cmanzana Aug 17, 2003 3:13 AM (in response to cmanzana)Now I am even more puzzled:
1) System.out.println() is not that slow in JDK1.3.1 (see below for rationale)
2) this drop in performance only happens if the method is returning a value: I tried with public void getMessage() and the performance was about the same with the normal version and the "javassisted" version.
3) I changed the operation Math.sqrt() to Math.cos() (actually I tried with almost all the Math operations) and then javassist worked just fine (actually the "javassisted" version was slightly faster than the normal one, which I find rather strange)
with Math.cos():
~7 seconds normal version
~7 seconds "javassisted" version
I don't know the reasons for all these different behaviours, my guesses:
- I am doing something terribly wrong: thus I would really appreciate if someone else could try exactly the same code and tell the results
- HotSpot and the rules that govern whether parts of the code should be compiled or should be interpreted (this one is a very uninformed guess)
finally, sorry Chiba for all the trouble this is causing but for me performance is the deciding factor to whether use javassist or to use some other library (BCEL, CGLIB,...)
---------------------------------------
about System.out.println():
Sytem.out.println() is not that slow in JDK1.3.1 and actually I just tried the following:package com.test; public class TestClassBean { public String getMessage() { try { for( long i = 0; i < 5000000L; i++ ) { Math.sqrt(i); } return myMessage; } finally { System.out.println( "Hello" ); } } public void setMessage( String msg ) { myMessage = msg; } private String myMessage; }
the execution time: ~3 seconds
the dissambled code:public class TestClassBean { public TestClassBean() { // 0 0:aload_0 // 1 1:invokespecial #11 <Method void Object()> // 2 4:return } public String getMessage() { // try 0 35 handler(s) 35 // 0 0:lconst_0 // 1 1:lstore_1 // 2 2:goto 15 // 3 5:lload_1 // 4 6:l2d // 5 7:invokestatic #23 <Method double Math.sqrt(double)> // 6 10:pop2 // 7 11:lload_1 // 8 12:lconst_1 // 9 13:ladd // 10 14:lstore_1 // 11 15:lload_1 // 12 16:ldc2w #24 <Long 0x4c4b40L> // 13 19:lcmp // 14 20:iflt 5 // 15 23:aload_0 // 16 24:getfield #27 <Field String myMessage> // 17 27:astore 5 // 18 29:jsr 43 // 19 32:aload 5 // 20 34:areturn // finally // 21 35:astore 4 // 22 37:jsr 43 // 23 40:aload 4 // 24 42:athrow // 25 43:astore_3 // 26 44:getstatic #33 <Field PrintStream System.out> // 27 47:ldc1 #35 <String "Hello"> // 28 49:invokevirtual #41 <Method void PrintStream.println(String)> // 29 52:ret 3 } public void setMessage(String msg) { // 0 0:aload_0 // 1 1:aload_1 // 2 2:putfield #27 <Field String myMessage> // 3 5:return } private String myMessage; }
-
6. Re: Javassist instrumented classes Performance
cmanzana Aug 17, 2003 3:38 AM (in response to cmanzana)There was something wrong in my previous post:
>> 3) I changed the operation Math.sqrt() to Math.cos() (actually I tried with almost all the Math operations) and then javassist worked just fine (actually the "javassisted" version was slightly faster than the normal one, which I find rather strange)
I am afraid I did the test with the other Math operations when the method return value was void, when the return value is a string the results are terrible:
with Math.cos():
~7 seconds normal version
~78 seconds "javassisted" version
so point (3) from my previous mail should be discarded altogether... -
7. Re: Javassist instrumented classes Performance
chiba Aug 17, 2003 11:17 AM (in response to cmanzana)Hmm... I'm now wondering that Javassist has a minor
bug (the produced bytecode is a bit wrong) and it may
confuse HotSpot's optimizer.
I'll examine this possibility. Can you give me a few
days for this since I make a business trip on Monday
(Well, it's already on Monday here!)? -
8. Re: Javassist instrumented classes Performance
cmanzana Aug 17, 2003 11:48 PM (in response to cmanzana)of course it is not a problem that you check this in few days :)
-
9. Re: Javassist instrumented classes Performance
chiba Aug 20, 2003 12:23 PM (in response to cmanzana)I found that JDK1.3/1.4 on Solaris showed
the same slow-down you had reported.
I think this is because maybe Javassist produces
bytecode that hits a bug of HotSpot. In fact,
I could not see the problem with JDK1.4 on XP.
I modified Javassist so that it produces bytecode
that is more HotSpot friendly. Since I have already
checked the modified source files in the CVS, you
can download and examine it.
Thank you for this bug(?) report.