Merge "Add new debug feature to track associations between processes. Also add some debugging for spurious service ANRs." into lmp-mr1-dev

2 files changed, 256 insertions, 16 deletions

diff --git a/services/core/java/com/android/server/am/ActiveServices.java b/services/core/java/com/android/server/am/ActiveServices.java
index f02a815..d199c3f 100755
--- a/services/core/java/com/android/server/am/ActiveServices.java
+++ b/services/core/java/com/android/server/am/ActiveServices.java
@@ -751,6 +751,9 @@ public final class ActiveServices {
                 }
             }
 
+            mAm.startAssociationLocked(callerApp.uid, callerApp.processName,
+                    s.appInfo.uid, s.name, s.processName);
+
             AppBindRecord b = s.retrieveAppBindingLocked(service, callerApp);
             ConnectionRecord c = new ConnectionRecord(b, activity,
                     connection, flags, clientLabel, clientIntent);
@@ -1445,10 +1448,10 @@ public final class ActiveServices {
 
         boolean created = false;
         try {
-            String nameTerm;
-            int lastPeriod = r.shortName.lastIndexOf('.');
-            nameTerm = lastPeriod >= 0 ? r.shortName.substring(lastPeriod) : r.shortName;
             if (LOG_SERVICE_START_STOP) {
+                String nameTerm;
+                int lastPeriod = r.shortName.lastIndexOf('.');
+                nameTerm = lastPeriod >= 0 ? r.shortName.substring(lastPeriod) : r.shortName;
                 EventLogTags.writeAmCreateService(
                         r.userId, System.identityHashCode(r), nameTerm, r.app.uid, r.app.pid);
             }
@@ -1746,6 +1749,8 @@ public final class ActiveServices {
             }
         }
 
+        mAm.stopAssociationLocked(b.client.uid, b.client.processName, s.appInfo.uid, s.name);
+
         if (b.connections.size() == 0) {
             b.intent.apps.remove(b.client);
         }
@@ -2367,7 +2372,8 @@ public final class ActiveServices {
             if (proc.executingServices.size() == 0 || proc.thread == null) {
                 return;
             }
-            long maxTime = SystemClock.uptimeMillis() -
+            final long now = SystemClock.uptimeMillis();
+            final long maxTime =  now -
                     (proc.execServicesFg ? SERVICE_TIMEOUT : SERVICE_BACKGROUND_TIMEOUT);
             ServiceRecord timeout = null;
             long nextTime = 0;
@@ -2383,7 +2389,21 @@ public final class ActiveServices {
             }
             if (timeout != null && mAm.mLruProcesses.contains(proc)) {
                 Slog.w(TAG, "Timeout executing service: " + timeout);
-                anrMessage = "Executing service " + timeout.shortName;
+                StringBuilder sb = new StringBuilder();
+                sb.append("sxecuting service ");
+                sb.append(timeout.shortName);
+                sb.append(" (execStart=");
+                TimeUtils.formatDuration(now-timeout.executingStart, sb);
+                sb.append(", nesting=");
+                sb.append(timeout.executeNesting);
+                sb.append(", fg=");
+                sb.append(proc.execServicesFg);
+                sb.append(", create=");
+                TimeUtils.formatDuration(now-timeout.createTime, sb);
+                sb.append(", proc=");
+                sb.append(timeout.app != null ? timeout.app.toShortString() : "null");
+                sb.append(")");
+                anrMessage = sb.toString();
             } else {
                 Message msg = mAm.mHandler.obtainMessage(
                         ActivityManagerService.SERVICE_TIMEOUT_MSG);
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index ed16d2e..97b4353 100755
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -749,6 +749,38 @@ public final class ActivityManagerService extends ActivityManagerNative
 
     final ActiveServices mServices;
 
+    final static class Association {
+        final int mSourceUid;
+        final String mSourceProcess;
+        final int mTargetUid;
+        final ComponentName mTargetComponent;
+        final String mTargetProcess;
+
+        int mCount;
+        long mTime;
+
+        int mNesting;
+        long mStartTime;
+
+        Association(int sourceUid, String sourceProcess, int targetUid,
+                ComponentName targetComponent, String targetProcess) {
+            mSourceUid = sourceUid;
+            mSourceProcess = sourceProcess;
+            mTargetUid = targetUid;
+            mTargetComponent = targetComponent;
+            mTargetProcess = targetProcess;
+        }
+    }
+
+    /**
+     * When service association tracking is enabled, this is all of the associations we
+     * have seen.  Mapping is target uid -> target component -> source uid -> source process name
+     * -> association data.
+     */
+    final SparseArray<ArrayMap<ComponentName, SparseArray<ArrayMap<String, Association>>>>
+            mAssociations = new SparseArray<>();
+    boolean mTrackingAssociations;
+
     /**
      * Backup/restore process management
      */
@@ -2071,6 +2103,8 @@ public final class ActivityManagerService extends ActivityManagerNative
         GL_ES_VERSION = SystemProperties.getInt("ro.opengles.version",
             ConfigurationInfo.GL_ES_VERSION_UNDEFINED);
 
+        mTrackingAssociations = "1".equals(SystemProperties.get("debug.track-associations"));
+
         mConfiguration.setToDefaults();
         mConfiguration.setLocale(Locale.getDefault());
 
@@ -9082,6 +9116,7 @@ public final class ActivityManagerService extends ActivityManagerNative
             }
             cpr.connections.add(conn);
             r.conProviders.add(conn);
+            startAssociationLocked(r.uid, r.processName, cpr.uid, cpr.name, cpr.info.processName);
             return conn;
         }
         cpr.addExternalProcessHandleLocked(externalProcessToken);
@@ -9105,6 +9140,7 @@ public final class ActivityManagerService extends ActivityManagerNative
             if (conn.stableCount == 0 && conn.unstableCount == 0) {
                 cpr.connections.remove(conn);
                 conn.client.conProviders.remove(conn);
+                stopAssociationLocked(conn.client.uid, conn.client.processName, cpr.uid, cpr.name);
                 return true;
             }
             return false;
@@ -12320,9 +12356,18 @@ public final class ActivityManagerService extends ActivityManagerNative
                 dumpAll = true;
             } else if ("-c".equals(opt)) {
                 dumpClient = true;
+            } else if ("-p".equals(opt)) {
+                if (opti < args.length) {
+                    dumpPackage = args[opti];
+                    opti++;
+                } else {
+                    pw.println("Error: -p option requires package argument");
+                    return;
+                }
+                dumpClient = true;
             } else if ("-h".equals(opt)) {
                 pw.println("Activity manager dump options:");
-                pw.println("  [-a] [-c] [-h] [cmd] ...");
+                pw.println("  [-a] [-c] [-p package] [-h] [cmd] ...");
                 pw.println("  cmd may be one of:");
                 pw.println("    a[ctivities]: activity stack state");
                 pw.println("    r[recents]: recent activities state");
@@ -12333,17 +12378,21 @@ public final class ActivityManagerService extends ActivityManagerNative
                 pw.println("    prov[iders] [COMP_SPEC ...]: content provider state");
                 pw.println("    provider [COMP_SPEC]: provider client-side state");
                 pw.println("    s[ervices] [COMP_SPEC ...]: service state");
+                pw.println("    as[sociations]: tracked app associations");
                 pw.println("    service [COMP_SPEC]: service client-side state");
                 pw.println("    package [PACKAGE_NAME]: all state related to given package");
                 pw.println("    all: dump all activities");
                 pw.println("    top: dump the top activity");
                 pw.println("    write: write all pending state to storage");
+                pw.println("    track-associations: enable association tracking");
+                pw.println("    untrack-associations: disable and clear association tracking");
                 pw.println("  cmd may also be a COMP_SPEC to dump activities.");
                 pw.println("  COMP_SPEC may be a component name (com.foo/.myApp),");
                 pw.println("    a partial substring in a component name, a");
                 pw.println("    hex object identifier.");
                 pw.println("  -a: include all available server state.");
                 pw.println("  -c: include client state.");
+                pw.println("  -p: limit output to given package.");
                 return;
             } else {
                 pw.println("Unknown argument: " + opt + "; use -h for help");
@@ -12358,11 +12407,11 @@ public final class ActivityManagerService extends ActivityManagerNative
             opti++;
             if ("activities".equals(cmd) || "a".equals(cmd)) {
                 synchronized (this) {
-                    dumpActivitiesLocked(fd, pw, args, opti, true, dumpClient, null);
+                    dumpActivitiesLocked(fd, pw, args, opti, true, dumpClient, dumpPackage);
                 }
             } else if ("recents".equals(cmd) || "r".equals(cmd)) {
                 synchronized (this) {
-                    dumpRecentsLocked(fd, pw, args, opti, true, null);
+                    dumpRecentsLocked(fd, pw, args, opti, true, dumpPackage);
                 }
             } else if ("broadcasts".equals(cmd) || "b".equals(cmd)) {
                 String[] newArgs;
@@ -12371,14 +12420,14 @@ public final class ActivityManagerService extends ActivityManagerNative
                     name = null;
                     newArgs = EMPTY_STRING_ARRAY;
                 } else {
-                    name = args[opti];
+                    dumpPackage = args[opti];
                     opti++;
                     newArgs = new String[args.length - opti];
                     if (args.length > 2) System.arraycopy(args, opti, newArgs, 0,
                             args.length - opti);
                 }
                 synchronized (this) {
-                    dumpBroadcastsLocked(fd, pw, args, opti, true, name);
+                    dumpBroadcastsLocked(fd, pw, args, opti, true, dumpPackage);
                 }
             } else if ("intents".equals(cmd) || "i".equals(cmd)) {
                 String[] newArgs;
@@ -12387,14 +12436,14 @@ public final class ActivityManagerService extends ActivityManagerNative
                     name = null;
                     newArgs = EMPTY_STRING_ARRAY;
                 } else {
-                    name = args[opti];
+                    dumpPackage = args[opti];
                     opti++;
                     newArgs = new String[args.length - opti];
                     if (args.length > 2) System.arraycopy(args, opti, newArgs, 0,
                             args.length - opti);
                 }
                 synchronized (this) {
-                    dumpPendingIntentsLocked(fd, pw, args, opti, true, name);
+                    dumpPendingIntentsLocked(fd, pw, args, opti, true, dumpPackage);
                 }
             } else if ("processes".equals(cmd) || "p".equals(cmd)) {
                 String[] newArgs;
@@ -12403,14 +12452,14 @@ public final class ActivityManagerService extends ActivityManagerNative
                     name = null;
                     newArgs = EMPTY_STRING_ARRAY;
                 } else {
-                    name = args[opti];
+                    dumpPackage = args[opti];
                     opti++;
                     newArgs = new String[args.length - opti];
                     if (args.length > 2) System.arraycopy(args, opti, newArgs, 0,
                             args.length - opti);
                 }
                 synchronized (this) {
-                    dumpProcessesLocked(fd, pw, args, opti, true, name);
+                    dumpProcessesLocked(fd, pw, args, opti, true, dumpPackage);
                 }
             } else if ("oom".equals(cmd) || "o".equals(cmd)) {
                 synchronized (this) {
@@ -12468,14 +12517,39 @@ public final class ActivityManagerService extends ActivityManagerNative
                     opti = 0;
                     more = true;
                 }
+            } else if ("associations".equals(cmd) || "as".equals(cmd)) {
+                synchronized (this) {
+                    dumpAssociationsLocked(fd, pw, args, opti, true, dumpClient, dumpPackage);
+                }
             } else if ("services".equals(cmd) || "s".equals(cmd)) {
                 synchronized (this) {
-                    mServices.dumpServicesLocked(fd, pw, args, opti, true, dumpClient, null);
+                    mServices.dumpServicesLocked(fd, pw, args, opti, true, dumpClient, dumpPackage);
                 }
             } else if ("write".equals(cmd)) {
                 mTaskPersister.flush();
                 pw.println("All tasks persisted.");
                 return;
+            } else if ("track-associations".equals(cmd)) {
+                synchronized (this) {
+                    if (!mTrackingAssociations) {
+                        mTrackingAssociations = true;
+                        pw.println("Association tracking started.");
+                    } else {
+                        pw.println("Association tracking already enabled.");
+                    }
+                }
+                return;
+            } else if ("untrack-associations".equals(cmd)) {
+                synchronized (this) {
+                    if (mTrackingAssociations) {
+                        mTrackingAssociations = false;
+                        mAssociations.clear();
+                        pw.println("Association tracking stopped.");
+                    } else {
+                        pw.println("Association tracking not running.");
+                    }
+                }
+                return;
             } else {
                 // Dumping a single activity?
                 if (!dumpActivity(fd, pw, cmd, args, opti, dumpAll)) {
@@ -12517,6 +12591,13 @@ public final class ActivityManagerService extends ActivityManagerNative
                 pw.println("-------------------------------------------------------------------------------");
             }
             dumpActivitiesLocked(fd, pw, args, opti, dumpAll, dumpClient, dumpPackage);
+            if (mAssociations.size() > 0) {
+                pw.println();
+                if (dumpAll) {
+                    pw.println("-------------------------------------------------------------------------------");
+                }
+                dumpAssociationsLocked(fd, pw, args, opti, dumpAll, dumpClient, dumpPackage);
+            }
             pw.println();
             if (dumpAll) {
                 pw.println("-------------------------------------------------------------------------------");
@@ -12591,6 +12672,78 @@ public final class ActivityManagerService extends ActivityManagerNative
         }
     }
 
