[geary/mjog/db-result-timing: 1/2] Geary.Db: Update SQL logging

[Michael Gratton <mjog src gnome org>]

commit 0f60c285df50586058f9368c29f7b288c8076b76
Author: Michael Gratton <mike vee net>
Date:   Wed Sep 9 18:48:43 2020 +1000

    Geary.Db: Update SQL logging
    
    Ensure all code paths that execute SQL are logging it if enabled, and
    clean up the log formatting.
    
    Add new `enable_result_logging` static property to control result
    logging separately from SQL logging, so we can get SQL logged without
    having to see email. Clean up result formatting, and keep track of the
    current result row number and log that as context.

 src/engine/db/db-context.vala             | 17 +++++++++++++----
 src/engine/db/db-database-connection.vala | 14 +++++++++-----
 src/engine/db/db-result.vala              | 27 +++++++++++++++------------
 3 files changed, 37 insertions(+), 21 deletions(-)
---
diff --git a/src/engine/db/db-context.vala b/src/engine/db/db-context.vala
index 2ba8b305d..7b8b9d654 100644
--- a/src/engine/db/db-context.vala
+++ b/src/engine/db/db-context.vala
@@ -16,16 +16,25 @@
 public abstract class Geary.Db.Context : BaseObject, Logging.Source {
 
 
+    /** The GLib logging domain used by this class. */
+    public const string LOGGING_DOMAIN = Logging.DOMAIN + ".Db";
+
+
     /**
-     * Determines if SQL queries and results will be logged.
+     * Determines if SQL queries will be logged.
      *
-     * This will cause extremely verbose logging, so enable with care.
+     * This will cause verbose logging, so enable with care.
      */
     public static bool enable_sql_logging = false;
 
 
-    /** The GLib logging domain used by this class. */
-    public const string LOGGING_DOMAIN = Logging.DOMAIN + ".Db";
+    /**
+     * Determines if SQL results will be logged.
+     *
+     * This will cause extremely verbose logging, so enable with extra care.
+     */
+    public static bool enable_result_logging = false;
+
 
     /** {@inheritDoc} */
     public string logging_domain {
diff --git a/src/engine/db/db-database-connection.vala b/src/engine/db/db-database-connection.vala
index 54d361604..29d52fd16 100644
--- a/src/engine/db/db-database-connection.vala
+++ b/src/engine/db/db-database-connection.vala
@@ -123,8 +123,10 @@ public class Geary.Db.DatabaseConnection : Context, Connection {
 
     /** {@inheritDoc} */
     public Statement prepare(string sql) throws DatabaseError {
-        var prepared = new Statement(this, sql);
-        return prepared;
+        if (Db.Context.enable_sql_logging) {
+            debug(sql);
+        }
+        return new Statement(this, sql);
     }
 
     /** {@inheritDoc} */
@@ -136,11 +138,10 @@ public class Geary.Db.DatabaseConnection : Context, Connection {
     /** {@inheritDoc} */
     public void exec(string sql, GLib.Cancellable? cancellable = null)
         throws GLib.Error {
+        check_cancelled("Connection.exec", cancellable);
         if (Db.Context.enable_sql_logging) {
-            debug("exec:\n\t%s", sql);
+            debug(sql);
         }
-
-        check_cancelled("Connection.exec", cancellable);
         var timer = new GLib.Timer();
         throw_on_error("Connection.exec_file", this.db.exec(sql), sql);
         check_elapsed("Query \"%s\"".printf(sql), timer);
@@ -150,6 +151,9 @@ public class Geary.Db.DatabaseConnection : Context, Connection {
     public void exec_file(GLib.File file, GLib.Cancellable? cancellable = null)
         throws GLib.Error {
         check_cancelled("Connection.exec_file", cancellable);
+        if (Db.Context.enable_sql_logging) {
+            debug(file.get_path());
+        }
 
         string sql;
         FileUtils.get_contents(file.get_path(), out sql);
diff --git a/src/engine/db/db-result.vala b/src/engine/db/db-result.vala
index 8c40c4759..14dc71a96 100644
--- a/src/engine/db/db-result.vala
+++ b/src/engine/db/db-result.vala
@@ -8,8 +8,12 @@ public class Geary.Db.Result : Geary.Db.Context {
     public bool finished { get; private set; default = false; }
 
 
+    /** The statement this result was generated from. */
     public Statement statement { get; private set; }
 
+    /** The current row represented by this result. */
+    public uint64 row { get; private set; default = 0; }
+
     /** {@inheritDoc} */
     public override Logging.Source? logging_parent {
         get { return this.statement; }
@@ -39,7 +43,8 @@ public class Geary.Db.Result : Geary.Db.Context {
     public bool next(Cancellable? cancellable = null) throws Error {
         check_cancelled("Result.next", cancellable);
 
-        if (!finished) {
+        if (!this.finished) {
+            this.row++;
             var timer = new GLib.Timer();
             this.finished = throw_on_error(
                 "Result.next", statement.stmt.step(), statement.sql
@@ -298,7 +303,12 @@ public class Geary.Db.Result : Geary.Db.Context {
 
     /** {@inheritDoc} */
     public override Logging.State to_logging_state() {
-        return new Logging.State(this, this.finished ? "finished" : "not finished");
+        return new Logging.State(
+            this,
+            "%llu, %s",
+            this.row,
+            this.finished ? "finished" : "!finished"
+        );
     }
 
     internal override Result? get_result() {
@@ -306,16 +316,9 @@ public class Geary.Db.Result : Geary.Db.Context {
     }
 
     [PrintfFormat]
-    private void log_result(string fmt, ...) {
-        if (Db.Context.enable_sql_logging) {
-            Statement? stmt = get_statement();
-            if (stmt != null) {
-                debug("%s\n\t<%s>",
-                      fmt.vprintf(va_list()),
-                      (stmt != null) ? "%.100s".printf(stmt.sql) : "no sql");
-            } else {
-                debug(fmt.vprintf(va_list()));
-            }
+    private inline void log_result(string fmt, ...) {
+        if (Db.Context.enable_result_logging) {
+            debug(fmt.vprintf(va_list()));
         }
     }