Log database lock contention as well (as seperate pseudo-queries).

This also makes the 500ms logging threshold (over which is always
logged, and under which is sub-sampled) configurable via a
SystemProperty, which is mostly useful for interactive debugging when
lock contention is suspected, but could also be useful in the future
as a quick way to adjust this threshold for dogfooders, without code
changes.

Change-Id: I769069d8d870331d89a4aa3239ba50db806fe4d4

2 files changed, 41 insertions, 17 deletions

diff --git a/core/java/android/database/sqlite/SQLiteDatabase.java b/core/java/android/database/sqlite/SQLiteDatabase.java
index 8442602..b52f6e0 100644
--- a/core/java/android/database/sqlite/SQLiteDatabase.java
+++ b/core/java/android/database/sqlite/SQLiteDatabase.java
@@ -213,16 +213,23 @@ public class SQLiteDatabase extends SQLiteClosable {
 
     // Things related to query logging/sampling for debugging
     // slow/frequent queries during development.  Always log queries
-    // which take 500ms+; shorter queries are sampled accordingly.
-    // Commit statements, which are typically slow, are logged
-    // together with the most recently executed SQL statement, for
-    // disambiguation.
-    private static final int QUERY_LOG_TIME_IN_MILLIS = 500;
+    // which take (by default) 500ms+; shorter queries are sampled
+    // accordingly.  Commit statements, which are typically slow, are
+    // logged together with the most recently executed SQL statement,
+    // for disambiguation.  The 500ms value is configurable via a
+    // SystemProperty, but developers actively debugging database I/O
+    // should probably use the regular log tunable,
+    // LOG_SLOW_QUERIES_PROPERTY, defined below.
+    private static int sQueryLogTimeInMillis = 0;  // lazily initialized
     private static final int QUERY_LOG_SQL_LENGTH = 64;
     private static final String COMMIT_SQL = "COMMIT;";
     private final Random mRandom = new Random();
     private String mLastSqlStatement = null;
 
+    // String prefix for slow database query EventLog records that show
+    // lock acquistions of the database.
+    /* package */ static final String GET_LOCK_LOG_PREFIX = "GETLOCK:";
+
     /** Used by native code, do not rename */
     /* package */ int mNativeHandle = 0;
 
@@ -1722,6 +1729,7 @@ public class SQLiteDatabase extends SQLiteClosable {
         }
         long timeStart = SystemClock.uptimeMillis();
         lock();
+        logTimeStat(mLastSqlStatement, timeStart, GET_LOCK_LOG_PREFIX);
         try {
             native_execSQL(sql);
         } catch (SQLiteDatabaseCorruptException e) {
@@ -1735,9 +1743,9 @@ public class SQLiteDatabase extends SQLiteClosable {
         // SQL statement for disambiguation.  Note that instance
         // equality to COMMIT_SQL is safe here.
         if (sql == COMMIT_SQL) {
-            logTimeStat(sql + mLastSqlStatement, timeStart);
+            logTimeStat(mLastSqlStatement, timeStart, COMMIT_SQL);
         } else {
-            logTimeStat(sql, timeStart);
+            logTimeStat(sql, timeStart, null);
         }
     }
 
@@ -1857,9 +1865,11 @@ public class SQLiteDatabase extends SQLiteClosable {
         return mPath;
     }
 
-
-
     /* package */ void logTimeStat(String sql, long beginMillis) {
+        logTimeStat(sql, beginMillis, null);
+    }
+
+    /* package */ void logTimeStat(String sql, long beginMillis, String prefix) {
         // Keep track of the last statement executed here, as this is
         // the common funnel through which all methods of hitting
         // libsqlite eventually flow.
@@ -1871,13 +1881,27 @@ public class SQLiteDatabase extends SQLiteClosable {
 
         int samplePercent;
         long durationMillis = SystemClock.uptimeMillis() - beginMillis;
-        if (durationMillis >= QUERY_LOG_TIME_IN_MILLIS) {
+        if (durationMillis == 0 && prefix == GET_LOCK_LOG_PREFIX) {
+            // The common case is locks being uncontended.  Don't log those,
+            // even at 1%, which is our default below.
+            return;
+        }
+        if (sQueryLogTimeInMillis == 0) {
+            sQueryLogTimeInMillis = SystemProperties.getInt("db.db_operation.threshold_ms", 500);
+        }
+        if (durationMillis >= sQueryLogTimeInMillis) {
             samplePercent = 100;
-        } else {
-            samplePercent = (int) (100 * durationMillis / QUERY_LOG_TIME_IN_MILLIS) + 1;
+        } else {;
+            samplePercent = (int) (100 * durationMillis / sQueryLogTimeInMillis) + 1;
             if (mRandom.nextInt(100) >= samplePercent) return;
         }
 
+        // Note: the prefix will be "COMMIT;" or "GETLOCK:" when non-null.  We wait to do
+        // it here so we avoid allocating in the common case.
+        if (prefix != null) {
+            sql = prefix + sql;
+        }
+
         if (sql.length() > QUERY_LOG_SQL_LENGTH) sql = sql.substring(0, QUERY_LOG_SQL_LENGTH);
 
         // ActivityThread.currentPackageName() only returns non-null if the
diff --git a/core/java/android/database/sqlite/SQLiteQuery.java b/core/java/android/database/sqlite/SQLiteQuery.java
index 7cd9561..43d2fac 100644
--- a/core/java/android/database/sqlite/SQLiteQuery.java
+++ b/core/java/android/database/sqlite/SQLiteQuery.java
@@ -51,20 +51,20 @@ public class SQLiteQuery extends SQLiteProgram {
 
     /**
      * Reads rows into a buffer. This method acquires the database lock.
-     * 
+     *
      * @param window The window to fill into
      * @return number of total rows in the query
      */
-    /* package */ int fillWindow(CursorWindow window,  
+    /* package */ int fillWindow(CursorWindow window,
             int maxRead, int lastPos) {
         long timeStart = SystemClock.uptimeMillis();
         mDatabase.lock();
-
+        mDatabase.logTimeStat(mSql, timeStart, SQLiteDatabase.GET_LOCK_LOG_PREFIX);
         try {
             acquireReference();
             try {
                 window.acquireReference();
-                // if the start pos is not equal to 0, then most likely window is 
+                // if the start pos is not equal to 0, then most likely window is
                 // too small for the data set, loading by another thread
                 // is not safe in this situation. the native code will ignore maxRead
                 int numRows = native_fill_window(window, window.getStartPosition(), mOffsetIndex,
@@ -83,7 +83,7 @@ public class SQLiteQuery extends SQLiteProgram {
                 mDatabase.onCorruption();
                 throw e;
             } finally {
-                window.releaseReference();                
+                window.releaseReference();
             }
         } finally {
             releaseReference();