Re: [jboss-dev] Interesting JBAS profiling results

org.jboss.ejb3.deployers.Ejb3Deployer@1ec264c 1370 -- vfsfile:/work/as/trunk/build/output/jboss-6.0.0.Alpha1/server/default/deploy/ejb3-interceptors-aop.xml 790 1 second in the Ejb3Deployer for just the profile service beans is a bit too much.

However, (as shown above) i think the real time is spent in the -aop.xml which gets triggered by this deployer. I will get some profiler snapshots for the trunk today - i wasn't doing anything against the trunk so far since the components in trunk are still not updated. regards, -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 _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development