Merge pull request #87 from square/jw/log-when-query-runs-with-times

Switch logging to happen at query run, not trigger. Add timing.

Author: JakeWharton

sqlbrite/src/main/java/com/squareup/sqlbrite/BriteContentResolver.java

@@ -33,6 +33,8 @@
 
 import static com.squareup.sqlbrite.SqlBrite.Logger;
 import static com.squareup.sqlbrite.SqlBrite.Query;
+import static java.lang.System.nanoTime;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 /**
  * A lightweight wrapper around {@link ContentResolver} which allows for continuously observing
@@ -80,19 +82,24 @@ public QueryObservable createQuery(@NonNull final Uri uri, @Nullable final Strin
       final String sortOrder, final boolean notifyForDescendents) {
     final Query query = new Query() {
       @Override public Cursor run() {
-        return contentResolver.query(uri, projection, selection, selectionArgs, sortOrder);
+        long startNanos = nanoTime();
+        Cursor cursor = contentResolver.query(uri, projection, selection, selectionArgs, sortOrder);
+        long tookMillis = NANOSECONDS.toMillis(nanoTime() - startNanos);
+
+        if (logging) {
+          log("QUERY (%sms)\n  uri: %s\n  projection: %s\n  selection: %s\n  selectionArgs: %s\n  "
+                  + "sortOrder: %s\n  notifyForDescendents: %s", tookMillis, uri,
+              Arrays.toString(projection), selection, Arrays.toString(selectionArgs), sortOrder,
+              notifyForDescendents);
+        }
+
+        return cursor;
       }
     };
     OnSubscribe<Query> subscribe = new OnSubscribe<Query>() {
       @Override public void call(final Subscriber<? super Query> subscriber) {
         final ContentObserver observer = new ContentObserver(contentObserverHandler) {
           @Override public void onChange(boolean selfChange) {
-            if (logging) {
-              log("QUERY\n  uri: %s\n  projection: %s\n  selection: %s\n  selectionArgs: %s\n  "
-                      + "sortOrder: %s\n  notifyForDescendents: %s", uri,
-                  Arrays.toString(projection), selection, Arrays.toString(selectionArgs), sortOrder,
-                  notifyForDescendents);
-            }
             subscriber.onNext(query);
           }
         };

sqlbrite/src/main/java/com/squareup/sqlbrite/BriteDatabase.java

@@ -43,15 +43,15 @@
 import static android.database.sqlite.SQLiteDatabase.CONFLICT_NONE;
 import static android.database.sqlite.SQLiteDatabase.CONFLICT_REPLACE;
 import static android.database.sqlite.SQLiteDatabase.CONFLICT_ROLLBACK;
+import static java.lang.System.nanoTime;
 import static java.lang.annotation.RetentionPolicy.SOURCE;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 /**
  * A lightweight wrapper around {@link SQLiteOpenHelper} which allows for continuously observing
  * the result of a query. Create using a {@link SqlBrite} instance.
  */
 public final class BriteDatabase implements Closeable {
-  private static final Set<String> INITIAL_TRIGGER = Collections.singleton("<initial>");
-
   private final SQLiteOpenHelper helper;
   private final SqlBrite.Logger logger;
 
@@ -285,7 +285,17 @@ private QueryObservable createQuery(final Func1<Set<String>, Boolean> tableFilte
         if (transactions.get() != null) {
           throw new IllegalStateException("Cannot execute observable query in a transaction.");
         }
-        return getReadableDatabase().rawQuery(sql, args);
+
+        long startNanos = nanoTime();
+        Cursor cursor = getReadableDatabase().rawQuery(sql, args);
+        long tookMillis = NANOSECONDS.toMillis(nanoTime() - startNanos);
+
+        if (logging) {
+          log("QUERY (%sms)\n  tables: %s\n  sql: %s\n  args: %s", tookMillis, tableFilter, sql,
+              Arrays.toString(args));
+        }
+
+        return cursor;
       }
 
       @Override public String toString() {
@@ -295,16 +305,12 @@ private QueryObservable createQuery(final Func1<Set<String>, Boolean> tableFilte
 
     Observable<Query> queryObservable = triggers //
         .filter(tableFilter) // Only trigger on tables we care about.
-        .startWith(INITIAL_TRIGGER) // Immediately execute the query for initial value.
         .map(new Func1<Set<String>, Query>() {
           @Override public Query call(Set<String> trigger) {
-            if (logging) {
-              log("QUERY\n  trigger: %s\n  tables: %s\n  sql: %s\n  args: %s", trigger, tableFilter,
-                  sql, Arrays.toString(args));
-            }
             return query;
           }
         }) //
+        .startWith(query) // Immediately trigger the query for initial value.
         .onBackpressureLatest() //
         .doOnSubscribe(new Action0() {
           @Override public void call() {
@@ -324,8 +330,15 @@ private QueryObservable createQuery(final Func1<Set<String>, Boolean> tableFilte
    */
   @CheckResult // TODO @WorkerThread
   public Cursor query(@NonNull String sql, @NonNull String... args) {
-    if (logging) log("QUERY\n  sql: %s\n  args: %s", sql, Arrays.toString(args));
-    return getReadableDatabase().rawQuery(sql, args);
+    long startNanos = nanoTime();
+    Cursor cursor = getReadableDatabase().rawQuery(sql, args);
+    long tookMillis = NANOSECONDS.toMillis(nanoTime() - startNanos);
+
+    if (logging) {
+      log("QUERY (%sms)\n  sql: %s\n  args: %s", tookMillis, sql, Arrays.toString(args));
+    }
+
+    return cursor;
   }
 
   /**