Log content provider authority name in traces

It'll help to debug content provider related performance issues.

Bug: 190416935
Test: Manual - Record perfetto trace & verify auth name is logged.
Test: CtsContentTestCases:android.content.cts
Test: FrameworksCoreTests:android.content
Change-Id: Ifaa1c58135e6aa2a46ecbba92a9266e7d29d5421
diff --git a/core/java/android/content/ContentProvider.java b/core/java/android/content/ContentProvider.java
index dc29c5e..a741f96 100644
--- a/core/java/android/content/ContentProvider.java
+++ b/core/java/android/content/ContentProvider.java
@@ -265,7 +265,7 @@
                 // Return an empty cursor for all columns.
                 return new MatrixCursor(cursor.getColumnNames(), 0);
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "query");
+            traceBegin(TRACE_TAG_DATABASE, "query: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -285,7 +285,7 @@
             // getCallingPackage() isn't available in getType(), as the javadoc states.
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "getType");
+            traceBegin(TRACE_TAG_DATABASE, "getType: ", uri.getAuthority());
             try {
                 return mInterface.getType(uri);
             } catch (RemoteException e) {
@@ -323,7 +323,7 @@
                     setCallingAttributionSource(original);
                 }
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "insert");
+            traceBegin(TRACE_TAG_DATABASE, "insert: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -345,7 +345,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return 0;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "bulkInsert");
+            traceBegin(TRACE_TAG_DATABASE, "bulkInsert: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -391,7 +391,7 @@
                     }
                 }
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "applyBatch");
+            traceBegin(TRACE_TAG_DATABASE, "applyBatch: ", authority);
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -423,7 +423,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return 0;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "delete");
+            traceBegin(TRACE_TAG_DATABASE, "delete: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -445,7 +445,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return 0;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "update");
+            traceBegin(TRACE_TAG_DATABASE, "update: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -465,7 +465,7 @@
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
             enforceFilePermission(attributionSource, uri, mode);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "openFile");
+            traceBegin(TRACE_TAG_DATABASE, "openFile: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -486,7 +486,7 @@
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
             enforceFilePermission(attributionSource, uri, mode);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "openAssetFile");
+            traceBegin(TRACE_TAG_DATABASE, "openAssetFile: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -505,7 +505,7 @@
                 String method, @Nullable String arg, @Nullable Bundle extras) {
             validateIncomingAuthority(authority);
             Bundle.setDefusable(extras, true);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "call");
+            traceBegin(TRACE_TAG_DATABASE, "call: ", authority);
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -523,7 +523,7 @@
             // getCallingPackage() isn't available in getType(), as the javadoc states.
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "getStreamTypes");
+            traceBegin(TRACE_TAG_DATABASE, "getStreamTypes: ", uri.getAuthority());
             try {
                 return mInterface.getStreamTypes(uri, mimeTypeFilter);
             } catch (RemoteException e) {
@@ -541,7 +541,7 @@
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
             enforceFilePermission(attributionSource, uri, "r");
-            Trace.traceBegin(TRACE_TAG_DATABASE, "openTypedAssetFile");
+            traceBegin(TRACE_TAG_DATABASE, "openTypedAssetFile: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -569,7 +569,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return null;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "canonicalize");
+            traceBegin(TRACE_TAG_DATABASE, "canonicalize: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -605,7 +605,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return null;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "uncanonicalize");
+            traceBegin(TRACE_TAG_DATABASE, "uncanonicalize: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -641,7 +641,7 @@
                     != PermissionChecker.PERMISSION_GRANTED) {
                 return false;
             }
-            Trace.traceBegin(TRACE_TAG_DATABASE, "refresh");
+            traceBegin(TRACE_TAG_DATABASE, "refresh: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -658,7 +658,7 @@
                 int uid, int modeFlags) {
             uri = validateIncomingUri(uri);
             uri = maybeGetUriWithoutUserId(uri);
-            Trace.traceBegin(TRACE_TAG_DATABASE, "checkUriPermission");
+            traceBegin(TRACE_TAG_DATABASE, "checkUriPermission: ", uri.getAuthority());
             final AttributionSource original = setCallingAttributionSource(
                     attributionSource);
             try {
@@ -2683,4 +2683,10 @@
         }
         return uri;
     }
+
+    private static void traceBegin(long traceTag, String methodName, String subInfo) {
+        if (Trace.isTagEnabled(traceTag)) {
+            Trace.traceBegin(traceTag, methodName + subInfo);
+        }
+    }
 }
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index 6b0e2db..902f1c1 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -5996,13 +5996,23 @@
     public final ContentProviderHolder getContentProvider(
             IApplicationThread caller, String callingPackage, String name, int userId,
             boolean stable) {
-        return mCpHelper.getContentProvider(caller, callingPackage, name, userId, stable);
+        traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "getContentProvider: ", name);
+        try {
+            return mCpHelper.getContentProvider(caller, callingPackage, name, userId, stable);
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     @Override
     public ContentProviderHolder getContentProviderExternal(
             String name, int userId, IBinder token, String tag) {
-        return mCpHelper.getContentProviderExternal(name, userId, token, tag);
+        traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "getContentProviderExternal: ", name);
+        try {
+            return mCpHelper.getContentProviderExternal(name, userId, token, tag);
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     /**
@@ -6017,18 +6027,57 @@
     @Deprecated
     @Override
     public void removeContentProviderExternal(String name, IBinder token) {
-        removeContentProviderExternalAsUser(name, token, UserHandle.getCallingUserId());
+        traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "removeContentProviderExternal: ", name);
+        try {
+            removeContentProviderExternalAsUser(name, token, UserHandle.getCallingUserId());
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     @Override
     public void removeContentProviderExternalAsUser(String name, IBinder token, int userId) {
-        mCpHelper.removeContentProviderExternalAsUser(name, token, userId);
+        traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "removeContentProviderExternalAsUser: ", name);
+        try {
+            mCpHelper.removeContentProviderExternalAsUser(name, token, userId);
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     @Override
     public final void publishContentProviders(IApplicationThread caller,
             List<ContentProviderHolder> providers) {
-        mCpHelper.publishContentProviders(caller, providers);
+        if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
+            final int maxLength = 256;
+            final StringBuilder sb = new StringBuilder(maxLength);
+            sb.append("publishContentProviders: ");
+            if (providers != null) {
+                boolean first = true;
+                for (int i = 0, size = providers.size(); i < size; i++) {
+                    final ContentProviderHolder holder = providers.get(i);
+                    if (holder != null && holder.info != null && holder.info.authority != null) {
+                        final int len = holder.info.authority.length();
+                        if (sb.length() + len > maxLength) {
+                            sb.append("[[TRUNCATED]]");
+                            break;
+                        }
+                        if (!first) {
+                            sb.append(';');
+                        } else {
+                            first = false;
+                        }
+                        sb.append(holder.info.authority);
+                    }
+                }
+            }
+            Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, sb.toString());
+        }
+        try {
+            mCpHelper.publishContentProviders(caller, providers);
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     @Override
@@ -17079,4 +17128,10 @@
             SystemClock.sleep(durationMs);
         }
     }
+
+    static void traceBegin(long traceTag, String methodName, String subInfo) {
+        if (Trace.isTagEnabled(traceTag)) {
+            Trace.traceBegin(traceTag, methodName + subInfo);
+        }
+    }
 }
diff --git a/services/core/java/com/android/server/am/ContentProviderHelper.java b/services/core/java/com/android/server/am/ContentProviderHelper.java
index ab1da80..1611395 100644
--- a/services/core/java/com/android/server/am/ContentProviderHelper.java
+++ b/services/core/java/com/android/server/am/ContentProviderHelper.java
@@ -58,6 +58,7 @@
 import android.os.RemoteCallback;
 import android.os.RemoteException;
 import android.os.SystemClock;
+import android.os.Trace;
 import android.os.UserHandle;
 import android.provider.Settings;
 import android.text.TextUtils;
@@ -707,20 +708,28 @@
         mService.enforceNotIsolatedCaller("removeContentProvider");
         final long ident = Binder.clearCallingIdentity();
         try {
-            synchronized (mService) {
-                ContentProviderConnection conn;
-                try {
-                    conn = (ContentProviderConnection) connection;
-                } catch (ClassCastException e) {
-                    String msg = "removeContentProvider: " + connection
-                            + " not a ContentProviderConnection";
-                    Slog.w(TAG, msg);
-                    throw new IllegalArgumentException(msg);
+            ContentProviderConnection conn;
+            try {
+                conn = (ContentProviderConnection) connection;
+            } catch (ClassCastException e) {
+                String msg = "removeContentProvider: " + connection
+                        + " not a ContentProviderConnection";
+                Slog.w(TAG, msg);
+                throw new IllegalArgumentException(msg);
+            }
+            if (conn == null) {
+                throw new NullPointerException("connection is null");
+            }
+            ActivityManagerService.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
+                    "removeContentProvider: ",
+                    (conn.provider != null && conn.provider.info != null
+                    ? conn.provider.info.authority : ""));
+            try {
+                synchronized (mService) {
+                    decProviderCountLocked(conn, null, null, stable, true, true);
                 }
-                if (conn == null) {
-                    throw new NullPointerException("connection is null");
-                }
-                decProviderCountLocked(conn, null, null, stable, true, true);
+            } finally {
+                Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
             }
         } finally {
             Binder.restoreCallingIdentity(ident);
@@ -781,8 +790,15 @@
             throw new NullPointerException("connection is null");
         }
 
-        conn.adjustCounts(stable, unstable);
-        return !conn.dead;
+        ActivityManagerService.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "refContentProvider: ",
+                (conn.provider != null && conn.provider.info != null
+                ? conn.provider.info.authority : ""));
+        try {
+            conn.adjustCounts(stable, unstable);
+            return !conn.dead;
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     void unstableProviderDied(IBinder connection) {
@@ -798,50 +814,60 @@
             throw new NullPointerException("connection is null");
         }
 
-        // Safely retrieve the content provider associated with the connection.
-        IContentProvider provider;
-        synchronized (mService) {
-            provider = conn.provider.provider;
-        }
+        ActivityManagerService.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
+                "unstableProviderDied: ",
+                (conn.provider != null && conn.provider.info != null
+                ? conn.provider.info.authority : ""));
 
-        if (provider == null) {
-            // Um, yeah, we're way ahead of you.
-            return;
-        }
-
-        // Make sure the caller is being honest with us.
-        if (provider.asBinder().pingBinder()) {
-            // Er, no, still looks good to us.
+        try {
+            // Safely retrieve the content provider associated with the connection.
+            IContentProvider provider;
             synchronized (mService) {
-                Slog.w(TAG, "unstableProviderDied: caller " + Binder.getCallingUid()
-                        + " says " + conn + " died, but we don't agree");
-                return;
+                provider = conn.provider.provider;
             }
-        }
 
-        // Well look at that!  It's dead!
-        synchronized (mService) {
-            if (conn.provider.provider != provider) {
-                // But something changed...  good enough.
+            if (provider == null) {
+                // Um, yeah, we're way ahead of you.
                 return;
             }
 
-            ProcessRecord proc = conn.provider.proc;
-            if (proc == null || proc.getThread() == null) {
-                // Seems like the process is already cleaned up.
-                return;
+            // Make sure the caller is being honest with us.
+            if (provider.asBinder().pingBinder()) {
+                // Er, no, still looks good to us.
+                synchronized (mService) {
+                    Slog.w(TAG, "unstableProviderDied: caller " + Binder.getCallingUid()
+                            + " says " + conn + " died, but we don't agree");
+                    return;
+                }
             }
 
-            // As far as we're concerned, this is just like receiving a
-            // death notification...  just a bit prematurely.
-            mService.reportUidInfoMessageLocked(TAG, "Process " + proc.processName
-                            + " (pid " + proc.getPid() + ") early provider death", proc.info.uid);
-            final long token = Binder.clearCallingIdentity();
-            try {
-                mService.appDiedLocked(proc, "unstable content provider");
-            } finally {
-                Binder.restoreCallingIdentity(token);
+            // Well look at that!  It's dead!
+            synchronized (mService) {
+                if (conn.provider.provider != provider) {
+                    // But something changed...  good enough.
+                    return;
+                }
+
+                ProcessRecord proc = conn.provider.proc;
+                if (proc == null || proc.getThread() == null) {
+                    // Seems like the process is already cleaned up.
+                    return;
+                }
+
+                // As far as we're concerned, this is just like receiving a
+                // death notification...  just a bit prematurely.
+                mService.reportUidInfoMessageLocked(TAG, "Process " + proc.processName
+                                + " (pid " + proc.getPid() + ") early provider death",
+                                proc.info.uid);
+                final long token = Binder.clearCallingIdentity();
+                try {
+                    mService.appDiedLocked(proc, "unstable content provider");
+                } finally {
+                    Binder.restoreCallingIdentity(token);
+                }
             }
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
         }
     }
 
@@ -855,13 +881,21 @@
             return;
         }
 
-        final ProcessRecord host = conn.provider.proc;
-        if (host == null) {
-            Slog.w(TAG, "Failed to find hosting ProcessRecord");
-            return;
-        }
+        ActivityManagerService.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
+                "appNotRespondingViaProvider: ",
+                (conn.provider != null && conn.provider.info != null
+                ? conn.provider.info.authority : ""));
+        try {
+            final ProcessRecord host = conn.provider.proc;
+            if (host == null) {
+                Slog.w(TAG, "Failed to find hosting ProcessRecord");
+                return;
+            }
 
-        mService.mAnrHelper.appNotResponding(host, "ContentProvider not responding");
+            mService.mAnrHelper.appNotResponding(host, "ContentProvider not responding");
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+        }
     }
 
     /**