Timing hacks DO NOT MERGE
Let's submit to see if any issues remain
Bug: 17310019
Change-Id: Ifef1b1645033adcf192d6ec9248456cae28cd09f
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 @@
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 @@
* 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 @@
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");
}
/**
