Simple timings vs AspectJ

[erlendboe]

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

[andygodwin]

> 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.

[rickardoberg]

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?

[erlendboe]

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..)

[gregork]

Could you post the AspectJ code?

[erlendboe]

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());
}
}

[gregork]

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.

[erlendboe]

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