Re: [jboss-dev] Interesting JBAS profiling results

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(a)lists.jboss.org >>>>>> https://lists.jboss.org/mailman/listinfo/jboss-development >>>>> >>>>> >>>> >>>> _______________________________________________ >>>> jboss-development mailing list >>>> jboss-development(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/jboss-development >>> >> >