[jboss-dev] Interesting JBAS profiling results

[Scott Marlow]

Jaikiran,

Are you running the default profile?  I am currently running "all" and 
seeing about 3.5 seconds for "LongRunningTasksThreadPool".

Could you please try running with the "all" config and share how much 
time you see "LongRunningTasksThreadPool" taking to deploy? 

Thank you!

Scott

Jaikiran Pai wrote:
> The latest numbers (from my laptop) as of Wednesday night against AS 
> trunk are here http://pastebin.com/fc3a7ad0 (also attached is the html 
> version). The WARDeployer which in it's start() method just does a 
> web.xml parsing through JBossXB seems to be taking 713 milli seconds 
> which seems to be on a higher side. There are other things like 
> TransactionManager too which are taking time (probably because the 
> configuration file involves usage of @JMX which triggers AOP?).
>
> I also got the number of deployers per stage that are currently used 
> in AS trunk. The output is attached.
>
> -Jaikiran
>
>
> Scott Marlow wrote:
>> FYI,  http://pastebin.com/m7325e91f   contains a breakdown of how 
>> long each component took to deploy in milliseconds (with trunk source 
>> as of this morning).
>> Scott Marlow wrote:
>>> It might also be interesting to see what the total deployment time 
>>> is per bean and how that might relate to the timings below.  Do we 
>>> have a way to do that (maybe via an interceptor)?
>>>
>>> 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
>>>
>>>
>>
>> _______________________________________________
>> jboss-development mailing list
>> jboss-development at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/jboss-development
>