Someone popped on to IRC and mentioned it takes 25 seconds for 1.1.2 to
start up their Rails console. I tried it myself and got a better result,
10s, but still far slower than Ruby's 2s. Given that a simple "puts 1"
script now starts up within .5s of Ruby for me, what gives with overall
startup performance?
Part of the answer is sure to be JVM warmup time. But I think there's
probably a lot more we can do to improve cold performance. Since it's
not hard for brain, now's probably a good time to take a step back and
look at improving our cold perf time. Gentlemen, start your engines!
(and then promptly stop them!)
To kick things off, here's a fully-timed runhprof run of starting up a
fresh Rails app's console. Notice that the majority of hotspots are in
the interpreter, and these top 30 account for 44% of accumulated time:
CPU TIME (ms) BEGIN (total = 226580928) Wed May 28 01:33:54 2008
rank self accum count trace method
1 2.88% 2.88% 5479 322419
org.jruby.evaluator.ASTInterpreter.evalInternal
2 1.91% 4.79% 748 323074
org.jruby.runtime.load.LoadService.smartLoad
3 1.90% 6.69% 746 323077 org.jruby.RubyKernel.require
4 1.90% 8.59% 746 323075
org.jruby.runtime.load.LoadService.require
5 1.81% 10.41% 474 318369 org.jruby.Ruby.loadFile
6 1.81% 12.22% 471 323073
org.jruby.runtime.load.ExternalScript.load
7 1.80% 14.02% 2440 323086
org.jruby.runtime.CallSite$InlineCachingCallSite.cacheAndCall
8 1.72% 15.74% 2071 318356
org.jruby.evaluator.ASTInterpreter.evalInternal
9 1.71% 17.45% 482 318359
org.jruby.evaluator.ASTInterpreter.rootNode
10 1.71% 19.16% 479 318360
org.jruby.evaluator.ASTInterpreter.evalInternal
11 1.71% 20.87% 475 318361 org.jruby.evaluator.ASTInterpreter.eval
12 1.64% 22.52% 849 323601
org.jruby.evaluator.ASTInterpreter.blockNode
13 1.64% 24.16% 2564 322070
org.jruby.evaluator.ASTInterpreter.evalInternal
14 1.55% 25.71% 11202 322546
org.jruby.evaluator.ASTInterpreter.evalInternal
15 1.53% 27.24% 642 331934
org.jruby.RubyKernelInvoker$require_s_method_1_0.call
16 1.41% 28.65% 2674 328510
org.jruby.evaluator.ASTInterpreter.blockNode
17 1.41% 30.06% 2202 325052
org.jruby.evaluator.ASTInterpreter.callNode
18 1.40% 31.46% 4097 323088
org.jruby.evaluator.ASTInterpreter.fCallNode
19 1.38% 32.84% 2577 323087
org.jruby.runtime.CallSite$InlineCachingCallSite.call
20 1.36% 34.20% 1401 328581 org.jruby.evaluator.ASTInterpreter.eval
21 1.35% 35.56% 472 328584
org.jruby.internal.runtime.methods.DefaultMethod.call
22 1.34% 36.90% 463 328583
org.jruby.internal.runtime.methods.DefaultMethod.interpretedCall
23 1.30% 38.20% 549 330274
org.jruby.evaluator.ASTInterpreter.evalInternal
24 1.05% 39.25% 849 328585
org.jruby.internal.runtime.methods.DefaultMethod.call
25 0.98% 40.23% 568 332399
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneBlock.call
26 0.97% 41.20% 174 330294
org.jruby.evaluator.ASTInterpreter.rescueNode
27 0.95% 42.15% 93 331939
org.jruby.evaluator.ASTInterpreter.fCallNode
28 0.94% 43.09% 87 331938
org.jruby.runtime.CallSite$InlineCachingCallSite.call
29 0.77% 43.87% 14333 326194 org.jruby.evaluator.ASTInterpreter.eval
30 0.77% 44.64% 14333 326193
org.jruby.evaluator.ASTInterpreter.evalInternal
- Charlie
---------------------------------------------------------------------
To unsubscribe from this list, please visit:
http://xircles.codehaus.org/manage_email