+    void dumpAssociationsLocked(FileDescriptor fd, PrintWriter pw, String[] args,
+            int opti, boolean dumpAll, boolean dumpClient, String dumpPackage) {
+        pw.println("ACTIVITY MANAGER ASSOCIATIONS (dumpsys activity associations)");
+
+        int dumpUid = 0;
+        if (dumpPackage != null) {
+            IPackageManager pm = AppGlobals.getPackageManager();
+            try {
+                dumpUid = pm.getPackageUid(dumpPackage, 0);
+            } catch (RemoteException e) {
+            }
+        }
+
+        boolean printedAnything = false;
+
+        final long now = SystemClock.uptimeMillis();
+
+        for (int i1=0, N1=mAssociations.size(); i1<N1; i1++) {
+            ArrayMap<ComponentName, SparseArray<ArrayMap<String, Association>>> targetComponents
+                    = mAssociations.valueAt(i1);
+            for (int i2=0, N2=targetComponents.size(); i2<N2; i2++) {
+                SparseArray<ArrayMap<String, Association>> sourceUids
+                        = targetComponents.valueAt(i2);
+                for (int i3=0, N3=sourceUids.size(); i3<N3; i3++) {
+                    ArrayMap<String, Association> sourceProcesses = sourceUids.valueAt(i3);
+                    for (int i4=0, N4=sourceProcesses.size(); i4<N4; i4++) {
+                        Association ass = sourceProcesses.valueAt(i4);
+                        if (dumpPackage != null) {
+                            if (!ass.mTargetComponent.getPackageName().equals(dumpPackage)
+                                    && UserHandle.getAppId(ass.mSourceUid) != dumpUid) {
+                                continue;
+                            }
+                        }
+                        printedAnything = true;
+                        pw.print("  ");
+                        pw.print(ass.mTargetProcess);
+                        pw.print("/");
+                        UserHandle.formatUid(pw, ass.mTargetUid);
+                        pw.print(" <- ");
+                        pw.print(ass.mSourceProcess);
+                        pw.print("/");
+                        UserHandle.formatUid(pw, ass.mSourceUid);
+                        pw.println();
+                        pw.print("    via ");
+                        pw.print(ass.mTargetComponent.flattenToShortString());
+                        pw.println();
+                        pw.print("    ");
+                        long dur = ass.mTime;
+                        if (ass.mNesting > 0) {
+                            dur += now - ass.mStartTime;
+                        }
+                        TimeUtils.formatDuration(dur, pw);
+                        pw.print(" (");
+                        pw.print(ass.mCount);
+                        pw.println(" times)");
+                        if (ass.mNesting > 0) {
+                            pw.print("    ");
+                            pw.print(" Currently active: ");
+                            TimeUtils.formatDuration(now - ass.mStartTime, pw);
+                            pw.println();
+                        }
+                    }
+                }
+            }
+
+        }
+
+        if (!printedAnything) {
+            pw.println("  (nothing)");
+        }
+    }
+
     void dumpProcessesLocked(FileDescriptor fd, PrintWriter pw, String[] args,
             int opti, boolean dumpAll, String dumpPackage) {
         boolean needSep = false;
@@ -14687,7 +14840,9 @@ public final class ActivityManagerService extends ActivityManagerNative
                 // In the protocol here, we don't expect the client to correctly
                 // clean up this connection, we'll just remove it.
                 cpr.connections.remove(i);
-                conn.client.conProviders.remove(conn);
+                if (conn.client.conProviders.remove(conn)) {
+                    stopAssociationLocked(capp.uid, capp.processName, cpr.uid, cpr.name);
+                }
             }
         }
 
