Improve the slow query instrumentation.

On user-debug and eng builds, you can set the
"db.log.slow_query_threshold" system property to queries that
take longer than the specified number of milliseconds.
Set it to 0 to log all queries.

This property has been around for a while but it was implemented
poorly.  In particular, it *changed* the behavior of the query
by calling getCount() while holding the Db connection.
In normal operation, the query will not actually run until later.

By putting the timing logic into fillWindow() instead, we ensure
that we only measure queries that actually ran.  We also capture
cases where the cursor window gets filled multiple times.

Bug: 5520301
Change-Id: I174f5e1ea15831a1d22a36e9a804d7755f230b38

Author: Jeff Brown

core/java/android/database/CursorWindow.java

@@ -55,6 +55,7 @@ public class CursorWindow extends SQLiteClosable implements Parcelable {
     public int mWindowPtr;
 
     private int mStartPos;
+    private final String mName;
 
     private final CloseGuard mCloseGuard = CloseGuard.get();
 
@@ -85,6 +86,8 @@ private static native void nativeCopyStringToBuffer(int windowPtr, int row, int
     private static native boolean nativePutDouble(int windowPtr, double value, int row, int column);
     private static native boolean nativePutNull(int windowPtr, int row, int column);
 
+    private static native String nativeGetName(int windowPtr);
+
     /**
      * Creates a new empty cursor window and gives it a name.
      * <p>
@@ -100,6 +103,7 @@ private static native void nativeCopyStringToBuffer(int windowPtr, int row, int
      */
     public CursorWindow(String name, boolean localWindow) {
         mStartPos = 0;
+        mName = name;
         mWindowPtr = nativeCreate(name, sCursorWindowSize, localWindow);
         if (mWindowPtr == 0) {
             throw new CursorWindowAllocationException("Cursor window allocation of " +
@@ -130,6 +134,7 @@ private CursorWindow(Parcel source) {
             throw new CursorWindowAllocationException("Cursor window could not be "
                     + "created from binder.");
         }
+        mName = nativeGetName(mWindowPtr);
         mCloseGuard.open("close");
     }
 
@@ -156,6 +161,14 @@ private void dispose() {
         }
     }
 
+    /**
+     * Gets the name of this cursor window.
+     * @hide
+     */
+    public String getName() {
+        return mName;
+    }
+
     /**
      * Closes the cursor window and frees its underlying resources when all other
      * remaining references have been released.
@@ -778,4 +791,9 @@ private String printStats() {
         String s = (buff.length() > 980) ? buff.substring(0, 980) : buff.toString();
         return "# Open Cursors=" + total + s;
     }
+
+    @Override
+    public String toString() {
+        return getName() + " {" + Integer.toHexString(mWindowPtr) + "}";
+    }
 }

core/java/android/database/sqlite/SQLiteDatabase.java

@@ -306,10 +306,6 @@ synchronized void setLastSqlStatement(String sql) {
     /** Used to find out where this object was created in case it never got closed. */
     private final Throwable mStackTrace;
 
-    // System property that enables logging of slow queries. Specify the threshold in ms.
-    private static final String LOG_SLOW_QUERIES_PROPERTY = "db.log.slow_query_threshold";
-    private final int mSlowQueryThreshold;
-
     /** stores the list of statement ids that need to be finalized by sqlite */
     private final ArrayList<Integer> mClosedStatementIds = new ArrayList<Integer>();
 
@@ -1559,11 +1555,6 @@ public Cursor rawQueryWithFactory(
             String editTable) {
         verifyDbIsOpen();
         BlockGuard.getThreadPolicy().onReadFromDisk();
-        long timeStart = 0;
-
-        if (false || mSlowQueryThreshold != -1) {
-            timeStart = System.currentTimeMillis();
-        }
 
         SQLiteDatabase db = getDbConnection(sql);
         SQLiteCursorDriver driver = new SQLiteDirectCursorDriver(db, sql, editTable);
@@ -1574,24 +1565,6 @@ public Cursor rawQueryWithFactory(
                     cursorFactory != null ? cursorFactory : mFactory,
                     selectionArgs);
         } finally {
-            if (false || mSlowQueryThreshold != -1) {
-
-                // Force query execution
-                int count = -1;
-                if (cursor != null) {
-                    count = cursor.getCount();
-                }
-
-                long duration = System.currentTimeMillis() - timeStart;
-
-                if (false || duration >= mSlowQueryThreshold) {
-                    Log.v(SQLiteCursor.TAG,
-                          "query (" + duration + " ms): " + driver.toString() + ", args are "
-                                  + (selectionArgs != null
-                                  ? TextUtils.join(",", selectionArgs)
-                                  : "<null>")  + ", count is " + count);
-                }
-            }
             releaseDbConnection(db);
         }
         return cursor;
@@ -1967,7 +1940,6 @@ private SQLiteDatabase(String path, CursorFactory factory, int flags,
         setMaxSqlCacheSize(DEFAULT_SQL_CACHE_SIZE);
         mFlags = flags;
         mPath = path;
-        mSlowQueryThreshold = SystemProperties.getInt(LOG_SLOW_QUERIES_PROPERTY, -1);
         mStackTrace = new DatabaseObjectNotClosedException().fillInStackTrace();
         mFactory = factory;
         mPrograms = new WeakHashMap<SQLiteClosable,Object>();

core/java/android/database/sqlite/SQLiteDebug.java

@@ -18,6 +18,8 @@
 
 import java.util.ArrayList;
 
+import android.os.Build;
+import android.os.SystemProperties;
 import android.util.Log;
 
 /**
@@ -64,6 +66,28 @@ public final class SQLiteDebug {
     public static final boolean DEBUG_LOCK_TIME_TRACKING_STACK_TRACE =
             Log.isLoggable("SQLiteLockStackTrace", Log.VERBOSE);
 
+    /**
+     * True to enable database performance testing instrumentation.
+     * @hide
+     */
+    public static final boolean DEBUG_LOG_SLOW_QUERIES = Build.IS_DEBUGGABLE;
+
+    /**
+     * Determines whether a query should be logged.
+     *
+     * Reads the "db.log.slow_query_threshold" system property, which can be changed
+     * by the user at any time.  If the value is zero, then all queries will
+     * be considered slow.  If the value does not exist, then no queries will
+     * be considered slow.
+     *
+     * This value can be changed dynamically while the system is running.
+     * @hide
+     */
+    public static final boolean shouldLogSlowQuery(long elapsedTimeMillis) {
+        int slowQueryMillis = SystemProperties.getInt("db.log.slow_query_threshold", -1);
+        return slowQueryMillis >= 0 && elapsedTimeMillis > slowQueryMillis;
+    }
+
     /**
      * Contains statistics about the active pagers in the current process.
      *

core/java/android/database/sqlite/SQLiteQuery.java

@@ -18,6 +18,7 @@
 
 import android.database.CursorWindow;
 import android.os.SystemClock;
+import android.text.TextUtils;
 import android.util.Log;
 
 /**
@@ -32,6 +33,7 @@ public class SQLiteQuery extends SQLiteProgram {
 
     private static native int nativeFillWindow(int databasePtr, int statementPtr, int windowPtr,
             int startPos, int offsetParam);
+
     private static native int nativeColumnCount(int statementPtr);
     private static native String nativeColumnName(int statementPtr, int columnIndex);
 
@@ -80,8 +82,24 @@ private static native int nativeFillWindow(int databasePtr, int statementPtr, in
             acquireReference();
             try {
                 window.acquireReference();
+                int startPos = window.getStartPosition();
                 int numRows = nativeFillWindow(nHandle, nStatement, window.mWindowPtr,
-                        window.getStartPosition(), mOffsetIndex);
+                        startPos, mOffsetIndex);
+                if (SQLiteDebug.DEBUG_LOG_SLOW_QUERIES) {
+                    long elapsed = SystemClock.uptimeMillis() - timeStart;
+                    if (SQLiteDebug.shouldLogSlowQuery(elapsed)) {
+                        Log.d(TAG, "fillWindow took " + elapsed
+                                + " ms: window=\"" + window
+                                + "\", startPos=" + startPos
+                                + ", offset=" + mOffsetIndex
+                                + ", filledRows=" + window.getNumRows()
+                                + ", countedRows=" + numRows
+                                + ", query=\"" + mSql + "\""
+                                + ", args=[" + (mBindArgs != null ?
+                                        TextUtils.join(", ", mBindArgs.values()) : "")
+                                + "]");
+                    }
+                }
                 mDatabase.logTimeStat(mSql, timeStart);
                 return numRows;
             } catch (IllegalStateException e){

core/java/android/os/Build.java

@@ -325,6 +325,13 @@ public static class VERSION_CODES {
     public static final String USER = getString("ro.build.user");
     public static final String HOST = getString("ro.build.host");
 
+    /**
+     * Returns true if we are running a debug build such as "user-debug" or "eng".
+     * @hide
+     */
+    public static final boolean IS_DEBUGGABLE =
+            SystemProperties.getInt("ro.debuggable", 0) == 1;
+
     /**
      * Returns the version string for the radio firmware.  May return
      * null (if, for instance, the radio is not currently on).

core/jni/android_database_CursorWindow.cpp

@@ -104,6 +104,11 @@ static void nativeDispose(JNIEnv* env, jclass clazz, jint windowPtr) {
     }
 }
 
+static jstring nativeGetName(JNIEnv* env, jclass clazz, jint windowPtr) {
+    CursorWindow* window = reinterpret_cast<CursorWindow*>(windowPtr);
+    return env->NewStringUTF(window->name().string());
+}
+
 static void nativeWriteToParcel(JNIEnv * env, jclass clazz, jint windowPtr,
         jobject parcelObj) {
     CursorWindow* window = reinterpret_cast<CursorWindow*>(windowPtr);
@@ -485,6 +490,8 @@ static JNINativeMethod sMethods[] =
             (void*)nativeDispose },
     { "nativeWriteToParcel", "(ILandroid/os/Parcel;)V",
             (void*)nativeWriteToParcel },
+    { "nativeGetName", "(I)Ljava/lang/String;",
+            (void*)nativeGetName },
     { "nativeClear", "(I)V",
             (void*)nativeClear },
     { "nativeGetNumRows", "(I)I",

libs/binder/CursorWindow.cpp

@@ -211,7 +211,7 @@ uint32_t CursorWindow::alloc(size_t size, bool aligned) {
     uint32_t offset = mHeader->freeOffset + padding;
     uint32_t nextFreeOffset = offset + size;
     if (nextFreeOffset > mSize) {
-        LOGE("Window is full: requested allocation %d bytes, "
+        LOGW("Window is full: requested allocation %d bytes, "
                 "free space %d bytes, window size %d bytes",
                 size, freeSpace(), mSize);
         return 0;