Show how long operations took for each UID in dumpsys.

Test: adb shell am instrument -w com.android.providers.contacts.tests
Test: manual
Bug: 36514278
Change-Id: I3ac1a18bc780c32f886ef16c5e429b1f654dae85

3 files changed, 139 insertions, 87 deletions

diff --git a/src/com/android/providers/contacts/AbstractContactsProvider.java b/src/com/android/providers/contacts/AbstractContactsProvider.java
index 1bc59e7e..ebf0a1b9 100644
--- a/src/com/android/providers/contacts/AbstractContactsProvider.java
+++ b/src/com/android/providers/contacts/AbstractContactsProvider.java
@@ -17,7 +17,6 @@
 package com.android.providers.contacts;
 
 import com.android.providers.contacts.ContactsDatabaseHelper.AccountsColumns;
-import com.android.providers.contacts.ContactsDatabaseHelper.ContactsColumns;
 import com.android.providers.contacts.ContactsDatabaseHelper.RawContactsColumns;
 import com.android.providers.contacts.ContactsDatabaseHelper.Tables;
 
@@ -130,6 +129,11 @@ public abstract class AbstractContactsProvider extends ContentProvider
     protected final SparseLongArray mUpdateInBatchStats = new SparseLongArray();
     protected final SparseLongArray mDeleteInBatchStats = new SparseLongArray();
 
+    private final SparseLongArray mOperationDurationMicroStats = new SparseLongArray();
+
+    private final ThreadLocal<Integer> mOperationNest = ThreadLocal.withInitial(() -> 0);
+    private final ThreadLocal<Long> mOperationStartNs = ThreadLocal.withInitial(() -> 0L);
+
     @Override
     public boolean onCreate() {
         Context context = getContext();
@@ -159,6 +163,12 @@ public abstract class AbstractContactsProvider extends ContentProvider
         synchronized (mStatsLock) {
             stats.put(callingUid, stats.get(callingUid) + 1);
             mAllCallingUids.put(callingUid, true);
+
+            final int nest = mOperationNest.get();
+            mOperationNest.set(nest + 1);
+            if (nest == 0) {
+                mOperationStartNs.set(SystemClock.elapsedRealtimeNanos());
+            }
         }
     }
 
@@ -169,6 +179,19 @@ public abstract class AbstractContactsProvider extends ContentProvider
         incrementStats(inBatch ? statsInBatch : statsNonBatch);
     }
 
+    protected void finishOperation() {
+        final int callingUid = Binder.getCallingUid();
+        synchronized (mStatsLock) {
+            final int nest = mOperationNest.get();
+            mOperationNest.set(nest - 1);
+            if (nest == 1) {
+                final long duration = SystemClock.elapsedRealtimeNanos() - mOperationStartNs.get();
+                mOperationDurationMicroStats.put(callingUid,
+                        mOperationDurationMicroStats.get(callingUid) + duration / 1000L);
+            }
+        }
+    }
+
     public ContactsTransaction getCurrentTransaction() {
         return mTransactionHolder.get();
     }
