Merge pull request #3296 from jruby/truffle-metrics

[Truffle] Add tools for measuring startup time and memory consumption.
jruby · Sep 1, 2015 · eb79c9b · eb79c9b
2 parents 4425d99 + 527bc08
commit eb79c9b
Showing 11 changed files with 269 additions and 2 deletions.
diff --git a/core/src/main/java/org/jruby/Main.java b/core/src/main/java/org/jruby/Main.java
@@ -45,6 +45,7 @@
 import org.jruby.runtime.ThreadContext;
 import org.jruby.runtime.builtin.IRubyObject;
 import org.jruby.util.SafePropertyAccessor;
+import org.jruby.util.cli.Options;
 import org.jruby.util.cli.OutputStrings;
 import org.jruby.util.log.Logger;
 import org.jruby.util.log.LoggerFactory;
@@ -183,6 +184,8 @@ public static class Status {
      * @param args command-line args, provided by the JVM.
      */
     public static void main(String[] args) {
+        printTruffleTimeMetric("before-main");
+
         doGCJCheck();
 
         Main main;
@@ -217,6 +220,9 @@ public static void main(String[] args) {
 
             System.exit(1);
         }
+
+        printTruffleTimeMetric("after-main");
+        printTruffleMemoryMetric();
     }
 
     public Status run(String[] args) {
@@ -531,6 +537,28 @@ protected static int handleRaiseException(RaiseException rj) {
         }
     }
 
+    public static void printTruffleTimeMetric(String id) {
+        if (Options.TRUFFLE_METRICS_TIME.load()) {
+            final long millis = System.currentTimeMillis();
+            System.err.printf("%s %d.%03d%n", id, millis / 1000, millis % 1000);
+        }
+    }
+
+    private static void printTruffleMemoryMetric() {
+        if (Options.TRUFFLE_METRICS_MEMORY_USED_ON_EXIT.load()) {
+            for (int n = 0; n < 10; n++) {
+                System.gc();
+            }
+
+            try {
+                Thread.sleep(1000);
+            } catch (InterruptedException e) {
+            }
+
+            System.err.printf("allocated %d%n", ManagementFactory.getMemoryMXBean().getHeapMemoryUsage().getUsed());
+        }
+    }
+
     private final RubyInstanceConfig config;
 }
 
diff --git a/core/src/main/java/org/jruby/Ruby.java b/core/src/main/java/org/jruby/Ruby.java
@@ -79,7 +79,6 @@
 import org.jruby.common.RubyWarnings;
 import org.jruby.compiler.JITCompiler;
 import org.jruby.embed.Extension;
-import org.jruby.exceptions.JumpException;
 import org.jruby.exceptions.MainExitException;
 import org.jruby.exceptions.RaiseException;
 import org.jruby.exceptions.Unrescuable;
@@ -549,7 +548,9 @@ public void runFromMain(InputStream inputStream, String filename) {
             return;
         }
 
+        Main.printTruffleTimeMetric("before-parse-initial");
         ParseResult parseResult = parseFromMain(filename, inputStream);
