[GR-4438] Startup timing facility added.

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");
         }
     }
 

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);
     }
 
     /**

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;

com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/StartupTiming.java

+/*
+ * 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);
+        }
+
+    }
+}