Merge "Improve the slow query instrumentation." into ics-mr0

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;