Instrumented profiling for multimodule Jigsaw startup

[Aleksey Shipilev]

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.