From 80259d00ba8fd68309f6d9063e8fd7cbd416711d Mon Sep 17 00:00:00 2001
From: Peter Serwylo <peter@serwylo.com>
Date: Tue, 22 Aug 2017 10:42:26 +1000
Subject: [PATCH] More precise (and correct) logging of slow queries in debug
 mode.

Some queries are deferred, and then forced to run by Android by invoking
`getCount()`. Under these circumstances, the measured speed of the query
execution is 1ms.

This adds speed logging around `getCount()` in case that is the first time
the query is run.
---
 .../org/fdroid/fdroid/data/LoggingQuery.java  | 29 ++++++++++++++++++-
 1 file changed, 28 insertions(+), 1 deletion(-)

diff --git a/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java b/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java
index bf257a0de..fcd66d202 100644
--- a/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java
+++ b/app/src/main/java/org/fdroid/fdroid/data/LoggingQuery.java
@@ -1,6 +1,7 @@
 package org.fdroid.fdroid.data;
 
 import android.database.Cursor;
+import android.database.CursorWrapper;
 import android.database.sqlite.SQLiteDatabase;
 
 import org.fdroid.fdroid.BuildConfig;
@@ -61,11 +62,37 @@ final class LoggingQuery {
             if (queryDuration >= SLOW_QUERY_DURATION) {
                 logSlowQuery(queryDuration);
             }
-            return cursor;
+
+            return new LogGetCountCursorWrapper(cursor);
         }
         return db.rawQuery(query, queryArgs);
     }
 
+    /**
+     * Sometimes the query will not actually be run when invoking "query()".
+     * Under such circumstances, it falls to the {@link android.content.ContentProvider#query}
+     * method to manually invoke the {@link Cursor#getCount()} method to force query execution.
+     * It does so with a comment saying "Force query execution". When this happens, the call to
+     * query() takes 1ms, whereas the call go getCount() is the bit which takes time.
+     * As such, we will also track that method duration in order to potentially log slow queries.
+     */
+    private class LogGetCountCursorWrapper extends CursorWrapper {
+        private LogGetCountCursorWrapper(Cursor cursor) {
+            super(cursor);
+        }
+
+        @Override
+        public int getCount() {
+            long startTime = System.currentTimeMillis();
+            int count = super.getCount();
+            long queryDuration = System.currentTimeMillis() - startTime;
+            if (queryDuration >= SLOW_QUERY_DURATION) {
+                logSlowQuery(queryDuration);
+            }
+            return count;
+        }
+    }
+
     private void execSQLInternal() {
         if (BuildConfig.DEBUG) {
             long startTime = System.currentTimeMillis();