Timing hacks DO NOT MERGE

Let's submit to see if any issues remain

Bug: 17310019
Change-Id: Ifef1b1645033adcf192d6ec9248456cae28cd09f

2 files changed, 44 insertions, 0 deletions

diff --git a/dalvik/src/main/java/dalvik/system/ZygoteHooks.java b/dalvik/src/main/java/dalvik/system/ZygoteHooks.java
index fa4f392..1f8f28a 100644
--- a/dalvik/src/main/java/dalvik/system/ZygoteHooks.java
+++ b/dalvik/src/main/java/dalvik/system/ZygoteHooks.java
@@ -28,6 +28,19 @@ public final class ZygoteHooks {
     private long token;
 
     /**
+     * Temporary hack: check time since start time and log if over a fixed threshold.
+     *
+     */
+    private static void checkTime(long startTime, String where) {
+        long now = System.nanoTime();
+        long msDuration = (now - startTime) / (1000 * 1000);
+        if (msDuration > 1000) {
+            // If we are taking more than a second, log about it.
+            System.logW("Slow operation: " + msDuration + "ms so far, now at " + where);
+        }
+    }
+
+    /**
      * Called by the zygote prior to every fork. Each call to {@code preFork}
      * is followed by a matching call to {@link #postForkChild(int)} on the child
      * process and {@link #postForkCommon()} on both the parent and the child
@@ -35,9 +48,13 @@ public final class ZygoteHooks {
      * the child process.
      */
     public void preFork() {
+        long startTime = System.nanoTime();
         Daemons.stop();
+        checkTime(startTime, "ZygoteHooks.Daemons.stop");
         waitUntilAllThreadsStopped();
+        checkTime(startTime, "ZygoteHooks.waituntilallthreadsstopped");
         token = nativePreFork();
+        checkTime(startTime, "ZygoteHooks.Daemons.nativePreFork");
     }
 
     /**
diff --git a/libart/src/main/java/java/lang/Daemons.java b/libart/src/main/java/java/lang/Daemons.java
index 1422c13..6f94f7f 100644
--- a/libart/src/main/java/java/lang/Daemons.java
+++ b/libart/src/main/java/java/lang/Daemons.java
@@ -35,20 +35,47 @@ public final class Daemons {
     private static final int NANOS_PER_SECOND = NANOS_PER_MILLI * 1000;
     private static final long MAX_FINALIZE_NANOS = 10L * NANOS_PER_SECOND;
 
+    /**
+     * Temporary hack: check time since start time and log if over a fixed threshold.
+     *
+     * @return void
+     */
+    private static void checkTime(long startTime, String where) {
+        long now = System.nanoTime();
+        long msDuration = (now - startTime) / (1000 * 1000);
+        if (msDuration > 1000) {
+            // If we are taking more than a second, log about it.
+            System.logW("Slow operation: " + msDuration + "ms so far, now at " + where);
+        }
+    }
+
+
     public static void start() {
+        long startTime = System.nanoTime();
         ReferenceQueueDaemon.INSTANCE.start();
+        checkTime(startTime, "Daemons.ReferenceQueueDaemonStart");
         FinalizerDaemon.INSTANCE.start();
+        checkTime(startTime, "Daemons.FinalizerQueueDaemonStart");
         FinalizerWatchdogDaemon.INSTANCE.start();
+        checkTime(startTime, "Daemons.FinalizerWatchdogQueueDaemonStart");
         HeapTrimmerDaemon.INSTANCE.start();
+        checkTime(startTime, "Daemons.HeapTrimmerDaemonStart");
         GCDaemon.INSTANCE.start();
+        checkTime(startTime, "Daemons.GCDaemonStart");
     }
 
     public static void stop() {
+        long startTime = System.nanoTime();
         ReferenceQueueDaemon.INSTANCE.stop();
+        checkTime(startTime, "Daemons.ReferenceQueueDaemonStop");
         FinalizerDaemon.INSTANCE.stop();
+        checkTime(startTime, "Daemons.FinalizerDaemonStop");
         FinalizerWatchdogDaemon.INSTANCE.stop();
+        checkTime(startTime, "Daemons.FinalizerWatchdogDaemonStop");
         HeapTrimmerDaemon.INSTANCE.stop();
+        checkTime(startTime, "Daemons.HeapTrimmerDaemonStop");
         GCDaemon.INSTANCE.stop();
+        checkTime(startTime, "Daemons.GCDaemonStop");
     }
 
     /**