diff --git a/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/REngine.java b/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/REngine.java
index eaa5cfbb487b3a1e1c357e329afb3189b833253d..e549c05fa0e08f18113343d31eeb982aa6407660 100644
--- a/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/REngine.java
+++ b/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/REngine.java
@@ -81,6 +81,7 @@ import com.oracle.truffle.r.runtime.RSource;
import com.oracle.truffle.r.runtime.RStartParams.SA_TYPE;
import com.oracle.truffle.r.runtime.ReturnException;
import com.oracle.truffle.r.runtime.RootWithBody;
+import com.oracle.truffle.r.runtime.StartupTiming;
import com.oracle.truffle.r.runtime.SubstituteVirtualFrame;
import com.oracle.truffle.r.runtime.ThreadTimings;
import com.oracle.truffle.r.runtime.Utils;
@@ -162,6 +163,7 @@ final class REngine implements Engine, Engine.Timings {
RBuiltinPackages.loadBase(baseFrame);
RGraphics.initialize();
if (FastROptions.LoadProfiles.getBooleanValue()) {
+ StartupTiming.timestamp("Before Profiles Loaded");
/*
* eval the system/site/user profiles. Experimentally GnuR does not report warnings
* during system profile evaluation, but does for the site/user profiles.
@@ -197,6 +199,8 @@ final class REngine implements Engine, Engine.Timings {
}
checkAndRunStartupShutdownFunction(".First");
checkAndRunStartupShutdownFunction(".First.sys");
+
+ StartupTiming.timestamp("After Profiles Loaded");
}
}
diff --git a/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/shell/RCommand.java b/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/shell/RCommand.java
index b48d4d484ac9d48719bceb299b3178ab290caaee..45a37ce645397b21b1f3cc9feaa8a5e72eec9db3 100644
--- a/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/shell/RCommand.java
+++ b/com.oracle.truffle.r.engine/src/com/oracle/truffle/r/engine/shell/RCommand.java
@@ -41,6 +41,7 @@ import com.oracle.truffle.api.vm.PolyglotEngine;
import com.oracle.truffle.api.vm.PolyglotEngine.Value;
import com.oracle.truffle.r.nodes.builtin.base.Quit;
import com.oracle.truffle.r.runtime.ExitException;
+import com.oracle.truffle.r.runtime.FastROptions;
import com.oracle.truffle.r.runtime.JumpToTopLevelException;
import com.oracle.truffle.r.runtime.RCmdOptions;
import com.oracle.truffle.r.runtime.RError;
@@ -48,6 +49,7 @@ import com.oracle.truffle.r.runtime.RInternalError;
import com.oracle.truffle.r.runtime.RRuntime;
import com.oracle.truffle.r.runtime.RSource;
import com.oracle.truffle.r.runtime.RStartParams;
+import com.oracle.truffle.r.runtime.StartupTiming;
import com.oracle.truffle.r.runtime.RStartParams.SA_TYPE;
import com.oracle.truffle.r.runtime.Utils;
import com.oracle.truffle.r.runtime.Utils.DebugExitException;
@@ -78,10 +80,15 @@ public class RCommand {
}
public static int doMain(String[] args, String[] env, boolean initial, InputStream inStream, OutputStream outStream) {
+ FastROptions.initialize();
+ StartupTiming.timestamp("Main Entered");
RCmdOptions options = RCmdOptions.parseArguments(RCmdOptions.Client.R, args, false);
options.printHelpAndVersion();
ContextInfo info = createContextInfoFromCommandLine(options, false, initial, inStream, outStream, env);
- return readEvalPrint(info.createVM(), info);
+ PolyglotEngine vm = info.createVM();
+ StartupTiming.timestamp("VM Created");
+ StartupTiming.printSummary();
+ return readEvalPrint(vm, info);
}
/**
diff --git a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/FastROptions.java b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/FastROptions.java
index ad7e272e9177f545a3da27dbd88495501d6d1751..10c6e80e1307c2ad7544c8483aa055d4d290bc1a 100644
--- a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/FastROptions.java
+++ b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/FastROptions.java
@@ -67,7 +67,11 @@ public enum FastROptions {
EagerEvalVariables("Enables optimistic eager evaluation of single variables reads", true),
EagerEvalDefault("Enables optimistic eager evaluation of single variables reads (for default parameters)", false),
EagerEvalExpressions("Enables optimistic eager evaluation of trivial expressions", false),
- PromiseCacheSize("Enables inline caches for promises evaluation", "3", true);
+ PromiseCacheSize("Enables inline caches for promises evaluation", "3", true),
+
+ // Miscellaneous
+
+ StartupTiming("Records and prints various timestamps during initialization", false);
private final String help;
private final boolean isBoolean;
diff --git a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/StartupTiming.java b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/StartupTiming.java
new file mode 100644
index 0000000000000000000000000000000000000000..047702f7b6149ccd2cd8bc4d6b6bb1d301e0b142
--- /dev/null
+++ b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/StartupTiming.java
@@ -0,0 +1,110 @@
+/*
+ * Copyright (c) 2017, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+package com.oracle.truffle.r.runtime;
+
+import java.io.PrintStream;
+import java.lang.management.ManagementFactory;
+import java.lang.management.RuntimeMXBean;
+import java.util.TreeSet;
+import java.util.concurrent.ConcurrentLinkedDeque;
+
+public final class StartupTiming {
+
+ private static volatile StartupTiming INSTANCE = null;
+
+ private final long startTime;
+ private final ConcurrentLinkedDeque<Timestamp> timestamps = new ConcurrentLinkedDeque<>();
+
+ private StartupTiming() {
+ RuntimeMXBean runtimeMXBean;
+ long st = 0L;
+ try {
+ runtimeMXBean = ManagementFactory.getRuntimeMXBean();
+ if (runtimeMXBean == null) {
+ st = System.currentTimeMillis();
+ } else {
+ st = runtimeMXBean.getStartTime();
+ }
+ } catch (Throwable t) {
+ st = System.currentTimeMillis();
+ }
+ startTime = st;
+ }
+
+ private static synchronized void init() {
+ if (INSTANCE == null) {
+ INSTANCE = new StartupTiming();
+ }
+ }
+
+ public static void timestamp(String name) {
+ if (FastROptions.StartupTiming.getBooleanValue()) {
+ init();
+ INSTANCE.putTimestamp(name);
+ }
+ }
+
+ public static void printSummary() {
+ if (FastROptions.StartupTiming.getBooleanValue()) {
+ init();
+ INSTANCE.summary(System.out);
+ }
+ }
+
+ private void putTimestamp(String tsName) {
+ timestamps.add(new Timestamp(System.currentTimeMillis(), tsName));
+ }
+
+ private void summary(PrintStream out) {
+ out.println("Startup timing table:");
+ out.println("<Timestamp>\t<FromStart>\t<FromPrev>");
+
+ TreeSet<Timestamp> sorted = new TreeSet<>(timestamps);
+ long prevTs = startTime;
+ for (Timestamp ts : sorted) {
+ long relTs = ts.timestamp - startTime;
+ long delta = ts.timestamp - prevTs;
+ String msg = ts.name;
+
+ out.println(String.format("%s:\t%s ms\t(%s ms)", msg, relTs, delta));
+
+ prevTs = ts.timestamp;
+ }
+ }
+
+ private static final class Timestamp implements Comparable<Timestamp> {
+ private final long timestamp;
+ private final String name;
+
+ Timestamp(long ts, String name) {
+ this.timestamp = ts;
+ this.name = name;
+ }
+
+ @Override
+ public int compareTo(Timestamp other) {
+ return this.timestamp == other.timestamp ? 0 : (this.timestamp < other.timestamp ? -1 : 1);
+ }
+
+ }
+}