[jboss-dev] Interesting JBAS profiling results

[Jaikiran Pai]

The last time i had looked at the AS profiling snapshot, i remember 
seeing VFS and classloading as the ones, where most of the time was 
being spent. Specifically in VFS, IIRC it was some PatternMatcher (which 
gets used even during classloading through VFS' DeploymentUnitClasspath) 
which was getting called too many times. As for classloading, i did try 
to isolate the issue, but could not spend enough time there. I remember 
it was doing something on the lines of scheduling a task for loading 
each class, i wasn't able to isolate the issue with a small application.

Overall, the slowdown starts from the point where MC starts passing each 
deployer and each deployment (which are ultimately MC beans) through its 
various lifecycle phases. During this process it does a whole lot of 
annotation scanning and also a lot of operations using reflection. I was 
planning to spend some time this week trying to get more details on 
this, but haven't been able to do so yet. I'll update this thread or 
create a new forum thread if i find anything new.

-Jaikiran

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