[jboss-dev] Interesting JBAS profiling results

Jaikiran Pai jpai at redhat.com
Fri Jun 19 13:38:58 EDT 2009 

Scott Marlow wrote:
> 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.
Actually that's not what is taking time. Looking at the code which 
generates the statistics for these deployers, it accumulates the timings 
of each deployment against each deployer. So the output that we see is 
for the org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer 
which is taking more than 3 seconds for this deployment. Also remember 
that these 3 seconds might be in separate batches too, since the 
statistics is just an addition of the time taken by each batch (if any).

regards,
-Jaikiran

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

More information about the jboss-development mailing list