After today's "svn up" of my workspace, i see that the "default" instance boot in around 48 to 50 seconds: 19:10:18,431 INFO [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r99718)] Started in 48s:36ms The only noticeable change that i have seen is related to admin-console being included in AS trunk. So i removed the admin-console.war from the deploy folder and the server boots in 23 to 25 seconds. Adding it back to deploy folder takes the boot time to 48 to 50 seconds consistently. I haven't yet looked at where the time is being spent for deploying this single app. But clearly it increases the boot time by almost 25 seconds. Anyone else seeing this drastic change in boot time? regards, -Jaikiran _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

After today's "svn up" of my workspace, i see that the "default" instance boot in around 48 to 50 seconds: 19:10:18,431 INFO [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r99718)] Started in 48s:36ms The only noticeable change that i have seen is related to admin-console being included in AS trunk. So i removed the admin-console.war from the deploy folder and the server boots in 23 to 25 seconds. Adding it back to deploy folder takes the boot time to 48 to 50 seconds consistently. I haven't yet looked at where the time is being spent for deploying this single app. But clearly it increases the boot time by almost 25 seconds. Anyone else seeing this drastic change in boot time? regards, -Jaikiran _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

One thing I'm looking at is tagging the console's web.xml as metadata complete. I'm seeing a ton of logging from WarAnnotationMetaDataDeployer. On 01/21/2010 08:23 AM, Dimitris Andreadis wrote: > Yeap, it's horribly slow. We need to do the same exercise and bring this overhead > considerably down, or it cancels all the boot gains so far. > > Jaikiran Pai wrote: >> After today's "svn up" of my workspace, i see that the "default" >> instance boot in around 48 to 50 seconds: >> >> 19:10:18,431 INFO [org.jboss.bootstrap.impl.base.server.AbstractServer] >> JBossAS [6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT >> date=r99718)] Started in 48s:36ms >> >> The only noticeable change that i have seen is related to admin-console >> being included in AS trunk. So i removed the admin-console.war from the >> deploy folder and the server boots in 23 to 25 seconds. Adding it back >> to deploy folder takes the boot time to 48 to 50 seconds consistently. I >> haven't yet looked at where the time is being spent for deploying this >> single app. But clearly it increases the boot time by almost 25 seconds. >> >> Anyone else seeing this drastic change in boot time? >> >> regards, >> -Jaikiran >> _______________________________________________ >> 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 took a shot at getting deployment of our standard webapps out of the main boot sequence, triggering deployment when a user request comes in instead. That cut 18 seconds out of the "default" config boot. For details, please see http://community.jboss.org/thread/147220 . Feedback appreciated.

Rémy Maucherat wrote, On 01/24/2010 08:51 PM (EEST): > On Sun, Jan 24, 2010 at 7:02 PM, Brian Stansberry > <brian.stansberry(a)redhat.com&gt; wrote: >> I took a shot at getting deployment of our standard webapps out of the >> main boot sequence, triggering deployment when a user request comes in >> instead. That cut 18 seconds out of the "default" config boot. For >> details, please see http://community.jboss.org/thread/147220 . Feedback >> appreciated. > You implemented exactly what I thought I would do if I was > implementing this. But I still hate it. As much as I hate Windows > delayed - background - on-demand boot compared with my honest Fedora > boot. Why hate it? Why load something in memory (and lose time for it) if it is not going to be used or is only to be used if need arises? Why user should go disabling stuff manually when user can have them in case he needs them but not lose time and memory for them when he doesn't? Should every jboss user know which services are safe to be removed and should every user spend time to do it? Also I'm not sure windows use cases are comparable to jboss AS use cases but that's another topic. _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

I don't believe you. I did the same, except, I deleted all the .WAR files. I only got a few seconds improvement (maybe 2-3 seconds). Brian Stansberry wrote: > On 01/21/2010 09:41 AM, Brian Stansberry wrote: >> That shaved 2 secs on my machine: from 46.2 to 44.2. >> >> https://jira.jboss.org/jira/browse/EMBJOPR-277 >> >> Nice, but peanuts in the big picture. We'll never get to below 10 secs >> if we can't get most of the work initializing this app off the critical >> path. >> > I took a shot at getting deployment of our standard webapps out of the > main boot sequence, triggering deployment when a user request comes in > instead. That cut 18 seconds out of the "default" config boot. For > details, please see http://community.jboss.org/thread/147220 . Feedback > appreciated. >

On Mon, Jan 25, 2010 at 2:54 PM, Bill Burke <bburke(a)redhat.com&gt; wrote: > I don't believe you. I did the same, except, I deleted all the .WAR > files. I only got a few seconds improvement (maybe 2-3 seconds). We added the deploy/admin-console.war in the default profile. Do you have that ? That's the thing using up all the deployment time. I agree the other WARs are not very significant. Rémy _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

