jruby · Feb 9, 2016 · Feb 9, 2016 · Feb 9, 2016 · Feb 9, 2016
diff --git a/core/src/main/java/org/jruby/Ruby.java b/core/src/main/java/org/jruby/Ruby.java
@@ -841,8 +841,11 @@ public IRubyObject runInterpreter(ThreadContext context, Node rootNode, IRubyObj
             assert self == getTopSelf();
             final JRubyTruffleInterface truffleContext = getTruffleContext();
             Main.printTruffleTimeMetric("before-run");
-            truffleContext.execute((RootNode) rootNode);
-            Main.printTruffleTimeMetric("after-run");
+            try {
+              truffleContext.execute((RootNode) rootNode);
+            } finally {
+              Main.printTruffleTimeMetric("after-run");
+            }
             return getNil();
         } else {
             return interpreter.execute(this, rootNode, self);
@@ -890,7 +893,7 @@ public JRubyTruffleInterface getTruffleContext() {
     }
 
     private JRubyTruffleInterface loadTruffle() {
-        Main.printTruffleTimeMetric("before-load-truffle-context");
+        Main.printTruffleTimeMetric("before-load-context");
 
         final Class<?> clazz;
 
@@ -909,7 +912,7 @@ private JRubyTruffleInterface loadTruffle() {
             throw new RuntimeException("Error while calling the constructor of Truffle's RubyContext", e);
         }
 
-        Main.printTruffleTimeMetric("after-load-truffle-context");
+        Main.printTruffleTimeMetric("after-load-context");
 
         return truffleContext;
     }

diff --git a/tool/jt.rb b/tool/jt.rb
@@ -251,6 +251,7 @@ def help
     puts '    benchmarks can be any benchmarks or group of benchmarks supported'
     puts '    by bench9000, eg all, classic, chunky, 3, 5, 10, 15 - default is 5'
     puts 'jt metrics alloc ...                           how much memory is allocated running a program (use -X-T to test normal JRuby)'
+    puts 'jt metrics time ...                            how long does it take to run a command, broken down into different phases'
     puts 'jt install ..../graal/mx/suite.py              install a JRuby distribution into an mx suite'
     puts
     puts 'you can also put build or rebuild in front of any command'
@@ -549,6 +550,8 @@ def metrics(command, *args)
     case command
     when 'alloc'
       metrics_alloc *args
+    when 'time'
+        metrics_time *args
     else
       raise ArgumentError, command
     end
@@ -565,7 +568,7 @@ def metrics_alloc(*args)
       r.close
     end
     puts if STDOUT.tty?
-    puts "#{human_size(samples.inject(:+)/samples.size)}, range #{human_size(samples.max-samples.min)}"
+    puts "#{human_size(samples.inject(:+)/samples.size)}, max #{human_size(samples.max)}"
   end
 
   def memory_allocated(trace)
@@ -584,6 +587,53 @@ def memory_allocated(trace)
     allocated
   end
 
+  def metrics_time(*args)
+    samples = []
+    METRICS_REPS.times do
+      print '.' if STDOUT.tty?
+      r, w = IO.pipe
+      start = Time.now
+      run '-Xtruffle.metrics.time=true', *args, {err: w, out: w}, :no_print_cmd
+      finish = Time.now
+      w.close
+      samples.push get_times(r.read, finish - start)
+      r.close
+    end
+    puts if STDOUT.tty?
+    samples[0].each_key do |region|
+      region_samples = samples.map { |s| s[region] }
+      puts "#{region} #{(region_samples.inject(:+)/samples.size).round(2)} s"
+    end
+  end
+
+  def get_times(trace, total)
+    start_times = {}
+    times = {}
+    depth = 1
+    accounted_for = 0
+    trace.lines do |line|
+      if line =~ /^([a-z\-]+) (\d+\.\d+)$/
+        region = $1
+        time = $2.to_f
+        if region.start_with? 'before-'
+          depth += 1
+          region = (' ' * depth + region['before-'.size..-1])
+          start_times[region] = time
+        elsif region.start_with? 'after-'
+          region = (' ' * depth + region['after-'.size..-1])
+          depth -= 1
+          elapsed = time - start_times[region]
+          times[region] = elapsed
+          accounted_for += elapsed if depth == 2
+        end
+      end
+    end
+    times[' jvm'] = total - times['  main']
+    times['total'] = total
+    times['unaccounted'] = total - accounted_for
+    times
+  end
+
   def human_size(bytes)
     if bytes < 1024
       "#{bytes} B"

diff --git a/truffle/src/main/java/org/jruby/truffle/RubyContext.java b/truffle/src/main/java/org/jruby/truffle/RubyContext.java
@@ -24,7 +24,7 @@
 import jnr.posix.POSIXFactory;
 import org.jcodings.Encoding;
 import org.jcodings.specific.UTF8Encoding;
-import org.jruby.Ruby;
+import org.jruby.*;
 import org.jruby.ext.ffi.Platform;
 import org.jruby.ext.ffi.Platform.OS_TYPE;
 import org.jruby.runtime.Visibility;
@@ -201,7 +201,12 @@ public RubyContext(Ruby runtime, TruffleLanguage.Env env) {
 
         coreLibrary = new CoreLibrary(this);
         rootLexicalScope = new LexicalScope(null, coreLibrary.getObjectClass());
+
+        org.jruby.Main.printTruffleTimeMetric("before-load-nodes");
         coreLibrary.initialize();
+        rubiniusPrimitiveManager = new RubiniusPrimitiveManager();
+        rubiniusPrimitiveManager.addAnnotatedPrimitives();
+        org.jruby.Main.printTruffleTimeMetric("after-load-nodes");
 
         featureLoader = new FeatureLoader(this);
         traceManager = new TraceManager(this);
@@ -210,9 +215,6 @@ public RubyContext(Ruby runtime, TruffleLanguage.Env env) {
         threadManager = new ThreadManager(this);
         threadManager.initialize();
 
-        rubiniusPrimitiveManager = new RubiniusPrimitiveManager();
-        rubiniusPrimitiveManager.addAnnotatedPrimitives();
-
         if (options.INSTRUMENTATION_SERVER_PORT != 0) {
             instrumentationServerManager = new InstrumentationServerManager(this, options.INSTRUMENTATION_SERVER_PORT);
             instrumentationServerManager.start();

diff --git a/truffle/src/main/java/org/jruby/truffle/core/CoreLibrary.java b/truffle/src/main/java/org/jruby/truffle/core/CoreLibrary.java
@@ -582,7 +582,6 @@ private void addCoreMethods() {
         // Bring in core method nodes
         CoreMethodNodeManager coreMethodNodeManager = new CoreMethodNodeManager(context, node.getSingletonClassNode());
 
-        Main.printTruffleTimeMetric("before-load-truffle-nodes");
         coreMethodNodeManager.addCoreMethodNodes(ArrayNodesFactory.getFactories());
         coreMethodNodeManager.addCoreMethodNodes(BasicObjectNodesFactory.getFactories());
         coreMethodNodeManager.addCoreMethodNodes(BindingNodesFactory.getFactories());
@@ -630,7 +629,6 @@ private void addCoreMethods() {
         coreMethodNodeManager.addCoreMethodNodes(PsychParserNodesFactory.getFactories());
         coreMethodNodeManager.addCoreMethodNodes(PsychEmitterNodesFactory.getFactories());
         coreMethodNodeManager.addCoreMethodNodes(AtomicReferenceNodesFactory.getFactories());
-        Main.printTruffleTimeMetric("after-load-truffle-nodes");
 
         coreMethodNodeManager.allMethodInstalled();
 
@@ -760,7 +758,7 @@ public void initializeAfterMethodsAdded() {
         // Load Ruby core
 
         try {
-            Main.printTruffleTimeMetric("before-load-truffle-core");
+            Main.printTruffleTimeMetric("before-load-core");
 
             state = State.LOADING_RUBY_CORE;
             try {
@@ -769,7 +767,7 @@ public void initializeAfterMethodsAdded() {
                 throw new RuntimeException(e);
             }
 
-            Main.printTruffleTimeMetric("after-load-truffle-core");
+            Main.printTruffleTimeMetric("after-load-core");
         } catch (RaiseException e) {
             final Object rubyException = e.getRubyException();
             BacktraceFormatter.createDefaultFormatter(getContext()).printBacktrace(context, (DynamicObject) rubyException, Layouts.EXCEPTION.getBacktrace((DynamicObject) rubyException));

diff --git a/truffle/src/main/java/org/jruby/truffle/core/rubinius/RubiniusPrimitiveManager.java b/truffle/src/main/java/org/jruby/truffle/core/rubinius/RubiniusPrimitiveManager.java
@@ -45,7 +45,6 @@ public RubiniusPrimitiveConstructor getPrimitive(String name) {
     public void addAnnotatedPrimitives() {
         final List<NodeFactory<? extends RubyNode>> nodeFactories = new ArrayList<>();
 
-        Main.printTruffleTimeMetric("before-load-rubinius-nodes");
         nodeFactories.addAll(VMPrimitiveNodesFactory.getFactories());
         nodeFactories.addAll(ObjectPrimitiveNodesFactory.getFactories());
         nodeFactories.addAll(TimePrimitiveNodesFactory.getFactories());
@@ -68,7 +67,6 @@ public void addAnnotatedPrimitives() {
         nodeFactories.addAll(ExceptionPrimitiveNodesFactory.getFactories());
         nodeFactories.addAll(ThreadPrimitiveNodesFactory.getFactories());
         nodeFactories.addAll(WeakRefPrimitiveNodesFactory.getFactories());
-        Main.printTruffleTimeMetric("after-load-rubinius-nodes");
 
         // This comes last as a catch-all
         nodeFactories.addAll(UndefinedPrimitiveNodesFactory.getFactories());