[jboss-dev] Interesting JBAS profiling results

[Max Rydahl Andersen]

I know i'm disconnected from the internals - but this is not news is it, 
everyone knows aop and vfs are the one spending most time (at least I 
have been told that endless times when asked how I can make AS 5 start 
as fast as AS 4) ?

What would be more interesting is to see what packages float on top 
based on how much their computational time is spent in aop/vfs ?
i.e. is it not more likely that some layers above is using vfs/aop 
wrong/badly/inefficiently ?

Just thinking out loud...

Optimizing things in vfs/aop is of course all good since that will 
benefit all, but maybe it's certain modules usage of these layers that 
are the problem.

p.s. this is similar to how I optimized hibernate startup time - if I 
just looked at the raw numbers I would blame classloading in the vm to 
be the
culprit since that is where 12-20% of our time is spent - but looking 
closer it is because Hibernates current design required full access to 
all classes
it would persist upfront, instead of doing it "on-a-need-to-know" basis. 
Unfortunately that couldn't be changed in Hibernate 3 at the time without
major breakage to public API's ....


David M. Lloyd wrote:
> I was talking to Jason G on the phone, and he had an interesting idea: 
> what happens when we profile the AS and look at the results by package 
> rather than method?  This should give us a rough idea, by project, of 
> where our startup time is being spent.  So I took a couple minutes and 
> did just that, with some interesting results.
>
> First, results for a minimal startup (results under 2% omitted):
>
> 9.7% - 2,418 ms - 41,306 hot spot inv. org.jboss.aop.pointcut
> 8.3% - 2,063 ms - 38,480 hot spot inv. 
> org.jboss.reflect.plugins.introspection
> 5.9% - 1,461 ms - 373,799 hot spot inv. org.jboss.aop
> 5.7% - 1,415 ms - 52,528 hot spot inv. 
> org.jboss.virtual.plugins.context.zip
> 5.7% - 1,411 ms - 294,922 hot spot inv. org.jboss.virtual.plugins.context
> 5.0% - 1,245 ms - 672,024 hot spot inv. org.jboss.aop.pointcut.ast
> 3.6% - 893 ms - 7,928 hot spot inv. org.jboss.classloader.spi.base
> 3.0% - 735 ms - 17,241 hot spot inv. org.jboss.dependency.plugins
> 2.9% - 720 ms - 20,215 hot spot inv. org.jboss.aop.util
> 2.8% - 697 ms - 150,242 hot spot inv. org.apache.log4j
> 2.6% - 636 ms - 272,879 hot spot inv. org.jboss.reflect.plugins
> 2.2% - 550 ms - 72,341 hot spot inv. org.jboss.metadata.plugins.context
>
> As you can see, a minimal startup is dominated by AOP with VFS being a 
> not-so-close second.
>
> Next, a default startup, which shows somewhat different behavior:
>
> 10.5% - 25,156 ms - 5,827,279 hot spot inv. 
> org.jboss.virtual.plugins.context
> 8.5% - 20,320 ms - 1,232,357 hot spot inv. 
> org.jboss.virtual.plugins.context.zip
> 6.6% - 15,822 ms - 1,054,169 hot spot inv. 
> org.jboss.virtual.plugins.vfs.helpers
> 6.4% - 15,319 ms - 297,465 hot spot inv. org.jboss.aop.pointcut
> 5.9% - 14,256 ms - 237,457 hot spot inv. org.jboss.dependency.plugins
> 5.1% - 12,148 ms - 6,769,258 hot spot inv. org.jboss.metadata.spi.scope
> 4.7% - 11,254 ms - 72,717 hot spot inv. javassist.bytecode
> 4.2% - 10,132 ms - 8,205,516 hot spot inv. org.jboss.dependency.spi
> 3.5% - 8,426 ms - 2,308,354 hot spot inv. org.jboss.aop
> 3.2% - 7,713 ms - 4,109,176 hot spot inv. org.jboss.aop.pointcut.ast
> 2.7% - 6,575 ms - 182,581 hot spot inv. 
> org.jboss.reflect.plugins.introspection
> 2.7% - 6,366 ms - 52,818 hot spot inv. org.jboss.classloader.spi.base
> 2.2% - 5,284 ms - 333,613 hot spot inv. org.jboss.mx.server
>
> VFS, AOP, metadata, classloading.  If I separate out filtered classes, 
> it's basically the same story:
>
> 17.4% - 42,348 ms - 53,786,066 hot spot inv. java.lang
> 8.4% - 20,408 ms - 5,827,335 hot spot inv. 
> org.jboss.virtual.plugins.context
> 8.2% - 19,943 ms - 21,005,518 hot spot inv. java.util
> 5.6% - 13,706 ms - 1,232,359 hot spot inv. 
> org.jboss.virtual.plugins.context.zip
> 4.5% - 11,068 ms - 297,465 hot spot inv. org.jboss.aop.pointcut
> 3.5% - 8,531 ms - 72,717 hot spot inv. javassist.bytecode
> 3.4% - 8,266 ms - 6,769,258 hot spot inv. org.jboss.metadata.spi.scope
> 3.3% - 8,106 ms - 1,054,287 hot spot inv. 
> org.jboss.virtual.plugins.vfs.helpers
> 3.2% - 7,754 ms - 237,461 hot spot inv. org.jboss.dependency.plugins
> 2.8% - 6,787 ms - 8,205,588 hot spot inv. org.jboss.dependency.spi
> 2.4% - 5,964 ms - 2,308,354 hot spot inv. org.jboss.aop
> 2.3% - 5,524 ms - 52,818 hot spot inv. org.jboss.classloader.spi.base
> 2.2% - 5,316 ms - 4,109,176 hot spot inv. org.jboss.aop.pointcut.ast
>
> So it looks to me like we ought to be focusing our optimization 
> efforts on VFS and AOP, maybe classloading as well.  I encourage folks 
> to play around with profiling this way; it's fairly illuminating.
>
> - DML
>
> _______________________________________________
> jboss-development mailing list
> jboss-development at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/jboss-development