One thing I'm looking at is tagging the console's web.xml as metadata complete. I'm seeing a ton of logging from WarAnnotationMetaDataDeployer.

I got 2 secs from adding metadata-complete=true. But that was hardly a scientific test. Anyway, IMO just as a general practice anything we ourselves deploy should be metadata complete. We should optimize our stuff for boot perf, not for convenience of our own folks developing it.

> I think we could have a proprietary "does not contain annotations" > flag, because metadata-complete does not mean that. That's exactly what Emanuel's post does: --- Can you try to exclude the admin-console from annotation scanning and see if that helps? in deployers/metadata-deployer-jboss-beans.xml <entry> <key>admin-console.war</key> <value><null/></value> </entry> --- _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

>> I think we could have a proprietary "does not contain annotations" >> flag, because metadata-complete does not mean that. > That's exactly what Emanuel's post does: > > --- > Can you try to exclude the admin-console from annotation scanning and > see if that helps? > > in deployers/metadata-deployer-jboss-beans.xml > > <entry> > <key>admin-console.war</key> > <value><null/></value> > </entry> Don't we want to do that in the "war" somehow? - the one that writes the application knows if he need annotation -

>>> in deployers/metadata-deployer-jboss-beans.xml >>> >>> <entry> >>> <key>admin-console.war</key> >>> <value><null/></value> >>> </entry> >> Don't we want to do that in the "war" somehow? - the one that writes the >> application knows if he need annotation - > That's what jboss-scanning.xml does. ;-) > * http://www.jboss.org/community/docs/DOC-13178 > Glad you brought that up; I tried that and IIRC only got about 1/2 the gain I did with Emanuel's approach. Which I found quite odd.

Remy can't use the AnnotationEnvironment/AnnotationRepository - since this does not support the Servlet 3.0 features - like excluding fragments. So he is currently stuck with the original annotation scanning thingy, which we replaced over a year ago since it was way too slow.

Rémy Maucherat wrote: > On Thu, Jan 21, 2010 at 4:18 PM, Brian Stansberry > <brian.stansberry(a)redhat.com&gt; wrote: >> One thing I'm looking at is tagging the console's web.xml as metadata >> complete. I'm seeing a ton of logging from WarAnnotationMetaDataDeployer. > > Disabling that does not really disable annotation scanning anymore: it > only disables annotations which add to the web.xml metadata (= mostly > the new ones from Servlet 3.0). So does this new semantic apply on to 3.0 web-app? Or does it even apply to a 2.5 web-app (like admin-console)?

There's a jboss-scanning.xml that can be added in a war's META-INF. But deployers have to be written to understand that.

After today's "svn up" of my workspace, i see that the "default" instance boot in around 48 to 50 seconds: 19:10:18,431 INFO [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r99718)] Started in 48s:36ms The only noticeable change that i have seen is related to admin-console being included in AS trunk. So i removed the admin-console.war from the deploy folder and the server boots in 23 to 25 seconds. Adding it back to deploy folder takes the boot time to 48 to 50 seconds consistently. I haven't yet looked at where the time is being spent for deploying this single app. But clearly it increases the boot time by almost 25 seconds. Anyone else seeing this drastic change in boot time? regards, -Jaikiran _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

On 01/21/2010 09:55 AM, Brian Stansberry wrote: > Next up, get rid of the 20.6MB of boot.log that's created when this app > is deployed. (Even w/o it, our boot.log was ridiculously big, IIRC> 7MB.) > > Adding -Djboss.boot.server.log.level=INFO (see [1]) cuts another 4 secs, > down to 40.2. If you also add -Djboss.server.log.threshold=INFO as well (which makes little difference in total output, but filters log messages much sooner), you might gain a couple more seconds (mine went from 44 to 42).

On 01/21/2010 10:41 AM, David M. Lloyd wrote: > On 01/21/2010 10:39 AM, David M. Lloyd wrote: >> On 01/21/2010 09:55 AM, Brian Stansberry wrote: Semi-OT: a couple weeks ago, when boot.log was< 10MB I tried setting -Djboss.boot.server.log.level=INFO and got very little improvement in boot time (< 200ms). My take on that is we must have a lot of DEBUG logging with very expensive message construction not guarded by isDebugEnabled().

