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.
This commit is contained in:
Peter Serwylo 2017-08-22 10:42:26 +10:00 committed by Hans-Christoph Steiner
parent d42d83321b
commit 80259d00ba

View File

@ -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();