[geary/mjog/db-result-timing: 1/5] Geary.Db.DatabaseConnection: Check elapsed time for exec statements

[Michael Gratton <mjog src gnome org>]

commit 485868d570ef95283c541a1a180fca88fec7a9ef
Author: Michael Gratton <mike vee net>
Date:   Tue Sep 8 08:34:23 2020 +1000

    Geary.Db.DatabaseConnection: Check elapsed time for exec statements
    
    Re-work elapsed timer to be usable in other context objects, use it
    for timing exec query execution.

 src/engine/db/db-context.vala             | 13 +++++++++++++
 src/engine/db/db-database-connection.vala |  9 ++++++---
 src/engine/db/db-result.vala              | 23 +++++------------------
 3 files changed, 24 insertions(+), 21 deletions(-)
---
diff --git a/src/engine/db/db-context.vala b/src/engine/db/db-context.vala
index a59f6c4c0..6713f6c82 100644
--- a/src/engine/db/db-context.vala
+++ b/src/engine/db/db-context.vala
@@ -61,6 +61,19 @@ public abstract class Geary.Db.Context : BaseObject, Logging.Source {
     /** {@inheritDoc} */
     public abstract Logging.State to_logging_state();
 
+
+    protected inline void check_elapsed(string message,
+                                        GLib.Timer timer)
+        throws DatabaseError {
+        var elapsed = timer.elapsed();
+        var threshold = (get_connection().busy_timeout * 1000.0) / 2.0;
+        if (threshold > 0 && elapsed > threshold) {
+            warning("%s: elapsed time: %lfs (>50%)", message, elapsed);
+        } else if (elapsed > 1.0) {
+            debug("%s: elapsed time: %lfs (>1s)", message, elapsed);
+        }
+    }
+
     protected inline int throw_on_error(string? method, int result, string? raw = null) throws DatabaseError 
{
         return Db.throw_on_error(this, method, result, raw);
     }
diff --git a/src/engine/db/db-database-connection.vala b/src/engine/db/db-database-connection.vala
index dd311bea6..d58911e47 100644
--- a/src/engine/db/db-database-connection.vala
+++ b/src/engine/db/db-database-connection.vala
@@ -137,7 +137,9 @@ public class Geary.Db.DatabaseConnection : Context, Connection {
         }
 
         check_cancelled("Connection.exec", cancellable);
-        throw_on_error("Connection.exec", db.exec(sql), sql);
+        var timer = new GLib.Timer();
+        throw_on_error("Connection.exec_file", this.db.exec(sql), sql);
+        check_elapsed("Query \"%s\"".printf(sql), timer);
     }
 
     /** {@inheritDoc} */
@@ -147,8 +149,9 @@ public class Geary.Db.DatabaseConnection : Context, Connection {
 
         string sql;
         FileUtils.get_contents(file.get_path(), out sql);
-
-        exec(sql, cancellable);
+        var timer = new GLib.Timer();
+        throw_on_error("Connection.exec_file", this.db.exec(sql), sql);
+        check_elapsed(file.get_path(), timer);
     }
 
     /**
diff --git a/src/engine/db/db-result.vala b/src/engine/db/db-result.vala
index 300d3afa9..b53821793 100644
--- a/src/engine/db/db-result.vala
+++ b/src/engine/db/db-result.vala
@@ -39,24 +39,11 @@ public class Geary.Db.Result : Geary.Db.Context {
 
         if (!finished) {
             var timer = new GLib.Timer();
-            finished = throw_on_error("Result.next", statement.stmt.step(), statement.sql) != Sqlite.ROW;
-            var elapsed = timer.elapsed();
-            var threshold = (get_connection().busy_timeout * 1000.0) / 2.0;
-            if (threshold > 0 && elapsed > threshold) {
-                warning(
-                    "Step for \"%s\" took elapsed time: %lfs (>50%)",
-                    statement.sql,
-                    elapsed
-                );
-            } else if (elapsed > 1.0) {
-                debug(
-                    "Step for \"%s\" took elapsed time: %lfs (>1s)",
-                    statement.sql,
-                    elapsed
-                );
-            }
-
-            log_result(finished ? "NO ROW" : "ROW");
+            this.finished = throw_on_error(
+                "Result.next", statement.stmt.step(), statement.sql
+            ) != Sqlite.ROW;
+            check_elapsed("Result.next", timer);
+            log_result(this.finished ? "NO ROW" : "ROW");
         }
 
         return !finished;