On 01/21/2010 11:20 AM, Brian Stansberry wrote: > On 01/21/2010 10:41 AM, David M. Lloyd wrote: >> On 01/21/2010 10:39 AM, David M. Lloyd wrote: >>> On 01/21/2010 09:55 AM, Brian Stansberry wrote: > > Semi-OT: a couple weeks ago, when boot.log was< 10MB I tried setting > -Djboss.boot.server.log.level=INFO and got very little improvement in > boot time (< 200ms). My take on that is we must have a lot of DEBUG > logging with very expensive message construction not guarded by > isDebugEnabled(). > John Bailey did some quick profiling or something and estimated that during startup we have > 5000 log.debug() calls not guarded by log.isDebugEnabled(). If you look at the debug logging output, a lot of the messages are pretty heavy, some absolutely huge; if those aren't guarded it's a serious cost. Warning: the rest of this post is completely unsupported by evidence; just my gut feel. Perhaps not guarded because that method is deprecated? Here's a good explanation of why it's deprecated: http://blogs.jboss.org/blog/dimitris/2005/04/01/AC08547736BD16504BEC955AE... I fear though that deprecating this method is a failed social experiment. Please resist the urge to make that deprecation warning go away by not putting a code guard around an expensive log.debug(). Either reduce the level to trace (and keep a guard of course) or accept the warning and bitch publicly about the deprecation. Please also resist the urge to shift off of EE 6 work in order to scour all our code for logging cleanups. :) -- Brian Stansberry Lead, AS Clustering JBoss by Red Hat _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

I don't know if John has that sort of info. He came up with numbers real quickly so I suspect he did something simple like profile a boot and look at the # of invocations of Logger.debug(). vs Logger.isDebugEnabled(). A simple thing to do is start the AS with -Djboss.boot.server.log.level=DEBUG. Scroll through the log looking for the numerous places where the contents of a classloader domain are logged, filling up a couple screens. If those aren't guarded -- bad. ;) On 01/21/2010 05:01 PM, Ales Justin wrote: > Is there a way we could pull out some stats? > e.g. # of debug calls per package/ class/log_owner > > This way the biggest culprits could check, and fix things. > e.g. we used to have some heavy debug log in deployers > > Although I guess the bad pieces are those where we loose time to > construct msg, which are not stats "bounty". > At least not with the old logging, w/o argvars. > > Sent from my iPod > > On 21.1.2010, at 23:50, Brian Stansberry&lt;brian.stansberry(a)redhat.com&gt; > wrote: > >> On 01/21/2010 11:20 AM, Brian Stansberry wrote: >>> On 01/21/2010 10:41 AM, David M. Lloyd wrote: >>>> On 01/21/2010 10:39 AM, David M. Lloyd wrote: >>>>> On 01/21/2010 09:55 AM, Brian Stansberry wrote: >>> >>> Semi-OT: a couple weeks ago, when boot.log was< 10MB I tried setting >>> -Djboss.boot.server.log.level=INFO and got very little improvement in >>> boot time (< 200ms). My take on that is we must have a lot of DEBUG >>> logging with very expensive message construction not guarded by >>> isDebugEnabled(). >>> >> >> John Bailey did some quick profiling or something and estimated that >> during startup we have> 5000 log.debug() calls not guarded by >> log.isDebugEnabled(). If you look at the debug logging output, a lot >> of >> the messages are pretty heavy, some absolutely huge; if those aren't >> guarded it's a serious cost. >> >> Warning: the rest of this post is completely unsupported by evidence; >> just my gut feel. >> >> Perhaps not guarded because that method is deprecated? >> >> Here's a good explanation of why it's deprecated: >> >> http://blogs.jboss.org/blog/dimitris/2005/04/01/AC08547736BD16504BEC955AE... >> >> I fear though that deprecating this method is a failed social >> experiment. Please resist the urge to make that deprecation warning go >> away by not putting a code guard around an expensive log.debug(). >> Either >> reduce the level to trace (and keep a guard of course) or accept the >> warning and bitch publicly about the deprecation. >> >> >> Please also resist the urge to shift off of EE 6 work in order to >> scour >> all our code for logging cleanups. :) >> >> -- >> Brian Stansberry >> Lead, AS Clustering >> JBoss by Red Hat >> _______________________________________________ >> 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 -- Brian Stansberry Lead, AS Clustering JBoss by Red Hat _______________________________________________ jboss-development mailing list jboss-development(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jboss-development

> > Please also resist the urge to shift off of EE 6 work in order to scour > all our code for logging cleanups. :) > If you happen to notice any loggers that are created as instance variables, please consider changing them to class (static) variables. You can check in these changes against JBAS-7291. The last time I looked (early last fall), 6MB of memory was used by 109,552 instances of org.jboss.logging.Logger.

FWIW. In profiling JBoss Messaging a couple years ago, we found out that not only does the log.debug() (or log.trace()) have an overhead, but the actual call to log.isDebugEnabled()/ log.isTraceEnabled() had a measurable impact.

On 01/21/2010 10:39 AM, David M. Lloyd wrote: > On 01/21/2010 09:55 AM, Brian Stansberry wrote: > >> Question: should INFO be the default for boot.log? >> >> My opinion is yes. > > Then perhaps the global threshold should also be INFO. > You mean the root logger level in deploy/jboss-logging.xml? I changed the default for that to INFO last night. It was INFO in M1, 5.1, maybe 5.0.