Measure walltime in ContentResolver and SQLiteDatabase operations logging.

Previously, SQLiteDatabase was using Debug.threadCpuTimeNanos(), which
doesn't include I/O time (user-perceived latency), and ContentResolver
was using System.currentTimeMillis(), which didn't account for deep
sleeps.

Now both are consistently using SystemClock.uptimeMillis().

2 files changed, 20 insertions, 19 deletions

diff --git a/core/java/android/content/ContentResolver.java b/core/java/android/content/ContentResolver.java
index bdbe341..45f361e 100644
--- a/core/java/android/content/ContentResolver.java
+++ b/core/java/android/content/ContentResolver.java
@@ -31,6 +31,7 @@ import android.os.IBinder;
 import android.os.ParcelFileDescriptor;
 import android.os.RemoteException;
 import android.os.ServiceManager;
+import android.os.SystemClock;
 import android.text.TextUtils;
 import android.util.Config;
 import android.util.EventLog;
@@ -243,13 +244,13 @@ public abstract class ContentResolver {
             return null;
         }
         try {
-            long startTime = System.currentTimeMillis();
+            long startTime = SystemClock.uptimeMillis();
             Cursor qCursor = provider.query(uri, projection, selection, selectionArgs, sortOrder);
             if (qCursor == null) {
                 releaseProvider(provider);
                 return null;
             }
-            long durationMillis = System.currentTimeMillis() - startTime;
+            long durationMillis = SystemClock.uptimeMillis() - startTime;
             maybeLogQueryToEventLog(durationMillis, uri, projection, selection, sortOrder);
             // Wrap the cursor object into CursorWrapperInner object
             return new CursorWrapperInner(qCursor, provider);
@@ -583,9 +584,9 @@ public abstract class ContentResolver {
             throw new IllegalArgumentException("Unknown URL " + url);
         }
         try {
-            long startTime = System.currentTimeMillis();
+            long startTime = SystemClock.uptimeMillis();
             Uri createdRow = provider.insert(url, values);
-            long durationMillis = System.currentTimeMillis() - startTime;
+            long durationMillis = SystemClock.uptimeMillis() - startTime;
             maybeLogUpdateToEventLog(durationMillis, url, "insert", null /* where */);
             return createdRow;
         } catch (RemoteException e) {
@@ -642,9 +643,9 @@ public abstract class ContentResolver {
             throw new IllegalArgumentException("Unknown URL " + url);
         }
         try {
-            long startTime = System.currentTimeMillis();
+            long startTime = SystemClock.uptimeMillis();
             int rowsCreated = provider.bulkInsert(url, values);
-            long durationMillis = System.currentTimeMillis() - startTime;
+            long durationMillis = SystemClock.uptimeMillis() - startTime;
             maybeLogUpdateToEventLog(durationMillis, url, "bulkinsert", null /* where */);
             return rowsCreated;
         } catch (RemoteException e) {
@@ -671,9 +672,9 @@ public abstract class ContentResolver {
             throw new IllegalArgumentException("Unknown URL " + url);
         }
         try {
-            long startTime = System.currentTimeMillis();
+            long startTime = SystemClock.uptimeMillis();
             int rowsDeleted = provider.delete(url, where, selectionArgs);
-            long durationMillis = System.currentTimeMillis() - startTime;
+            long durationMillis = SystemClock.uptimeMillis() - startTime;
             maybeLogUpdateToEventLog(durationMillis, url, "delete", where);
             return rowsDeleted;
         } catch (RemoteException e) {
@@ -703,9 +704,9 @@ public abstract class ContentResolver {
             throw new IllegalArgumentException("Unknown URI " + uri);
         }
         try {
-            long startTime = System.currentTimeMillis();
+            long startTime = SystemClock.uptimeMillis();
             int rowsUpdated = provider.update(uri, values, where, selectionArgs);
-            long durationMillis = System.currentTimeMillis() - startTime;
+            long durationMillis = SystemClock.uptimeMillis() - startTime;
             maybeLogUpdateToEventLog(durationMillis, uri, "update", where);
             return rowsUpdated;
         } catch (RemoteException e) {
diff --git a/core/java/android/database/sqlite/SQLiteDatabase.java b/core/java/android/database/sqlite/SQLiteDatabase.java
index 5d1e7cf..a7e6ca0 100644
--- a/core/java/android/database/sqlite/SQLiteDatabase.java
+++ b/core/java/android/database/sqlite/SQLiteDatabase.java
@@ -202,7 +202,7 @@ public class SQLiteDatabase extends SQLiteClosable {
     private long mLastLockMessageTime = 0L;
 
     // always log queries which take 100ms+; shorter queries are sampled accordingly
-    private static final int QUERY_LOG_TIME_IN_NANOS = 100 * 1000000;
+    private static final int QUERY_LOG_TIME_IN_MILLIS = 100;
     private static final int QUERY_LOG_SQL_LENGTH = 64;
     private final Random mRandom = new Random();
 
@@ -1650,7 +1650,7 @@ public class SQLiteDatabase extends SQLiteClosable {
      * @throws SQLException If the SQL string is invalid for some reason
      */
     public void execSQL(String sql) throws SQLException {
-        long timeStart = Debug.threadCpuTimeNanos();
+        long timeStart = SystemClock.uptimeMillis();
         lock();
         try {
             native_execSQL(sql);
@@ -1676,7 +1676,7 @@ public class SQLiteDatabase extends SQLiteClosable {
         if (bindArgs == null) {
             throw new IllegalArgumentException("Empty bindArgs");
         }
-        long timeStart = Debug.threadCpuTimeNanos();
+        long timeStart = SystemClock.uptimeMillis();
         lock();
         SQLiteStatement statement = null;
         try {
@@ -1785,17 +1785,17 @@ public class SQLiteDatabase extends SQLiteClosable {
 
 
 
-    /* package */ void logTimeStat(String sql, long beginNanos) {
+    /* package */ void logTimeStat(String sql, long beginMillis) {
         // Sample fast queries in proportion to the time taken.
         // Quantize the % first, so the logged sampling probability
         // exactly equals the actual sampling rate for this query.
 
         int samplePercent;
-        long nanos = Debug.threadCpuTimeNanos() - beginNanos;
-        if (nanos >= QUERY_LOG_TIME_IN_NANOS) {
+        long durationMillis = SystemClock.uptimeMillis() - beginMillis;
+        if (durationMillis >= QUERY_LOG_TIME_IN_MILLIS) {
             samplePercent = 100;
         } else {
-            samplePercent = (int) (100 * nanos / QUERY_LOG_TIME_IN_NANOS) + 1;
+            samplePercent = (int) (100 * durationMillis / QUERY_LOG_TIME_IN_MILLIS) + 1;
             if (mRandom.nextInt(100) >= samplePercent) return;
         }
 
@@ -1812,8 +1812,8 @@ public class SQLiteDatabase extends SQLiteClosable {
         String blockingPackage = ActivityThread.currentPackageName();
         if (blockingPackage == null) blockingPackage = "";
 
-        int millis = (int) (nanos / 1000000);
-        EventLog.writeEvent(EVENT_DB_OPERATION, mPath, sql, millis, blockingPackage, samplePercent);
+        EventLog.writeEvent(
+            EVENT_DB_OPERATION, mPath, sql, durationMillis, blockingPackage, samplePercent);
     }
 
     /**