Le 2 sept. 2008 à 23:15, Charles Oliver N. a écrit :
Since fib performance doesn’t seem to be the source of the problem,
perhaps you could -Xprof during the Rails commands.
1 - Test with JRuby and Xprof: jruby -J-Xprof -S rails -d mysql blog
create
…
Flat profile of 32.62 secs (2132 total ticks): main
Interpreted + native Method
13.0% 274 + 0 org.jruby.parser.DefaultRubyParser.yyparse
1.8% 0 + 37 java.io.FileInputStream.close0
0.9% 0 + 19 java.io.FileOutputStream.writeBytes
0.8% 0 + 17 sun.nio.ch.FileDispatcher.preClose0
0.7% 0 + 14 java.io.FileInputStream.readBytes
0.5% 7 + 3 java.lang.ClassLoader.defineClass1
0.5% 0 + 10 com.sun.jna.Function.invokeInt
0.5% 10 + 0 org.jruby.Ruby.initCore
0.4% 0 + 9 java.io.UnixFileSystem.getBooleanAttributes0
0.3% 0 + 6 java.lang.System.arraycopy
0.3% 0 + 6 java.lang.Class.forName0
0.2% 1 + 4 java.lang.Class.getDeclaredConstructors0
0.2% 5 + 0 org.jruby.javasupport.Java.createJavaModule
0.2% 4 + 0 org.jruby.RubySymbol$SymbolTable.getSymbol
0.1% 3 + 0 org.jruby.ast.CallNoArgBlockNode.interpret
0.1% 3 + 0 org.jruby.RubyString.makeShared
0.1% 3 + 0 org.jruby.runtime.ThreadContext.buildTrace
0.1% 3 + 0 org.jruby.gen.org$jruby$RubyLocalJumpError
$Populator.populate
0.1% 0 + 3 java.io.UnixFileSystem.createFileExclusively
0.1% 3 + 0 org.jruby.RubyModule.variableTableStore
0.1% 3 + 0
org.jruby.compiler.impl.StandardASMCompiler.startScript
0.1% 3 + 0 org.jruby.gen.org$jruby$javasupport
$JavaClass$Populator.populate
0.1% 3 + 0 org.joda.time.chrono.BasicChronology.
0.1% 3 + 0 java.util.concurrent.ConcurrentHashMap
$HashIterator.
0.1% 3 + 0
org.jruby.runtime.scope.ManyVarsDynamicScope.growIfNeeded
54.8% 996 + 162 Total interpreted (including elided)
Compiled + native Method
1.7% 36 + 0
org.jruby.lexer.yacc.InputStreamLexerSource.read
0.9% 20 + 0 org.jruby.lexer.yacc.RubyYaccLexer.identifier
0.8% 17 + 0 java.util.concurrent.ConcurrentHashMap.get
0.6% 12 + 1 org.jruby.lexer.yacc.RubyYaccLexer.yylex
0.6% 12 + 0 java.lang.ThreadLocal.get
0.5% 11 + 0 java.io.UnixFileSystem.normalize
0.5% 10 + 0 java.nio.Buffer.
0.4% 9 + 0 java.util.ArrayList.add
0.4% 9 + 0 java.lang.AbstractStringBuilder.append
0.3% 4 + 2 java.util.concurrent.ConcurrentHashMap
$Segment.get
0.3% 6 + 0
org.jruby.runtime.ThreadContext.preMethodFrameAndScope
0.3% 6 + 0 java.util.ArrayList.get
0.3% 6 + 0 org.jruby.parser.DefaultRubyParser.getPosition
0.2% 5 + 0
org.jruby.runtime.ThreadContext.preYieldSpecificBlock
0.2% 5 + 0 org.jruby.RubyModule.constantTableFastFetch
0.2% 5 + 0 org.joni.StackMachine.push
0.2% 5 + 0
org.jruby.runtime.scope.OneVarDynamicScope.getValue
0.2% 4 + 0 org.jruby.RubyArray.modify
0.2% 4 + 0 java.util.concurrent.ConcurrentHashMap
$EntryIterator.getValue
0.2% 4 + 0 org.jruby.RubyString.equals
0.2% 4 + 0 sun.nio.cs.ISO_8859_1$Encoder.encodeArrayLoop
0.2% 4 + 0 java.lang.String.lastIndexOf
0.2% 4 + 0
org.jruby.internal.runtime.methods.JavaMethod.preFrameOnly
0.2% 4 + 0 org.jruby.parser.ParserSupport.newArrayNode
0.2% 4 + 0 org.jruby.parser.StaticScope.getConstantInner
18.1% 359 + 23 Total compiled (including elided)
Stub + native Method
4.5% 0 + 95 java.io.UnixFileSystem.getBooleanAttributes0
1.7% 0 + 35 java.lang.String.intern
0.2% 0 + 5 java.lang.Object.hashCode
0.1% 0 + 3 java.lang.ClassLoader.findLoadedClass0
0.0% 0 + 1 java.lang.Object.clone
0.0% 0 + 1 java.lang.Class.isArray
0.0% 0 + 1 java.util.zip.Inflater.inflateBytes
6.7% 0 + 141 Total stub
Thread-local ticks:
0.9% 19 Blocked (of total)
7.5% 159 Class loader
12.9% 273 Compilation
Flat profile of 0.06 secs (3 total ticks): DestroyJavaVM
Thread-local ticks:
33.3% 1 Blocked (of total)
100.0% 2 Unknown: no last frame
Global summary of 33.29 seconds:
100.0% 2526 Received ticks
12.8% 324 Received GC ticks
12.4% 314 Compilation
0.0% 1 Deoptimization
0.2% 4 Other VM operations
6.3% 159 Class loader
0.1% 2 Unknown code
2 - Test with JRuby, Xprof and reflection: jruby -J-
Djruby.reflection=true -J-Xprof -S rails -d mysql blog
create
…
Flat profile of 38.65 secs (2201 total ticks): main
Interpreted + native Method
14.8% 321 + 0 org.jruby.parser.DefaultRubyParser.yyparse
1.0% 1 + 20 com.sun.jna.Function.invokeInt
0.6% 0 + 14 java.io.FileOutputStream.writeBytes
0.6% 1 + 11 java.lang.Class.getDeclaredConstructors0
0.5% 0 + 11 java.io.UnixFileSystem.getBooleanAttributes0
0.5% 0 + 10 java.lang.Class.forName0
0.5% 0 + 10 java.lang.Throwable.fillInStackTrace
0.4% 8 + 0 org.jruby.Ruby.initCore
0.4% 0 + 8 java.io.FileInputStream.readBytes
0.3% 0 + 7 java.lang.String.intern
0.2% 5 + 0 org.jruby.javasupport.Java.createJavaModule
0.2% 5 + 0 java.lang.String.regionMatches
0.2% 5 + 0 java.lang.ClassLoader.defineClass1
0.2% 4 + 0 org.jruby.ast.MultipleAsgnNode.interpret
0.2% 0 + 4 java.io.UnixFileSystem.createFileExclusively
0.2% 0 + 4 sun.nio.ch.FileDispatcher.write0
0.2% 4 + 0
org.jruby.internal.runtime.methods.DefaultMethod.call
0.2% 4 + 0 org.jruby.RubyArray.alloc
0.2% 1 + 3 com.sun.jna.Memory.malloc
0.2% 4 + 0 org.jruby.Ruby.getGlobalVariables
0.2% 1 + 3 java.lang.ClassLoader.findBootstrapClass
0.2% 0 + 4 sun.nio.ch.FileDispatcher.preClose0
0.1% 3 + 0 java.net.URLClassLoader$1.run
0.1% 3 + 0 org.jruby.parser.ParserSupport.new_call
0.1% 0 + 3 java.util.zip.ZipFile.open
56.0% 1075 + 141 Total interpreted (including elided)
Compiled + native Method
2.0% 44 + 0
org.jruby.lexer.yacc.InputStreamLexerSource.read
1.2% 25 + 0 java.io.UnixFileSystem.normalize
1.1% 24 + 0 java.util.concurrent.ConcurrentHashMap.get
1.0% 20 + 1 org.jruby.lexer.yacc.RubyYaccLexer.yylex
0.9% 20 + 0 org.jruby.lexer.yacc.RubyYaccLexer.identifier
0.4% 9 + 0 org.jruby.util.ByteList.hashCode
0.3% 7 + 0 java.nio.Buffer.
0.3% 7 + 0 java.util.ArrayList.add
0.3% 7 + 0 java.lang.AbstractStringBuilder.append
0.2% 5 + 0
org.jruby.internal.runtime.ThreadService.getCurrentContext
0.2% 5 + 0
org.jruby.lexer.yacc.RubyYaccLexer.identifierToken
0.2% 5 + 0 org.jruby.runtime.CompiledBlockLight.pre
0.2% 5 + 0 java.util.ArrayList.get
0.2% 4 + 0 sun.nio.cs.ISO_8859_1$Encoder.encodeArrayLoop
0.2% 4 + 0
org.jruby.runtime.ThreadContext.preMethodFrameAndScope
0.2% 3 + 1 org.jruby.runtime.CompiledBlock.yield
0.2% 4 + 0
org.jruby.lexer.yacc.InputStreamLexerSource.unread
0.1% 1 + 2 jruby.objectweb.asm.ByteVector.putUTF8
0.1% 3 + 0 org.jruby.RubyString.equals
0.1% 3 + 0 org.jruby.ast.InstVarNode.interpret
0.1% 3 + 0
org.jruby.lexer.yacc.StringTerm.parseStringIntoBuffer
0.1% 3 + 0 jruby.objectweb.asm.ClassWriter.a
0.1% 3 + 0 org.jruby.parser.StaticScope.getConstantInner
0.1% 3 + 0 java.lang.ThreadLocal.get
0.1% 3 + 0 org.jruby.parser.ParserSupport.checkExpression
18.7% 374 + 32 Total compiled (including elided)
Stub + native Method
3.6% 0 + 78 java.io.UnixFileSystem.getBooleanAttributes0
2.0% 0 + 43 java.lang.String.intern
0.2% 0 + 5 sun.reflect.Reflection.getClassAccessFlags
0.1% 0 + 2 java.lang.Object.hashCode
0.0% 0 + 1 java.lang.ClassLoader.findLoadedClass0
0.0% 0 + 1 java.util.zip.Inflater.inflateBytes
0.0% 0 + 1 java.util.zip.ZipFile.getEntry
6.0% 0 + 131 Total stub
Thread-local ticks:
1.4% 30 Blocked (of total)
6.0% 131 Class loader
13.2% 287 Compilation
Flat profile of 0.00 secs (1 total ticks): DestroyJavaVM
Thread-local ticks:
100.0% 1 Blocked (of total)
Global summary of 39.00 seconds:
100.0% 2627 Received ticks
14.7% 385 Received GC ticks
11.2% 294 Compilation
0.2% 4 Other VM operations
5.0% 131 Class loader
4.934000 0.000000 4.934000 ( 4.935814)
$Populator.populate
0.1% 2 + 0 java.security.AccessController.doPrivileged
0.0% 1 + 0 org.jruby.runtime.CallSite
772 + 0 benchmarktestInvokermethod__0$RUBY
2.2% 57 + 0 org.jruby.runtime.CallSite
0.0% 1 + 0 java.io.DataInputStream.readUTF
0.4% 11 Received GC ticks
Interpreted + native Method 0.1%
0.0% 2 + 0 org.jruby.RubyModule.searchMethod
org.joda.time.chrono.BasicChronology.assemble
0.0% 1 + 0 java.util.concurrent.ConcurrentHashMap
11.7% 487 + 0 org.jruby.RubyFixnum$i_method_1_0
$InlineCachingCallSite.call
0.0% 1 + 0 java.lang.AbstractStringBuilder.append
Stub + native Method 18.3%
Global summary of 54.62 seconds:
Michèle Garoche wrote:
4.482000 0.000000 4.482000 ( 4.481732)
9.041000 0.000000 9.041000 ( 9.041358)
MRI (but not several times slower)
To unsubscribe from this list, please visit:
Michèle
http://micmacfr.homeunix.org
To unsubscribe from this list, please visit:
http://xircles.codehaus.org/manage_email
Cheers,
Michèle
http://micmacfr.homeunix.org