Instrumented profiling for multimodule Jigsaw startup

[Aleksey Shipilev]

(Trying again with attachments)

-Aleksey.

On 03/14/2012 10:59 PM, Aleksey Shipilev wrote:
> Ok, here's the first bunch of data from me.
> 
> The setup is:
>   - Intel i5 520M, 8 Gb DDR3, running Ubuntu 11.10 i686
>   - personal Jigsaw build, as of 2012-03-14; this build is also
> instrumented with multiple logging messages all around Java launcher,
> JDK, and Hotspot.
>   - simple Perl script annotates output with timestamps; that is better
> than synchronizing timers between JDK and JVM code; the tracing code
> incurs non-negligible overhead, but one can see *relative* times spent
> in each section.
>   - multimodule library with 500 modules, all in single dependency
> chain; each module references one other module, and invokes the method
> from there, forcing Jigsaw to actually load the modules at runtime
>   - two measurement modes: a) hot startup, when file caches are warmed
> up, and b) cold startup, where drop_caches = 3 was set before the run,
> effectively forcing kernel to drop the read cache
> 
> I had also run this setup for two cases: invoking from the dependency
> root (i.e. forcing loading all the modules) and from the dependency leaf
> (i.e. loading only one user module).
> 
> The results are attached.
> 
> In short, without tracing:
>   23.4 secs to start up in cold mode, loading 500 modules
>    1.7 secs to start up in warm mode, loading 500 modules
>    2.7 secs to start up in cold mode, loading single module
>    0.6 secs to start up in warm mode, loading single module
> 
> Note that last two scenarios are effectively simple "HelloWorld" scenarios.
> 
> Some observations on these results:
>   A. Current Jigsaw build is actually starting up pretty fast. It was
> was somewhat 20s to load 500 modules in *warm* mode in November; now
> it's only 1.5s, which is a nice improvement.
> 
>   B. The major performance hog is reading module configuration. Even in
> warm mode, it takes around 500ms to load local class map. It seems to be
> connected with the size of it. I'm not sure if compressing will help
> here, will explore a bit more.
> 
>   C. After major init phase is over, the overhead of loading the class
> from other module seems to be OK, at least in warm mode; it takes some
> 1ms to load one up. It gets much worse in cold mode, where the cost of
> doing real I/O boosts that time up to 30 ms. (I would think it would be
> better if I have an SSD, but anyway).
> 
> Thanks,
> Aleksey.