From 89101cd9d9b5c1a6ff1ed85eba0613ca4c4802e2 Mon Sep 17 00:00:00 2001 From: Jeff Brown Date: Thu, 27 Oct 2011 21:24:54 -0700 Subject: 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 --- .../android/database/sqlite/SQLiteDatabase.java | 28 ---------------------- core/java/android/database/sqlite/SQLiteDebug.java | 24 +++++++++++++++++++ core/java/android/database/sqlite/SQLiteQuery.java | 20 +++++++++++++++- 3 files changed, 43 insertions(+), 29 deletions(-) (limited to 'core/java/android/database/sqlite') diff --git a/core/java/android/database/sqlite/SQLiteDatabase.java b/core/java/android/database/sqlite/SQLiteDatabase.java index 00d7ce80a6fa..f990be60809d 100644 --- a/core/java/android/database/sqlite/SQLiteDatabase.java +++ b/core/java/android/database/sqlite/SQLiteDatabase.java @@ -306,10 +306,6 @@ public class SQLiteDatabase extends SQLiteClosable { /** 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 mClosedStatementIds = new ArrayList(); @@ -1559,11 +1555,6 @@ public class SQLiteDatabase extends SQLiteClosable { 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 class SQLiteDatabase extends SQLiteClosable { 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) - : "") + ", count is " + count); - } - } releaseDbConnection(db); } return cursor; @@ -1967,7 +1940,6 @@ public class SQLiteDatabase extends SQLiteClosable { 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(); diff --git a/core/java/android/database/sqlite/SQLiteDebug.java b/core/java/android/database/sqlite/SQLiteDebug.java index 9496079178e6..cc057e016fe3 100644 --- a/core/java/android/database/sqlite/SQLiteDebug.java +++ b/core/java/android/database/sqlite/SQLiteDebug.java @@ -18,6 +18,8 @@ package android.database.sqlite; 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. * diff --git a/core/java/android/database/sqlite/SQLiteQuery.java b/core/java/android/database/sqlite/SQLiteQuery.java index 7db0914140b2..faf6cba10679 100644 --- a/core/java/android/database/sqlite/SQLiteQuery.java +++ b/core/java/android/database/sqlite/SQLiteQuery.java @@ -18,6 +18,7 @@ package android.database.sqlite; 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 @@ public class SQLiteQuery extends SQLiteProgram { 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){ -- cgit v1.2.3