From 48ac66b315394d7a85ccfc9efd6a1847feac4fbc Mon Sep 17 00:00:00 2001 From: Peter Serwylo Date: Thu, 7 Jul 2016 16:43:45 +1000 Subject: [PATCH] Added LoggingQuery for diagnostics during debug mode. SQLite has a very nice "EXPLAIN QUERY PLAN" command (https://sqlite.org/eqp.html). It is not really meant to be used in production code, as per the docs, but it is super helpful at diagnosing missing indexes or other performance problems with databases. I find it much better than, for example, the MySQL alternative. This commit routes queries from the `ApkProvider` and `AppProvider` through a `LoggingQuery` which (in debug builds) times queries, and if they take longer than a certain threshold, outputs them to logcat. In addition, it will then ask sqlite to explain its query plan for that same query, and output that to logcat too. --- .../org/fdroid/fdroid/data/ApkProvider.java | 2 +- .../org/fdroid/fdroid/data/AppProvider.java | 2 +- .../org/fdroid/fdroid/data/LoggingQuery.java | 119 ++++++++++++++++++ 3 files changed, 121 insertions(+), 2 deletions(-) create mode 100644 app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java diff --git a/app/src/main/java/org/fdroid/fdroid/data/ApkProvider.java b/app/src/main/java/org/fdroid/fdroid/data/ApkProvider.java index dbc667ffa..cbb265a74 100644 --- a/app/src/main/java/org/fdroid/fdroid/data/ApkProvider.java +++ b/app/src/main/java/org/fdroid/fdroid/data/ApkProvider.java @@ -459,7 +459,7 @@ public class ApkProvider extends FDroidProvider { queryBuilder.addSelection(query); queryBuilder.addOrderBy(sortOrder); - Cursor cursor = db().rawQuery(queryBuilder.toString(), queryBuilder.getArgs()); + Cursor cursor = LoggingQuery.query(db(), queryBuilder.toString(), queryBuilder.getArgs()); cursor.setNotificationUri(getContext().getContentResolver(), uri); return cursor; } diff --git a/app/src/main/java/org/fdroid/fdroid/data/AppProvider.java b/app/src/main/java/org/fdroid/fdroid/data/AppProvider.java index 3dedab94f..f16999bc8 100644 --- a/app/src/main/java/org/fdroid/fdroid/data/AppProvider.java +++ b/app/src/main/java/org/fdroid/fdroid/data/AppProvider.java @@ -785,7 +785,7 @@ public class AppProvider extends FDroidProvider { query.addFields(projection); // TODO: Make the order of addFields/addSelection not dependent on each other... query.addOrderBy(sortOrder); - Cursor cursor = db().rawQuery(query.toString(), query.getArgs()); + Cursor cursor = LoggingQuery.query(db(), query.toString(), query.getArgs()); cursor.setNotificationUri(getContext().getContentResolver(), uri); return cursor; } diff --git a/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java b/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java new file mode 100644 index 000000000..69e90d880 --- /dev/null +++ b/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java @@ -0,0 +1,119 @@ +package org.fdroid.fdroid.data; + +import android.database.Cursor; +import android.database.sqlite.SQLiteDatabase; + +import org.fdroid.fdroid.BuildConfig; +import org.fdroid.fdroid.Utils; + +/** + * Helper class to log slow queries to logcat when in debug mode. When not in debug mode, it + * runs the queries without any logging. + * + * Here is an example of what would be output to logcat for a query that takes too long (except the + * query would not be formatted as nicely): + * + * Query [155ms]: + * SELECT fdroid_app.rowid as _id, ... + * FROM fdroid_app + * LEFT JOIN fdroid_apk ON (fdroid_apk.appId = fdroid_app.rowid) + * LEFT JOIN fdroid_repo ON (fdroid_apk.repo = fdroid_repo._id) + * LEFT JOIN fdroid_installedApp AS installed ON (installed.appId = fdroid_app.id) + * LEFT JOIN fdroid_apk AS suggestedApk ON (fdroid_app.suggestedVercode = suggestedApk.vercode AND fdroid_app.rowid = suggestedApk.appId) + * WHERE + * fdroid_repo.isSwap = 0 OR fdroid_repo.isSwap IS NULL + * GROUP BY fdroid_app.rowid + * ORDER BY fdroid_app.name COLLATE LOCALIZED + * Explain: + * SCAN TABLE fdroid_app + * SEARCH TABLE fdroid_apk USING COVERING INDEX sqlite_autoindex_fdroid_apk_1 (appId=?) + * SEARCH TABLE fdroid_repo USING INTEGER PRIMARY KEY (rowid=?) + * SEARCH TABLE fdroid_installedApp AS installed USING INDEX sqlite_autoindex_fdroid_installedApp_1 (appId=?) + * SEARCH TABLE fdroid_apk AS suggestedApk USING INDEX sqlite_autoindex_fdroid_apk_1 (appId=? AND vercode=?) + * USE TEMP B-TREE FOR ORDER BY + */ +public class LoggingQuery { + + private static final long SLOW_QUERY_DURATION = 100; + private static final String TAG = "Slow Query"; + + private final SQLiteDatabase db; + private final String query; + private final String[] queryArgs; + + public LoggingQuery(SQLiteDatabase db, String query, String[] queryArgs) { + this.db = db; + this.query = query; + this.queryArgs = queryArgs; + } + + /** + * When running a debug build, this will log details (including query plans) for any query which + * takes longer than {@link LoggingQuery#SLOW_QUERY_DURATION}. + */ + public Cursor rawQuery() { + if (BuildConfig.DEBUG) { + long startTime = System.currentTimeMillis(); + Cursor cursor = db.rawQuery(query, queryArgs); + long queryDuration = System.currentTimeMillis() - startTime; + + if (queryDuration >= SLOW_QUERY_DURATION) { + logSlowQuery(queryDuration); + } + return cursor; + } else { + return db.rawQuery(query, queryArgs); + } + } + + /** + * Log the query and its duration to the console. In addition, execute an "EXPLAIN QUERY PLAN" + * for the query in question so that the query can be diagnosed (https://sqlite.org/eqp.html) + */ + private void logSlowQuery(long queryDuration) { + StringBuilder sb = new StringBuilder(); + sb.append("Query [") + .append(queryDuration) + .append("ms]: ") + .append(query); + + try { + StringBuilder sbExplain = new StringBuilder("\nExplain:\n"); + for (String plan : getExplainQueryPlan()) { + sbExplain.append(" ").append(plan).append("\n"); + } + sb.append(sbExplain); + } catch (Exception e) { + // Ignore exception, we caught this because the SQLite docs say explain query plan can + // change between versions. We do our best in getExplainQueryPlan() to mitigate this, + // but it may still break with newer releases. In that case, at least we will still be + // logging the slow query to logcat which is helpful. + } + + Utils.debugLog(TAG, sb.toString()); + } + + private String[] getExplainQueryPlan() { + Cursor cursor = db.rawQuery("EXPLAIN QUERY PLAN " + query, queryArgs); + String[] plan = new String[cursor.getCount()]; + cursor.moveToFirst(); + while (!cursor.isAfterLast()) { + // The docs at https://sqlite.org/eqp.html talk about how the output format of + // EXPLAIN QUERY PLAN can change between SQLite versions. This has been observed + // between the sqlite versions on Android 2.3.3 and Android 5.0. However, it seems + // that the last column is always the one with the interesting details that we wish + // to log. If this fails for some reason, then hey, it is only for debug builds, right? + if (cursor.getColumnCount() > 0) { + int index = cursor.getColumnCount() - 1; + plan[cursor.getPosition()] = cursor.getString(index); + } + cursor.moveToNext(); + } + cursor.close(); + return plan; + } + + public static Cursor query(SQLiteDatabase db, String query, String[] queryBuilderArgs) { + return new LoggingQuery(db, query, queryBuilderArgs).rawQuery(); + } +}