+        Main.printTruffleTimeMetric("after-parse-initial");
 
         // if no DATA, we're done with the stream, shut it down
         if (fetchGlobalConstant("DATA") == null) {
@@ -843,7 +844,9 @@ public IRubyObject runInterpreter(ThreadContext context, Node rootNode, IRubyObj
         if (getInstanceConfig().getCompileMode() == CompileMode.TRUFFLE) {
             assert rootNode instanceof RootNode;
             assert self == getTopSelf();
+            Main.printTruffleTimeMetric("before-run");
             getTruffleContext().execute((RootNode) rootNode);
+            Main.printTruffleTimeMetric("after-run");
             return getNil();
         } else {
             return Interpreter.getInstance().execute(this, rootNode, self);
@@ -891,6 +894,8 @@ public TruffleContextInterface getTruffleContext() {
     }
 
     private TruffleContextInterface loadTruffleContext() {
+        Main.printTruffleTimeMetric("before-load-truffle-context");
+
         final Class<?> clazz;
 
         try {
@@ -910,6 +915,8 @@ private TruffleContextInterface loadTruffleContext() {
 
         truffleContext.initialize();
 
+        Main.printTruffleTimeMetric("after-load-truffle-context");
+
         return truffleContext;
     }
 

diff --git a/core/src/main/java/org/jruby/util/cli/Options.java b/core/src/main/java/org/jruby/util/cli/Options.java
@@ -150,6 +150,9 @@ public class Options {
     public static final Option<Boolean> TRUFFLE_DISPATCH_METHODMISSING_ALWAYS_CLONED = bool(TRUFFLE, "truffle.call.method_missing_always_cloned", true, "Always clone #method_missing call targets.");
     public static final Option<Boolean> TRUFFLE_DISPATCH_METHODMISSING_ALWAYS_INLINED = bool(TRUFFLE, "truffle.call.method_missing_always_inlined", true, "Always inline #method_missing call targets.");
 
+    public static final Option<Boolean> TRUFFLE_METRICS_TIME = bool(TRUFFLE, "truffle.metrics.time", false, "Print the time at various stages of VM operation.");
+    public static final Option<Boolean> TRUFFLE_METRICS_MEMORY_USED_ON_EXIT = bool(TRUFFLE, "truffle.metrics.memory_used_on_exit", false, "Print the size of heap memory in use on exit.");
+
     public static final Option<Boolean> NATIVE_ENABLED = bool(NATIVE, "native.enabled", true, "Enable/disable native code, including POSIX features and C exts.");
     public static final Option<Boolean> NATIVE_VERBOSE = bool(NATIVE, "native.verbose", false, "Enable verbose logging of native extension loading.");
     public static final Option<Boolean> FFI_COMPILE_DUMP = bool(NATIVE, "ffi.compile.dump", false, "Dump bytecode-generated FFI stubs to console.");

diff --git a/test/truffle/memory/minimum-heap.rb b/test/truffle/memory/minimum-heap.rb
@@ -0,0 +1,59 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Calculates the approximate minimum heap sized needed to run hello world.
+# Not run it fast - just run it at all.
+
+# For example:
+# $ ruby test/truffle/memory/minimum-heap.rb bin/jruby "-X+T -e 'puts 14'"
+
+COMMAND = ARGV[0]
+OPTIONS = ARGV[1]
+
+TOLERANCE = 1
+UPPER_FACTOR = 4
+
+def can_run(heap)
+  print "trying #{heap} MB... "
+
+  output = `#{COMMAND} -J-Xmx#{heap}m #{OPTIONS} 2>&1`
+  can_run = !output.include?('OutOfMemoryError')
+
+  if can_run
+    puts "yes"
+  else
+    puts "no"
+  end
+
+  can_run
+end
+
+puts "looking for an upper bound..."
+
+lower = 0
+upper = 1
+
+while !can_run(upper)
+  lower = upper
+  upper *= UPPER_FACTOR
+end
+
+puts "binary search between #{lower} and #{upper} MB..."
+
+while upper - lower > TOLERANCE
+  mid = lower + (upper - lower) / 2
+
+  if can_run(mid)
+    upper = mid
+  else
+    lower = mid
+  end
+end
+
+puts "minimum heap: #{upper} MB"
diff --git a/test/truffle/memory/total-allocation.rb b/test/truffle/memory/total-allocation.rb
@@ -0,0 +1,33 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Calculates the total memory allocated to run a program.
+
+# For example:
+# $ bin/jruby -X+T -Xtruffle.metrics.memory_used_on_exit=true -J-verbose:gc -e 'puts 14' 2>&1 | ruby test/truffle/memory/total-allocation.rb
+
+on_exit = nil
+allocated = 0
+
+ARGF.each do |line|
+  if line =~ /(\d+)K->(\d+)K/
+    before = $1.to_i * 1024
+    after = $2.to_i * 1024
+    collected = before - after
+    allocated += collected
+  elsif line =~ /^allocated (\d+)$/
+    on_exit = $1.to_i
+  else
+    puts line
+  end
+end
+
+allocated += on_exit
+
+puts "#{allocated/1024/1024} MB"
diff --git a/test/truffle/startup/count-classes.rb b/test/truffle/startup/count-classes.rb
@@ -0,0 +1,25 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Counts how many classes are loaded to run a program.
+
+# For example:
+# $ bin/jruby -X+T -J-XX:+TraceClassLoading -e 'puts 14' 2>&1 | ruby test/truffle/startup/count-classes.rb
+
+classes = 0
+
+ARGF.each do |line|
+  if line.start_with? '[Loaded '
+    classes += 1
+  else
+    puts line
+  end
+end
+
+puts "classes-loaded #{classes}"
diff --git a/test/truffle/startup/jruby-timed b/test/truffle/startup/jruby-timed
@@ -0,0 +1,14 @@
+#!/usr/bin/env bash
+
+gnu_date() {
+  if hash gdate 2> /dev/null
+  then
+    gdate "$@"
+  else
+    date "$@"
+  fi
+}
+
+gnu_date +"before-launcher %s.%N"
+bin/jruby "$@"
+gnu_date +"after-launcher %s.%N"
diff --git a/test/truffle/startup/process-times.rb b/test/truffle/startup/process-times.rb
@@ -0,0 +1,49 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Calculates where the time goes for important regions while running a program.
+
+# For example:
+# $ test/truffle/startup/jruby-timed -X+T -Xtruffle.metrics.time=true -e 'puts 14' 2>&1 | ruby test/truffle/startup/process-times.rb
+
+before_times = {}
+after_times = {}
+nesting = 0
+accounted = 0
+
+ARGF.each do |line|
+  if line =~ /([\w-]+) (\d+\.\d+)/
+    id = $1.split('-')
+    relative = id.first
+    region = id.drop(1).join('-')
+    time = $2.to_f
+
+    case relative
+    when 'before'
+      before_times[region] = time
+      nesting += 1
+    when 'after'
+      after_times[region] = time
+      elapsed = time - before_times[region]
+
+      # 3 means ignore launcher, ignore main, then count regions within that
+      if nesting == 3 && !(['launcher', 'main'].include? region)
+        accounted += elapsed
+      end
+
+      puts "#{region} #{elapsed}"
+      nesting -= 1
+    end
+  end
+end
+
+total = after_times['launcher'] - before_times['launcher']
+
+puts "accounted #{accounted}"
+puts "unaccounted #{total - accounted}"
diff --git a/test/truffle/subjects/client.rb b/test/truffle/subjects/client.rb
@@ -0,0 +1,21 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Repeatedly makes the same request, ignoring failures. Useful for server.rb
+# where you may want to know how soon it can handle its first request.
+
+require 'open-uri'
+
+loop do
+  begin
+    open('http://localhost:8000/hello').read
+  rescue
+    next
+  end
+end
diff --git a/test/truffle/subjects/server.rb b/test/truffle/subjects/server.rb
@@ -0,0 +1,24 @@
+#!/usr/bin/env ruby
+# Copyright (c) 2015 Oracle and/or its affiliates. All rights reserved. This
+# code is released under a tri EPL/GPL/LGPL license. You can use it,
+# redistribute it and/or modify it under the terms of the:
+# 
+# Eclipse Public License version 1.0
+# GNU General Public License version 2
+# GNU Lesser General Public License version 2.1
+
+# Serves a single request then shuts down. Useful with client.rb to make that
+# request.
+
+require 'webrick'
+
+server = WEBrick::HTTPServer.new(Port: 8000)
+
+server.mount_proc '/hello' do |req, res|
+  res.status = 200
+  res['Content-Type'] = 'text/plain'
+  res.body = 'Hello, World!'
+  server.shutdown
+end
+
+server.start
diff --git a/truffle/src/main/java/org/jruby/truffle/runtime/core/CoreLibrary.java b/truffle/src/main/java/org/jruby/truffle/runtime/core/CoreLibrary.java
@@ -23,6 +23,7 @@
 import org.jcodings.EncodingDB;
 import org.jcodings.specific.UTF8Encoding;
 import org.jcodings.transcode.EConvFlags;
+import org.jruby.Main;
 import org.jruby.RubyString;
 import org.jruby.ext.ffi.Platform;
 import org.jruby.ext.ffi.Platform.OS_TYPE;
@@ -53,7 +54,6 @@
 import org.jruby.truffle.runtime.layouts.Layouts;
 import org.jruby.truffle.runtime.layouts.ThreadBacktraceLocationLayoutImpl;
 import org.jruby.truffle.runtime.layouts.ext.DigestLayoutImpl;
-import org.jruby.truffle.runtime.loader.SourceLoader;
 import org.jruby.truffle.runtime.methods.InternalMethod;
 import org.jruby.truffle.runtime.rubinius.RubiniusTypes;
 import org.jruby.truffle.runtime.signal.SignalOperations;
@@ -669,12 +669,16 @@ public void initializeAfterMethodsAdded() {
         // Load Ruby core
 
         try {
+            Main.printTruffleTimeMetric("before-load-truffle-core");
+
             state = State.LOADING_RUBY_CORE;
             try {
                 context.load(context.getSourceCache().getSource(CoreLibrary.CORE_LOAD_PATH + "/core.rb"), node, NodeWrapper.IDENTITY);
             } catch (IOException e) {
                 throw new RuntimeException(e);
             }
+
+            Main.printTruffleTimeMetric("after-load-truffle-core");
         } catch (RaiseException e) {
             final Object rubyException = e.getRubyException();
             BacktraceFormatter.createDefaultFormatter(getContext()).printBacktrace((DynamicObject) rubyException, Layouts.EXCEPTION.getBacktrace((DynamicObject) rubyException));