[jboss-dev] Re: Bootstrap times

[Adrian Brock]

I guess this didn't get through the spam filter because
of the attachments? :-)

On Tue, 2008-09-09 at 15:56 +0200, Adrian Brock wrote:
> After Sacha's "the AS is hanging" thread
> last week, I've created some simple stats
> to show the times spent in deployers
> and the microcontainer state transfers.
> 
> See attached for the full stats
> (this is the default configuration).
> 
> DEPLOYERS
> 
> For the deployers you can see
> the big hits are in the expected
> bean and jmx deployers which do
> most of the work.
> 
> Other hits include annotation scanning,
> classloader creation and surprisingly
> the ejb3 deployer (there are no ejb3 deployments? :-).
> 
> ANNOTATION DEPLOYER
> 
> Drilling down in the annotation scanning,
> you can see most time is spent in
> jbossweb.sar, console-mgr.sar and jbossws.sar
> Making these metadata complete would knock
> something like 7-8 seconds off the bootstrap time.
> 
> CLASSLOADER DEPLOYER
> 
> Most of the time in the classloader bucket
> is spent processing conf/jboss-service.xml
> so this is a function of the number of jars
> in server/default/lib, i.e. determining
> what packages they contain.
> 
> EJB3 DEPLOYER
> 
> A lot of time in the EJB3 bucket is taken on
> jbossweb.sar (nearly a second?), but
> there are others where it is taking upto
> a quarter of second.
> 
> RAR PARSER DEPLOYER
> 
> Although, it doesn't take much time,
> this looks less efficient than the other
> parsers. I'd guess there is some inefficiency
> due it using the old ObjectModelFactory
> instead of annotations? e.g. maybe it
> is reconstructing the schema binding on
> every request or parsing the schema?
> 
> KERNEL
> 
> The kernel reports show more details
> of the stages for beans/jmx and more
> of a summary for the deployers (i.e.
> it shows the deployment stages rather
> than individual deployers).
> 
> A quick guide to the states:
> 
> Real = Real deployers
> PostClassLoader = annotation scanning
> Start = bean/jmx.start()
> Described = bean/jmx metadata analysis
> Instantiated = object construction
> Parse = Parsing deployers
> ClassLoader = ClassLoading deployers
> Create = bean/jmx.create()
> etc.
> 
> REAL
> 
> The biggest hit is the Real stage.
> 
> But there will be some double
> counting here. e.g. the real stage
> of a bean/jmx will also show up in
> Instantiated/Create/Start/etc.
> 
> Also, the times will include dependencies.
> e.g. the starting of the transaction
> manager will start a lot of other services.
> 
> Creating some of the deployers is showing
> more time than I would expect?
> 
> jboss-jca is obviously slow since it is the
> only one using JAXB instead of JBossXB,
> so it has to load all those classes,
> but why does aop, ejb3, web take more than
> one second to just create the deployers?
> 
> POSTCLASSLOADER
> 
> This is the annotation scanning again
> 
> START
> 
> This is obviously where a lot of
> services do things, but again the
> WARDeployer is showing as quite high up?
> 
> DESCRIBED
> 
> There is nothing in here that is
> very big, but it does include
> the aop annotation scanning for beans,
> so there are lots of small bits
> that add up.
> 
> TODO
> 
> I'll let you look at the numbers
> yourselves, in particular the parts
> you are responsible for and see
> whether you can explain it,
> you're happy with it or there
> is something strange going on.
> 
-- 
xxxxxxxxxxxxxxxxxxxxxxxxxxxx
Adrian Brock
Chief Scientist
JBoss, a division of Red Hat
xxxxxxxxxxxxxxxxxxxxxxxxxxxx