@@ -14773,6 +14928,8 @@ public final class ActivityManagerService extends ActivityManagerNative
             for (int i=0; i<app.conProviders.size(); i++) {
                 ContentProviderConnection conn = app.conProviders.get(i);
                 conn.provider.connections.remove(conn);
+                stopAssociationLocked(app.uid, app.processName, conn.provider.uid,
+                        conn.provider.name);
             }
             app.conProviders.clear();
         }
@@ -16715,6 +16872,69 @@ public final class ActivityManagerService extends ActivityManagerNative
         return null;
     }
 
+    Association startAssociationLocked(int sourceUid, String sourceProcess, int targetUid,
+            ComponentName targetComponent, String targetProcess) {
+        if (!mTrackingAssociations) {
+            return null;
+        }
+        ArrayMap<ComponentName, SparseArray<ArrayMap<String, Association>>> components
+                = mAssociations.get(targetUid);
+        if (components == null) {
+            components = new ArrayMap<>();
+            mAssociations.put(targetUid, components);
+        }
+        SparseArray<ArrayMap<String, Association>> sourceUids = components.get(targetComponent);
+        if (sourceUids == null) {
+            sourceUids = new SparseArray<>();
+            components.put(targetComponent, sourceUids);
+        }
+        ArrayMap<String, Association> sourceProcesses = sourceUids.get(sourceUid);
+        if (sourceProcesses == null) {
+            sourceProcesses = new ArrayMap<>();
+            sourceUids.put(sourceUid, sourceProcesses);
+        }
+        Association ass = sourceProcesses.get(sourceProcess);
+        if (ass == null) {
+            ass = new Association(sourceUid, sourceProcess, targetUid, targetComponent,
+                    targetProcess);
+            sourceProcesses.put(sourceProcess, ass);
+        }
+        ass.mCount++;
+        ass.mNesting++;
+        if (ass.mNesting == 1) {
+            ass.mStartTime = SystemClock.uptimeMillis();
+        }
+        return ass;
+    }
+
+    void stopAssociationLocked(int sourceUid, String sourceProcess, int targetUid,
+            ComponentName targetComponent) {
+        if (!mTrackingAssociations) {
+            return;
+        }
+        ArrayMap<ComponentName, SparseArray<ArrayMap<String, Association>>> components
+                = mAssociations.get(targetUid);
+        if (components == null) {
+            return;
+        }
+        SparseArray<ArrayMap<String, Association>> sourceUids = components.get(targetComponent);
+        if (sourceUids == null) {
+            return;
+        }
+        ArrayMap<String, Association> sourceProcesses = sourceUids.get(sourceUid);
+        if (sourceProcesses == null) {
+            return;
+        }
+        Association ass = sourceProcesses.get(sourceProcess);
+        if (ass == null || ass.mNesting <= 0) {
+            return;
+        }
+        ass.mNesting--;
+        if (ass.mNesting == 0) {
+            ass.mTime += SystemClock.uptimeMillis() - ass.mStartTime;
+        }
+    }
+
     private final int computeOomAdjLocked(ProcessRecord app, int cachedAdj, ProcessRecord TOP_APP,
             boolean doingAll, long now) {
         if (mAdjSeq == app.adjSeq) {