@@ -176,119 +199,139 @@ public abstract class AbstractContactsProvider extends ContentProvider
     @Override
     public Uri insert(Uri uri, ContentValues values) {
         incrementStats(mInsertStats, mInsertInBatchStats);
-        ContactsTransaction transaction = startTransaction(false);
         try {
-            Uri result = insertInTransaction(uri, values);
-            if (result != null) {
-                transaction.markDirty();
+            ContactsTransaction transaction = startTransaction(false);
+            try {
+                Uri result = insertInTransaction(uri, values);
+                if (result != null) {
+                    transaction.markDirty();
+                }
+                transaction.markSuccessful(false);
+                return result;
+            } finally {
+                endTransaction(false);
             }
-            transaction.markSuccessful(false);
-            return result;
         } finally {
-            endTransaction(false);
+            finishOperation();
         }
     }
 
     @Override
     public int delete(Uri uri, String selection, String[] selectionArgs) {
         incrementStats(mDeleteStats, mDeleteInBatchStats);
-        ContactsTransaction transaction = startTransaction(false);
         try {
-            int deleted = deleteInTransaction(uri, selection, selectionArgs);
-            if (deleted > 0) {
-                transaction.markDirty();
+            ContactsTransaction transaction = startTransaction(false);
+            try {
+                int deleted = deleteInTransaction(uri, selection, selectionArgs);
+                if (deleted > 0) {
+                    transaction.markDirty();
+                }
+                transaction.markSuccessful(false);
+                return deleted;
+            } finally {
+                endTransaction(false);
             }
-            transaction.markSuccessful(false);
-            return deleted;
         } finally {
-            endTransaction(false);
+            finishOperation();
         }
     }
 
     @Override
     public int update(Uri uri, ContentValues values, String selection, String[] selectionArgs) {
         incrementStats(mUpdateStats, mUpdateInBatchStats);
-        ContactsTransaction transaction = startTransaction(false);
         try {
-            int updated = updateInTransaction(uri, values, selection, selectionArgs);
-            if (updated > 0) {
-                transaction.markDirty();
+            ContactsTransaction transaction = startTransaction(false);
+            try {
+                int updated = updateInTransaction(uri, values, selection, selectionArgs);
+                if (updated > 0) {
+                    transaction.markDirty();
+                }
+                transaction.markSuccessful(false);
+                return updated;
+            } finally {
+                endTransaction(false);
             }
-            transaction.markSuccessful(false);
-            return updated;
         } finally {
-            endTransaction(false);
+            finishOperation();
         }
     }
 
     @Override
     public int bulkInsert(Uri uri, ContentValues[] values) {
         incrementStats(mBatchStats);
-        ContactsTransaction transaction = startTransaction(true);
-        int numValues = values.length;
-        int opCount = 0;
         try {
-            for (int i = 0; i < numValues; i++) {
-                insert(uri, values[i]);
-                if (++opCount >= BULK_INSERTS_PER_YIELD_POINT) {
-                    opCount = 0;
-                    try {
-                        yield(transaction);
-                    } catch (RuntimeException re) {
-                        transaction.markYieldFailed();
-                        throw re;
+            ContactsTransaction transaction = startTransaction(true);
+            int numValues = values.length;
+            int opCount = 0;
+            try {
+                for (int i = 0; i < numValues; i++) {
+                    insert(uri, values[i]);
+                    if (++opCount >= BULK_INSERTS_PER_YIELD_POINT) {
+                        opCount = 0;
+                        try {
+                            yield(transaction);
+                        } catch (RuntimeException re) {
+                            transaction.markYieldFailed();
+                            throw re;
+                        }
                     }
                 }
+                transaction.markSuccessful(true);
+            } finally {
+                endTransaction(true);
             }
-            transaction.markSuccessful(true);
+            return numValues;
         } finally {
-            endTransaction(true);
+            finishOperation();
         }
-        return numValues;
     }
 
     @Override
     public ContentProviderResult[] applyBatch(ArrayList<ContentProviderOperation> operations)
             throws OperationApplicationException {
         incrementStats(mBatchStats);
-        if (VERBOSE_LOGGING) {
-            Log.v(TAG, "applyBatch: " + operations.size() + " ops");
-        }
-        int ypCount = 0;
-        int opCount = 0;
-        ContactsTransaction transaction = startTransaction(true);
         try {
-            final int numOperations = operations.size();
-            final ContentProviderResult[] results = new ContentProviderResult[numOperations];
-            for (int i = 0; i < numOperations; i++) {
-                if (++opCount >= MAX_OPERATIONS_PER_YIELD_POINT) {
-                    throw new OperationApplicationException(
-                            "Too many content provider operations between yield points. "
-                                    + "The maximum number of operations per yield point is "
-                                    + MAX_OPERATIONS_PER_YIELD_POINT, ypCount);
-                }
-                final ContentProviderOperation operation = operations.get(i);
-                if (i > 0 && operation.isYieldAllowed()) {
-                    if (VERBOSE_LOGGING) {
-                        Log.v(TAG, "applyBatch: " + opCount + " ops finished; about to yield...");
+            if (VERBOSE_LOGGING) {
+                Log.v(TAG, "applyBatch: " + operations.size() + " ops");
+            }
+            int ypCount = 0;
+            int opCount = 0;
+            ContactsTransaction transaction = startTransaction(true);
+            try {
+                final int numOperations = operations.size();
+                final ContentProviderResult[] results = new ContentProviderResult[numOperations];
+                for (int i = 0; i < numOperations; i++) {
+                    if (++opCount >= MAX_OPERATIONS_PER_YIELD_POINT) {
+                        throw new OperationApplicationException(
+                                "Too many content provider operations between yield points. "
+                                        + "The maximum number of operations per yield point is "
+                                        + MAX_OPERATIONS_PER_YIELD_POINT, ypCount);
                     }
-                    opCount = 0;
-                    try {
-                        if (yield(transaction)) {
-                            ypCount++;
+                    final ContentProviderOperation operation = operations.get(i);
+                    if (i > 0 && operation.isYieldAllowed()) {
+                        if (VERBOSE_LOGGING) {
+                            Log.v(TAG, "applyBatch: " + opCount + " ops finished; about to yield...");
+                        }
+                        opCount = 0;
+                        try {
+                            if (yield(transaction)) {
+                                ypCount++;
+                            }
+                        } catch (RuntimeException re) {
+                            transaction.markYieldFailed();
+                            throw re;
                         }
-                    } catch (RuntimeException re) {
-                        transaction.markYieldFailed();
-                        throw re;
                     }
-                }
 
-                results[i] = operation.apply(this, results, i);
+                    results[i] = operation.apply(this, results, i);
+                }
+                transaction.markSuccessful(true);
+                return results;
+            } finally {
+                endTransaction(true);
             }
-            transaction.markSuccessful(true);
-            return results;
         } finally {
-            endTransaction(true);
+            finishOperation();
         }
     }
 
@@ -426,20 +469,22 @@ public abstract class AbstractContactsProvider extends ContentProvider
         synchronized (mStatsLock) {
             pw.println();
             pw.println("  Client activities:");
-            pw.println("    UID        Query  Insert Update Delete   Batch Insert Update Delete:");
+            pw.println("    UID        Query  Insert Update Delete   Batch Insert Update Delete"
+                + "          Sec");
             for (int i = 0; i < mAllCallingUids.size(); i++) {
-                final int pid = mAllCallingUids.keyAt(i);
+                final int uid = mAllCallingUids.keyAt(i);
                 pw.println(String.format(
-                        "    %-9d %6d  %6d %6d %6d  %6d %6d %6d %6d",
-                        pid,
-                        mQueryStats.get(pid),
-                        mInsertStats.get(pid),
-                        mUpdateStats.get(pid),
-                        mDeleteStats.get(pid),
-                        mBatchStats.get(pid),
-                        mInsertInBatchStats.get(pid),
-                        mUpdateInBatchStats.get(pid),
-                        mDeleteInBatchStats.get(pid)
+                        "    %-9d %6d  %6d %6d %6d  %6d %6d %6d %6d %12.3f",
+                        uid,
+                        mQueryStats.get(uid),
+                        mInsertStats.get(uid),
+                        mUpdateStats.get(uid),
+                        mDeleteStats.get(uid),
+                        mBatchStats.get(uid),
+                        mInsertInBatchStats.get(uid),
+                        mUpdateInBatchStats.get(uid),
+                        mDeleteInBatchStats.get(uid),
+                        (mOperationDurationMicroStats.get(uid) / 1000000.0)
                 ));
             }
         }
diff --git a/src/com/android/providers/contacts/ContactsProvider2.java b/src/com/android/providers/contacts/ContactsProvider2.java
index 66580797..72edc086 100644
--- a/src/com/android/providers/contacts/ContactsProvider2.java
+++ b/src/com/android/providers/contacts/ContactsProvider2.java
@@ -5529,12 +5529,15 @@ public class ContactsProvider2 extends AbstractContactsProvider
                     cancellationSignal);
         }
         incrementStats(mQueryStats);
+        try {
+            // Otherwise proceed with a normal query against the contacts DB.
+            switchToContactMode();
 
-        // Otherwise proceed with a normal query against the contacts DB.
-        switchToContactMode();
-
-        return queryDirectoryIfNecessary(uri, projection, selection, selectionArgs, sortOrder,
-                cancellationSignal);
+            return queryDirectoryIfNecessary(uri, projection, selection, selectionArgs, sortOrder,
+                    cancellationSignal);
+        } finally {
+            finishOperation();
+        }
     }
 
     private boolean isCallerFromSameUser() {
diff --git a/src/com/android/providers/contacts/ProfileProvider.java b/src/com/android/providers/contacts/ProfileProvider.java
index 00e7715f..6c84e4b0 100644
--- a/src/com/android/providers/contacts/ProfileProvider.java
+++ b/src/com/android/providers/contacts/ProfileProvider.java
@@ -71,8 +71,12 @@ public class ProfileProvider extends AbstractContactsProvider {
     public Cursor query(Uri uri, String[] projection, String selection, String[] selectionArgs,
             String sortOrder, CancellationSignal cancellationSignal) {
         incrementStats(mQueryStats);
-        return mDelegate.queryLocal(uri, projection, selection, selectionArgs, sortOrder, -1,
-                cancellationSignal);
+        try {
+            return mDelegate.queryLocal(uri, projection, selection, selectionArgs, sortOrder, -1,
+                    cancellationSignal);
+        } finally {
+            finishOperation();
+        }
     }
 
     @Override