7 Replies Latest reply on Sep 3, 2003 2:10 AM by erlendboe

    Simple timings vs AspectJ

    erlendboe Newbie

      I just did some simple, unscientific timings of example1 using jboss AOP standalone

      timings done with "time" (include java startup time ,etc)
      POJO:
      0.210u 0.100s 0:00.40 77.5% 0+0k 0+21io 0pf+0w

      POJO-JBoss-AOP:
      1.490u 0.350s 0:02.28 80.7% 0+0k 0+0io 0pf+0w

      POJO-AspectJ:
      0.300u 0.110s 0:00.47 87.2% 0+0k 0+23io 0pf+0w

      JBoss-AOP over 7 times slower than POJO, over 4.9 times slower than ASpectJ.
      Please note that comparing directly to POJO is meaningless, as it writes a lot less to the console!

      I make it call helloWorld 100 and 10000 times. Here are the results:
      POJO:
      0.240u 0.080s 0:00.84 38.0% 0+0k 0+0io 0pf+0w (100)
      0.490u 0.150s 0:01.95 32.8% 0+0k 0+9io 0pf+0w (10000)

      POJO-JBOSS-AOP:
      1.760u 0.280s 0:03.78 53.9% 0+0k 1+21io 0pf+0w(100)
      2.410u 0.760s 0:09.60 33.0% 0+0k 0+9io 0pf+0w (10000)

      POJO-AspectJ:
      0.340u 0.100s 0:00.94 46.8% 0+0k 2+1io 0pf+0w (100)
      1.060u 0.510s 0:07.45 21.0% 0+0k 0+0io 0pf+0w (10000)

      JBoss-AOP 7.3 (100), 4.9 (10000) times slower than POJO, 5 (100), 2.3 (10000) times slower than AspectJ

      To complete the tests, I inserted calls to System.currentTimeMillis() before and after the calls to helloWorld

      for 10000 calls I get:
      POJO: 1850 millis, POJO-JBOSS-AOP: 6350, POJO-AspectJ: 6310

      Now, I know that these are just some very very quick tests, but I still think they show that the speed of JBoss-AOP is comparable to AspectJ, but that there is a heavy start-up price to pay (not so suprising since it has to parse an XML file)

      Erlend

        • 1. Re: Simple timings vs AspectJ
          Andy Godwin Newbie

          > I just did some simple, unscientific timings of
          > example1 using jboss AOP standalone

          Interesting stuff, Erlend, I've been meaning to do
          some similar rough tests to get a feeling for the
          performance.

          > JBoss-AOP over 7 times slower than POJO, over 4.9
          > times slower than ASpectJ.
          > Please note that comparing directly to POJO is
          > meaningless, as it writes a lot less to the console!

          Beware writing to the console :) Seriously, tho, as an
          example, when I shutdown JBoss, if the console is
          visible, and scrolling furiously, it takes about 20
          seconds, but if I obscure the console with another
          window it takes about 4!

          > Now, I know that these are just some very very quick
          > tests, but I still think they show that the speed of
          > JBoss-AOP is comparable to AspectJ, but that there is
          > a heavy start-up price to pay (not so suprising since
          > it has to parse an XML file)
          >
          > Erlend

          The start up price is, for better or for worse, inevitable.
          AspectJ uses a compilation step to achieve what JBoss
          does at runtime. It's analogous to the EJB compilation
          done by a lot of other app server vendors.

          • 2. Re: Simple timings vs AspectJ
            Rickard Öberg Newbie

            I would like to know what hardware and JVM you are using. The POJO test gives you 0.185ms/call, which is a very high number. For comparison, when I run a similar "hello world" test on our own AOP framework on a 1.7GHz/JRockit 8 setup I get about 0.007ms/call, and that's with a couple of advice being invoked as well.

            Can you tell us the setup you're using, and also try running it 500000 times in order to make sure that the timings are more stable?

            • 3. Re: Simple timings vs AspectJ
              erlendboe Newbie

              Rickard,

              I have an apple PowerBook G4, 867Mhz with 768 MB ram.
              JVM: 1.4.1_01 from apple/SUN

              for 500000 times I get:
              POJO: between 40333 (first time) and 52542.
              Example:
              Time: 50785
              5.660u 4.130s 0:51.27 19.0% 0+0k 0+17io 0pf+0w

              changing POJO to write the time to std. err, and redirecting stdout to /dev/null gives:
              Time: 8928
              4.680u 2.360s 0:09.42 74.7% 0+0k 0+0io 0pf+0w

              A VERY different result..

              With JBoss-AOP I get:
              Time: 229326
              Leaving method: main
              31.990u 15.910s 3:52.28 20.6% 0+0k 1+21io 0pf+0w
              (about 4.5 times slower than POJO)

              with JBoss-AOP /dev/null I get:
              Time: 45075
              27.880u 7.850s 0:47.35 75.4% 0+0k 0+21io 0pf+0w
              (Time: 5 times slower than POJO /dev/null)

              With ASpectJ I get:
              Time: 240749
              33.780u 15.750s 4:01.24 20.5% 0+0k 0+1io 0pf+0w
              (about 4.7 times slower than POJO)

              With ASpectJ /dev/null I get:
              Time: 41401
              28.040u 7.210s 0:41.90 84.1% 0+0k 0+21io 0pf+0w
              (about 4.6 times slower than POJO /dev/null)

              after seeing these big differences/problems with using console output, I changed pojo to print 3 lines in helloWorld, so that it prints a similar amout to the console as the JBoss-AOP and AspectJ version.

              For this changed POJO I get:
              Time: 159985
              17.340u 13.720s 2:40.36 19.3% 0+0k 0+21io 0pf+0w

              and for >/dev/null I get:
              Time: 27108
              14.230u 6.420s 0:27.50 75.0% 0+0k 0+6io 0pf+0w

              (=> AOP-JBoss 1.4 times POJO, 1.66 POJO /dev/null,
              Aspect J: 1.5 times POJO, 1.52 POJO /dev/null

              So I think this shows that I can stop worrying about JBoss-AOP being slower than AspectJ, or "too slow"

              (It seems to me that it also shows that the value of doing timings is very limited.. at least for timings that write to the console..)

              • 4. Re: Simple timings vs AspectJ
                gregork Newbie

                Could you post the AspectJ code?

                • 5. Re: Simple timings vs AspectJ
                  erlendboe Newbie

                  The aspect is trivial... I have included it below:
                  =============================
                  aspect POJOAspect {

                  pointcut myConstructor(): within(POJO) && execution(new(..));
                  pointcut myMethod(): within(POJO) && execution(* *(..));

                  before(): myConstructor() {
                  System.out.println("Before constructor: " + thisJoinPointStaticPart.getSignature());
                  }

                  after(): myConstructor() {
                  System.out.println("After constructor: " + thisJoinPointStaticPart.getSignature());

                  }

                  before(): myMethod() {
                  System.out.println("Before method: " + thisJoinPointStaticPart.getSignature());
                  }

                  after(): myMethod() {
                  System.out.println("After method: " + thisJoinPointStaticPart.getSignature());
                  }
                  }

                  • 6. Re: Simple timings vs AspectJ
                    gregork Newbie

                    Well you said simple and unscientific, so perhaps I shouldn't compain.

                    But since Bill's interview could be interpreted to suggest that this code measures AOP overhead, there's a couple of things to say about the code.

                    - You should change after to after returning.

                    - It measures string concatenation, not AOP overhead. To measure AOP overhead, make the advice bodies null. That's the equivalent of the null method dispatch test that is one measure of OO performance.

                    • 7. Re: Simple timings vs AspectJ
                      erlendboe Newbie

                      I agree that my test is not exactly that scientific, and I was suprised too to see that it was used as "proof"... thats also why I wrote that disclaimer, to make sure that nobody would use it in that way...

                      I'm also suprised that nobody else has made some better tests and published the results..

                      I remember reading somewhere that thisJoinPoint (and maybe) thisJoinPointStaticPart is the slowest part of AspectJ, so I guess my test is a "worst-case" scenario for AspectJ anyway.

                      Its no secret which AOP I plan to use in my next project: AspectJ - of course !

                      I think that the success of JBoss is based on one thing only: Convenience (very easy to deploy your application)
                      ... and thats part of the reason why they have made their own AOP.

                      I hope that you will move AspectJ in this direction, with emphasis on ease of use.


                      Erlend
                      -Another happy customer