Timing Hacks DO NOT MERGE

Let's submit to see any lingering effects.

Bug: 17310019
Change-Id: I791bceec0b6aa8b80ac4e6c582a10c3f0ec7a906

diff --git a/core/java/android/app/ActivityThread.java b/core/java/android/app/ActivityThread.java
index 38999a8..4f2a3bc 100644 (file)
--- a/core/java/android/app/ActivityThread.java
+++ b/core/java/android/app/ActivityThread.java
@@ -1938,7 +1938,7 @@ public final class ActivityThread {
         if (dumpFullInfo) {
             printRow(pw, HEAP_FULL_COLUMN, "", "Pss", "Pss", "Shared", "Private",
                     "Shared", "Private", "Swapped", "Heap", "Heap", "Heap");
-            printRow(pw, HEAP_FULL_COLUMN, "", "Total", "Clean", "Dirty", "Dirty",
+            printRow(pw, HEAP_FULL_COLUMN, "", "Total", "Clean", "Dirty", "",
                     "Clean", "Clean", "Dirty", "Size", "Alloc", "Free");
             printRow(pw, HEAP_FULL_COLUMN, "", "------", "------", "------", "------",
                     "------", "------", "------", "------", "------", "------");

diff --git a/core/java/com/android/internal/os/Zygote.java b/core/java/com/android/internal/os/Zygote.java
index 54c532a..c5211bb 100644 (file)
--- a/core/java/com/android/internal/os/Zygote.java
+++ b/core/java/com/android/internal/os/Zygote.java
@@ -20,9 +20,12 @@ package com.android.internal.os;
 import dalvik.system.ZygoteHooks;
 import android.system.ErrnoException;
 import android.system.Os;
+import android.os.SystemClock;
+import android.util.Slog;
 
 /** @hide */
 public final class Zygote {
+    private static final String TAG = "Zygote";
     /*
     * Bit values for "debugFlags" argument.  The definitions are duplicated
     * in the native code.
@@ -81,10 +84,14 @@ public final class Zygote {
      */
     public static int forkAndSpecialize(int uid, int gid, int[] gids, int debugFlags,
           int[][] rlimits, int mountExternal, String seInfo, String niceName, int[] fdsToClose) {
+        long startTime = SystemClock.elapsedRealtime();
         VM_HOOKS.preFork();
+        checkTime(startTime, "Zygote.preFork");
         int pid = nativeForkAndSpecialize(
                   uid, gid, gids, debugFlags, rlimits, mountExternal, seInfo, niceName, fdsToClose);
+        checkTime(startTime, "Zygote.nativeForkAndSpecialize");
         VM_HOOKS.postForkCommon();
+        checkTime(startTime, "Zygote.postForkCommon");
         return pid;
     }
 
@@ -92,6 +99,18 @@ public final class Zygote {
           int[][] rlimits, int mountExternal, String seInfo, String niceName, int[] fdsToClose);
 
     /**
+     * Temporary hack: check time since start time and log if over a fixed threshold.
+     *
+     */
+    private static void checkTime(long startTime, String where) {
+        long now = SystemClock.elapsedRealtime();
+        if ((now-startTime) > 1000) {
+            // If we are taking more than a second, log about it.
+            Slog.w(TAG, "Slow operation: " + (now-startTime) + "ms so far, now at " + where);
+        }
+    }
+
+    /**
      * Special method to start the system server process. In addition to the
      * common actions performed in forkAndSpecialize, the pid of the child
      * process is recorded such that the death of the child process will cause
@@ -127,7 +146,9 @@ public final class Zygote {
             int[][] rlimits, long permittedCapabilities, long effectiveCapabilities);
 
     private static void callPostForkChildHooks(int debugFlags) {
+        long startTime = SystemClock.elapsedRealtime();
         VM_HOOKS.postForkChild(debugFlags);
+        checkTime(startTime, "Zygote.callPostForkChildHooks");
     }
 
 

diff --git a/core/java/com/android/internal/os/ZygoteConnection.java b/core/java/com/android/internal/os/ZygoteConnection.java
index 43ebb3d..b4c4da6 100644 (file)
--- a/core/java/com/android/internal/os/ZygoteConnection.java
+++ b/core/java/com/android/internal/os/ZygoteConnection.java
@@ -37,6 +37,8 @@ import java.io.PrintStream;
 import java.nio.charset.StandardCharsets;
 import java.util.ArrayList;
 import libcore.io.IoUtils;
+import android.os.SystemClock;
+import android.util.Slog;
 
 /**
  * A connection that can make spawn requests.
@@ -103,11 +105,23 @@ class ZygoteConnection {
     }
 
     /**
+     * Temporary hack: check time since start time and log if over a fixed threshold.
+     *
+     */
+    private void checkTime(long startTime, String where) {
+        long now = SystemClock.elapsedRealtime();
+        if ((now-startTime) > 1000) {
+            // If we are taking more than a second, log about it.
+            Slog.w(TAG, "Slow operation: " + (now-startTime) + "ms so far, now at " + where);
+        }
+    }
+
+    /**
      * Returns the file descriptor of the associated socket.
      *
      * @return null-ok; file descriptor
      */
-    FileDescriptor getFileDesciptor() {
+    FileDescriptor getFileDescriptor() {
         return mSocket.getFileDescriptor();
     }
 
@@ -131,6 +145,8 @@ class ZygoteConnection {
         Arguments parsedArgs = null;
         FileDescriptor[] descriptors;
 
+        long startTime = SystemClock.elapsedRealtime();
+
         try {
             args = readArgumentList();
             descriptors = mSocket.getAncillaryFileDescriptors();
@@ -140,6 +156,7 @@ class ZygoteConnection {
             return true;
         }
 
+        checkTime(startTime, "zygoteConnection.runOnce: readArgumentList");
         if (args == null) {
             // EOF reached.
             closeSocket();
@@ -171,14 +188,19 @@ class ZygoteConnection {
                         ", effective=0x" + Long.toHexString(parsedArgs.effectiveCapabilities));
             }
 
+
             applyUidSecurityPolicy(parsedArgs, peer, peerSecurityContext);
             applyRlimitSecurityPolicy(parsedArgs, peer, peerSecurityContext);
             applyInvokeWithSecurityPolicy(parsedArgs, peer, peerSecurityContext);
             applyseInfoSecurityPolicy(parsedArgs, peer, peerSecurityContext);
 
+            checkTime(startTime, "zygoteConnection.runOnce: apply security policies");
+
             applyDebuggerSystemProperty(parsedArgs);
             applyInvokeWithSystemProperty(parsedArgs);
 
+            checkTime(startTime, "zygoteConnection.runOnce: apply security policies");
+
             int[][] rlimits = null;
 
             if (parsedArgs.rlimits != null) {
@@ -220,9 +242,11 @@ class ZygoteConnection {
 
             fd = null;
 
+            checkTime(startTime, "zygoteConnection.runOnce: preForkAndSpecialize");
             pid = Zygote.forkAndSpecialize(parsedArgs.uid, parsedArgs.gid, parsedArgs.gids,
                     parsedArgs.debugFlags, rlimits, parsedArgs.mountExternal, parsedArgs.seInfo,
                     parsedArgs.niceName, fdsToClose);
+            checkTime(startTime, "zygoteConnection.runOnce: postForkAndSpecialize");
         } catch (IOException ex) {
             logAndPrintError(newStderr, "Exception creating pipe", ex);
         } catch (ErrnoException ex) {

diff --git a/core/java/com/android/internal/os/ZygoteInit.java b/core/java/com/android/internal/os/ZygoteInit.java
index 051de6e..0aee0e3 100644 (file)
--- a/core/java/com/android/internal/os/ZygoteInit.java
+++ b/core/java/com/android/internal/os/ZygoteInit.java
@@ -770,7 +770,7 @@ public class ZygoteInit {
             } else if (index == 0) {
                 ZygoteConnection newPeer = acceptCommandPeer(abiList);
                 peers.add(newPeer);
-                fds.add(newPeer.getFileDesciptor());
+                fds.add(newPeer.getFileDescriptor());
             } else {
                 boolean done;
                 done = peers.get(index).runOnce();

diff --git a/core/jni/com_android_internal_os_Zygote.cpp b/core/jni/com_android_internal_os_Zygote.cpp
index 1f7acec..3d2d471 100644 (file)
--- a/core/jni/com_android_internal_os_Zygote.cpp
+++ b/core/jni/com_android_internal_os_Zygote.cpp
@@ -43,6 +43,7 @@
 #include <utils/String8.h>
 #include <selinux/android.h>
 #include <processgroup/processgroup.h>
+#include <inttypes.h>
 
 #include "android_runtime/AndroidRuntime.h"
 #include "JNIHelp.h"
@@ -398,6 +399,22 @@ void SetThreadName(const char* thread_name) {
   }
 }
 
+  // Temporary timing check.
+uint64_t MsTime() {
+  timespec now;
+  clock_gettime(CLOCK_MONOTONIC, &now);
+  return static_cast<uint64_t>(now.tv_sec) * UINT64_C(1000) + now.tv_nsec / UINT64_C(1000000);
+}
+
+
+void ckTime(uint64_t start, const char* where) {
+  uint64_t now = MsTime();
+  if ((now-start) > 1000) {
+    // If we are taking more than a second, log about it.
+    ALOGW("Slow operation: %"PRIu64" ms in %s", (uint64_t)(now-start), where);
+  }
+}
+
 // Utility routine to fork zygote and specialize the child process.
 static pid_t ForkAndSpecializeCommon(JNIEnv* env, uid_t uid, gid_t gid, jintArray javaGids,
                                      jint debug_flags, jobjectArray javaRlimits,
@@ -405,7 +422,9 @@ static pid_t ForkAndSpecializeCommon(JNIEnv* env, uid_t uid, gid_t gid, jintArra
                                      jint mount_external,
                                      jstring java_se_info, jstring java_se_name,
                                      bool is_system_server, jintArray fdsToClose) {
+  uint64_t start = MsTime();
   SetSigChldHandler();
+  ckTime(start, "ForkAndSpecializeCommon:SetSigChldHandler");
 
   pid_t pid = fork();
 
@@ -413,9 +432,12 @@ static pid_t ForkAndSpecializeCommon(JNIEnv* env, uid_t uid, gid_t gid, jintArra
     // The child process.
     gMallocLeakZygoteChild = 1;
 
+
     // Clean up any descriptors which must be closed immediately
     DetachDescriptors(env, fdsToClose);
 
+    ckTime(start, "ForkAndSpecializeCommon:Fork and detach");
+
     // Keep capabilities across UID change, unless we're staying root.
     if (uid != 0) {
       EnableKeepCapabilities(env);
@@ -518,7 +540,10 @@ static pid_t ForkAndSpecializeCommon(JNIEnv* env, uid_t uid, gid_t gid, jintArra
 
     UnsetSigChldHandler();
 
+    ckTime(start, "ForkAndSpecializeCommon:child process setup");
+
     env->CallStaticVoidMethod(gZygoteClass, gCallPostForkChildHooks, debug_flags);
+    ckTime(start, "ForkAndSpecializeCommon:PostForkChildHooks returns");
     if (env->ExceptionCheck()) {
       ALOGE("Error calling post fork hooks.");
       RuntimeAbort(env);