9 Replies Latest reply on Aug 20, 2003 12:23 PM by chiba

    Javassist instrumented classes Performance

    cmanzana

      While checking the overhead of javassist instrumented classes, I have found the following:

      Having the following classes:

      public class TestClass {
      public String test() {
       for( long i = 0; i < 10000000L; i++ ) {
       Math.sqrt(i);
       }
       }
      }

      and

      public class Checker {
       public static void main( String args[] ) {
       TestClass tc = new TestClass();
       for( int i = 0; i < 5; i++ ) {
       tc.test();
       }
       }
      }

      I used the following manipulation approaches:
      a)
      ExprEditor exprEditor = new ExprEditor() {
       public void edit( MethodCall m ) throws CannotCompileException {
       if ( m.getClassName().equals( "TestClass" ) ) {
       m.replace(
       "{" +
       "long start = System.currentTimeMillis();" +
       "$_ = $proceed($$);" +
       "long elapsed = System.currentTimeMillis() - start );" +
       "System.out.println( elapsed );" +
       "}" );
       }
       }
       };

      b)
      ExprEditor exprEditor = new ExprEditor() {
       public void edit( MethodCall m ) throws CannotCompileException {
       if ( m.getClassName().equals( "TestClass" ) ) {
       m.replace(
       "{" +
       "long start = System.currentTimeMillis();" +
       "$_ = $proceed($$);" +
       "System.out.println( System.currentTimeMillis() - start );" +
       "}" );
       }
       }
       };

      The results of executing Checker were:
      a)
      594
      1062
      1094
      1047
      1047

      b)
      625
      562
      563
      593
      563

      this happens as well when using insertAfter() instead of instrument()

      it seems to me like javassist has problems defining local variables at the end of a method body (the performance of executing the instrumented method doubles!)

      I am curious to know why that is happening. Also I am not sure what way jBoss is using javassist but I think it can be quite likely that it might suffer a big performance penalty for instrumenting code

      By the way for the tests I was using JRE1.3.1 and javassist 2.5


        • 1. Re: Javassist instrumented classes Performance
          chiba

          This result seems weird... I'll check this.
          Basically, the overhead due to Javassist
          is quite small.

          • 2. Re: Javassist instrumented classes Performance
            chiba

            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

              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

                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

                  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

                    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

                      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

                        of course it is not a problem that you check this in few days :)

                        • 9. Re: Javassist instrumented classes Performance
                          chiba

                          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.