Studying Rails startup time

[Charles Oliver Nutter-2]

Now that we've gotten JRuby's own startup time down pretty low, I
thought I'd start examining the startup time of nontrivial real-world
apps. The biggest one of those, obviously, is Rails.

Rails 2.1 with Mongrel (in development mode) starts up in about 12
seconds on my machine, using soylatte Java 6, on OS X 10.5, a Core Duo
2.16GHz processor, and 2GB of memory. C Ruby starts up in about 8
seconds, so we're actually not so far off the mark here.

I added a ParserStats MBean to explore whether parse time might be a
problem. Of course without knowing MRI's parse time, it's hard to know
if this is good or bad, but here's the stats I gathered:

* A total of 5.512MB of source are parsed during Rails startup
* Total parse time spent was around 3.08s
* There were 503 parses due to file loads
* There were 1943 parses due to evals

Given that the total parse time (including AST construction) was only
about 3 seconds, it doesn't seem like parsing is the largest problem for
our startup. Even if parse time was completely eliminated, we'd still be
a full second slower than MRI. If anyone knows how to gather metrics on
MRI parse time, please let me know.

So for the moment I'm going to explore other possible bottlenecks in
JRuby startup that might be slowing down Rails startup. Any information
or help you've gathered would be appreciated.

- Charlie

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Charles Oliver Nutter-2]

Charles Oliver Nutter wrote:

> Now that we've gotten JRuby's own startup time down pretty low, I
> thought I'd start examining the startup time of nontrivial real-world
> apps. The biggest one of those, obviously, is Rails.
>
> Rails 2.1 with Mongrel (in development mode) starts up in about 12
> seconds on my machine, using soylatte Java 6, on OS X 10.5, a Core Duo
> 2.16GHz processor, and 2GB of memory. C Ruby starts up in about 8
> seconds, so we're actually not so far off the mark here.
>
> I added a ParserStats MBean to explore whether parse time might be a
> problem. Of course without knowing MRI's parse time, it's hard to know
> if this is good or bad, but here's the stats I gathered:
>
> * A total of 5.512MB of source are parsed during Rails startup
> * Total parse time spent was around 3.08s
> * There were 503 parses due to file loads
> * There were 1943 parses due to evals

One more metric on parsing...

I pulled out the long benchmark from bench_eval and ran it with --manage
to compare the total time versus the parse time. The two runs of the
eval benchmark were 18.2s and 17.9s for a total of about 36.1s.
According to the ParserStats MBean, total parse time for the whole run
was 32.66s. So I think it's at least safe to say that almost all the
overhead of eval is parsing/ast construction.

- Charlie

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Peter Williams-4]

Just an FYI, it is possible to profile "deployment of a rails app to
V3", using the NetBeans Profiler and the V3 plugin.  99% of what this
measures is Rails startup, as invoked by JRuby.

I actually did this a while back to see whether the results had any
value for end users (doubtful - it just shows JRuby interpreter over and
over).  I'll poke around to see if I still have the saved stats.  It
might have value for your team.  It should be easy enough to recreate.  
It's just a bit time & memory consuming while the profiler instruments
things and you have to manually attach the profiler to V3 since Rails
project has no profiler integration points.

-Peter

Charles Oliver Nutter wrote:

> Charles Oliver Nutter wrote:
>> Now that we've gotten JRuby's own startup time down pretty low, I
>> thought I'd start examining the startup time of nontrivial real-world
>> apps. The biggest one of those, obviously, is Rails.
>>
>> Rails 2.1 with Mongrel (in development mode) starts up in about 12
>> seconds on my machine, using soylatte Java 6, on OS X 10.5, a Core
>> Duo 2.16GHz processor, and 2GB of memory. C Ruby starts up in about 8
>> seconds, so we're actually not so far off the mark here.
>>
>> I added a ParserStats MBean to explore whether parse time might be a
>> problem. Of course without knowing MRI's parse time, it's hard to
>> know if this is good or bad, but here's the stats I gathered:
>>
>> * A total of 5.512MB of source are parsed during Rails startup
>> * Total parse time spent was around 3.08s
>> * There were 503 parses due to file loads
>> * There were 1943 parses due to evals
>
> One more metric on parsing...
>
> I pulled out the long benchmark from bench_eval and ran it with
> --manage to compare the total time versus the parse time. The two runs
> of the eval benchmark were 18.2s and 17.9s for a total of about 36.1s.
> According to the ParserStats MBean, total parse time for the whole run
> was 32.66s. So I think it's at least safe to say that almost all the
> overhead of eval is parsing/ast construction.
>
> - Charlie
>
> ---------------------------------------------------------------------
> To unsubscribe from this list, please visit:
>
>    http://xircles.codehaus.org/manage_email
>
>

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Charles Oliver Nutter-2]

Peter Williams wrote:

> Just an FYI, it is possible to profile "deployment of a rails app to
> V3", using the NetBeans Profiler and the V3 plugin.  99% of what this
> measures is Rails startup, as invoked by JRuby.
>
> I actually did this a while back to see whether the results had any
> value for end users (doubtful - it just shows JRuby interpreter over and
> over).  I'll poke around to see if I still have the saved stats.  It
> might have value for your team.  It should be easy enough to recreate.  
> It's just a bit time & memory consuming while the profiler instruments
> things and you have to manually attach the profiler to V3 since Rails
> project has no profiler integration points.

Yeah, if you want to publish profile snapshots that would be great. It
kinda fits into what we know of JRuby and JVM though:

* JVM takes a while to warm up, so even JRuby code that's fast later is
slow at the beginning
* JRuby interprets at first, so doesn't run at full speed immediately
* Even though interpreter is faster than MRI, that's faster when warmed
up; it's still slower initially
* Every incremental improvement we make to interpreter performance (of
which there have been many in 1.1.3 and 1.1.4) will help startup time

I think there's still a lot of runway left for startup performance, but
there's a glass ceiling imposed by the JVM on how much improvement we
can make. Profiles like yours might help us see specific areas in the
interpreter that are coming up as bottlenecks.

- Charlie

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email