[jboss-dev] Interesting JBAS profiling results

Fri Jun 19 08:25:08 EDT 2009

Thanks for checking.  I set a breakpoint in the 
"LongRunningTasksThreadPool" and it executed in sub-second time.  So, 
its not the "org.jboss.threads.JBossExecutors.threadFactoryExecutor" 
that initializes the thread pool. 

At this point, my plan of attack is to try instrumenting code (maybe 
using jamon) along the relevant call stack (see 
http://pastebin.com/m285cebc4).  We are also trying to profile as well.

Jaikiran Pai wrote:
> Strange! I see this too in the "all" profile. Attached is the .zip 
> file. Interestingly almost all the deployments now show a noticeable  
> increased processing time. I wonder if the "all" profile contains some 
> deployer which probably picks up this deployments and does some 
> expensive operations. Even the DefaultDS binding deployment takes 
> around 9 seconds.
>
> -Jaikiran
>
>
> Scott Marlow wrote:
>> For comparison, here are "all" numbers from my laptop  
>> http://pastebin.com/m21a0bdf5
>>
>> "
>> LongRunningTasksThreadPool  3304
>> jboss.jca:name=DefaultDS,service=DataSourceBinding  9423
>> "
>>
>>
>> Jaikiran Pai wrote:
>>> I am running the default profile. I'll get the numbers for "all" 
>>> profile. I can then compare them against my numbers for the default 
>>> profile.
>>>
>>> On a related note, i guess using the default profile for testing the 
>>> performance would be a good idea because that's what most users are 
>>> interested in.
>>>
>>> P.S: Once the MC and other component upgrade happens in the trunk we 
>>> might see some different  (hopefully better) numbers.
>>>
>>> -Jaikiran
>>>
>>> Scott Marlow wrote:
>>>> 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
>>>>>
>>>>
>>>
>>