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

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

Jaikiran Pai wrote: > 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. Just updated AS trunk and i see that there are *no* EJB3 beans being deployed (not even profile service beans). So 1 second for deploying nothing doesn't seem right. I'll see what causes this.

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

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 >

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

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

How about something simple to solve the AOP problem immediately? Like a META-INF/.no-aop file where if there, no AOP matching is done on any class in there. 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 > > > ------------------------------------------------------------------------ > > _______________________________________________ > jboss-development mailing list > jboss-development(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/jboss-development

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

Max Rydahl Andersen wrote: > I know i'm disconnected from the internals - but this is not news > is it, everyone knows aop and vfs are the one spending most time > (at least I have been told that endless times when asked how I can > make AS 5 start as fast as AS 4) ? Well we knew we had issues there, but we did not definitively know if there were other factors. These numbers seem to suggest the hunch is accurate. > What would be more interesting is to see what packages float on top > based on how much their computational time is spent in aop/vfs ? > i.e. is it not more likely that some layers above is using vfs/aop > wrong/badly/inefficiently ? > Just thinking out loud... Yes, we should do that as well. > Optimizing things in vfs/aop is of course all good since that will > benefit all, but maybe it's certain modules usage of these layers > that are the problem. > This is most likely the case with at least the VFS issues, since we know that we have multiple passes happening from calling code. We have to look at the AOP usage in more detail, and try and remove it from areas where it's not really needed. > p.s. this is similar to how I optimized hibernate startup time - if > I just looked at the raw numbers I would blame classloading in the > vm to be the > culprit since that is where 12-20% of our time is spent - but > looking closer it is because Hibernates current design required > full access to all classes > it would persist upfront, instead of doing it "on-a-need-to-know" > basis. Unfortunately that couldn't be changed in Hibernate 3 at the > time without > major breakage to public API's .... Ugh. Yeah, catching/correcting these issues long after major releases is always a pain. -- Jason T. Greene JBoss, a division of Red Hat _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development