Integrate database statement tracing into our diagnostics machinery

11 files changed, 77 insertions, 30 deletions

diff --git a/bpkg/cfg-create.cxx b/bpkg/cfg-create.cxx
index 2f8fad9..d780657 100644
--- a/bpkg/cfg-create.cxx
+++ b/bpkg/cfg-create.cxx
@@ -116,7 +116,7 @@ namespace bpkg
 
     // Create the database.
     //
-    open (c, true);
+    open (c, trace, true);
 
     if (verb)
     {
diff --git a/bpkg/database b/bpkg/database
index 820555d..c4ace56 100644
--- a/bpkg/database
+++ b/bpkg/database
@@ -8,6 +8,7 @@
 #include <odb/sqlite/database.hxx>
 
 #include <bpkg/types>
+#include <bpkg/diagnostics>
 
 namespace bpkg
 {
@@ -15,7 +16,7 @@ namespace bpkg
   using odb::sqlite::transaction;
 
   database
-  open (const dir_path& configuration, bool create = false);
+  open (const dir_path& configuration, tracer&, bool create = false);
 }
 
 #endif // BPKG_DATABASE
diff --git a/bpkg/database.cxx b/bpkg/database.cxx
index 1bfe9b9..8553a15 100644
--- a/bpkg/database.cxx
+++ b/bpkg/database.cxx
@@ -22,8 +22,10 @@ namespace bpkg
   using odb::schema_catalog;
 
   database
-  open (const dir_path& d, bool create)
+  open (const dir_path& d, tracer& tr, bool create)
   {
+    tracer trace ("open");
+
     path f (d / path ("bpkg.sqlite3"));
 
     if (!create && !exists (f))
@@ -41,6 +43,8 @@ namespace bpkg
                    "",                    // Default VFS.
                    move (cf));
 
+      db.tracer (trace);
+
       // Lock the database for as long as the connection is active. First
       // we set locking_mode to EXCLUSIVE which instructs SQLite not to
       // release any locks until the connection is closed. Then we force
@@ -53,33 +57,31 @@ namespace bpkg
       {
         db.connection ()->execute ("PRAGMA locking_mode = EXCLUSIVE");
         transaction t (db.begin_exclusive ());
-        t.commit ();
-      }
-      catch (odb::timeout&)
-      {
-        fail << "configuration " << d << " is already used by another process";
-      }
 
-      if (create)
-      {
-        // Create the new schema.
-        //
-        if (db.schema_version () != 0)
-          fail << f << ": already has database schema";
+        if (create)
+        {
+          // Create the new schema.
+          //
+          if (db.schema_version () != 0)
+            fail << f << ": already has database schema";
+
+          schema_catalog::create_schema (db);
+        }
+        else
+        {
+          // Migrate the database if necessary.
+          //
+          schema_catalog::migrate (db);
+        }
 
-        transaction t (db.begin ());
-        schema_catalog::create_schema (db);
         t.commit ();
       }
-      else
+      catch (odb::timeout&)
       {
-        // Migrate the database if necessary.
-        //
-        transaction t (db.begin ());
-        schema_catalog::migrate (db);
-        t.commit ();
+        fail << "configuration " << d << " is already used by another process";
       }
 
+      db.tracer (tr); // Switch to the caller's tracer.
       return db;
     }
     catch (const database_exception& e)
diff --git a/bpkg/diagnostics b/bpkg/diagnostics
index f403d9f..e48d4f2 100644
--- a/bpkg/diagnostics
+++ b/bpkg/diagnostics
@@ -13,6 +13,8 @@
 #include <ostream>
 #include <exception>
 
+#include <odb/tracer.hxx>
+
 #include <bpkg/types>
 
 namespace bpkg
@@ -320,11 +322,25 @@ namespace bpkg
 
   // trace
   //
-  struct trace_mark_base: basic_mark_base
+  // Also implement the ODB tracer interface so that we can use
+  // it to trace database statement execution.
+  //
+  struct trace_mark_base: basic_mark_base, odb::tracer
   {
     explicit
     trace_mark_base (const char* name, const void* data = nullptr)
         : basic_mark_base ("trace", name, data) {}
+
+    // odb::tracer interface.
+    //
+    virtual void
+    prepare (odb::connection&, const odb::statement&);
+
+    virtual void
+    execute (odb::connection&, const char* statement);
+
+    virtual void
+    deallocate (odb::connection&, const odb::statement&);
   };
   typedef diag_mark<trace_mark_base> trace_mark;
 
diff --git a/bpkg/diagnostics.cxx b/bpkg/diagnostics.cxx
index 697bd28..221bded 100644
--- a/bpkg/diagnostics.cxx
+++ b/bpkg/diagnostics.cxx
@@ -6,6 +6,8 @@
 
 #include <iostream>
 
+#include <odb/statement.hxx>
+
 #include <bpkg/utility>
 
 using namespace std;
@@ -98,6 +100,29 @@ namespace bpkg
       r << name_ << ": ";
   }
 
+  // trace
+  //
+  void trace_mark_base::
+  prepare (odb::connection&, const odb::statement& s)
+  {
+    if (verb >= 6)
+      static_cast<trace_mark&> (*this) << "PREPARE " << s.text ();
+  }
+
+  void trace_mark_base::
+  execute (odb::connection&, const char* stmt)
+  {
+    if (verb >= 5)
+      static_cast<trace_mark&> (*this) << stmt;
+  }
+
+  void trace_mark_base::
+  deallocate (odb::connection&, const odb::statement& s)
+  {
+    if (verb >= 6)
+      static_cast<trace_mark&> (*this) << "DEALLOCATE " << s.text ();
+  }
+
   const basic_mark error ("error");
   const basic_mark warn ("warning");
   const basic_mark info ("info");
diff --git a/bpkg/pkg-configure.cxx b/bpkg/pkg-configure.cxx
index 604b126..c0dc05e 100644
--- a/bpkg/pkg-configure.cxx
+++ b/bpkg/pkg-configure.cxx
@@ -47,7 +47,7 @@ namespace bpkg
       fail << "package name argument expected" <<
         info << "run 'bpkg help pkg-configure' for more information";
 
-    database db (open (c));
+    database db (open (c, trace));
     transaction t (db.begin ());
 
     shared_ptr<package> p (db.find<package> (n));
diff --git a/bpkg/pkg-disfigure.cxx b/bpkg/pkg-disfigure.cxx
index 092555d..d9ed811 100644
--- a/bpkg/pkg-disfigure.cxx
+++ b/bpkg/pkg-disfigure.cxx
@@ -22,6 +22,7 @@ namespace bpkg
                  const shared_ptr<package>& p)
   {
     tracer trace ("pkg_disfigure");
+    t.tracer (trace); // "Tail" call, never restored.
 
     database& db (t.database ());
 
@@ -102,7 +103,7 @@ namespace bpkg
 
     string n (args.next ());
 
-    database db (open (c));
+    database db (open (c, trace));
     transaction t (db.begin ());
 
     shared_ptr<package> p (db.find<package> (n));
diff --git a/bpkg/pkg-fetch.cxx b/bpkg/pkg-fetch.cxx
index c7982e8..1e7072c 100644
--- a/bpkg/pkg-fetch.cxx
+++ b/bpkg/pkg-fetch.cxx
@@ -30,7 +30,7 @@ namespace bpkg
     dir_path c (o.directory ());
     level4 ([&]{trace << "configuration: " << c;});
 
-    database db (open (c));
+    database db (open (c, trace));
 
     path a;
     bool purge;
diff --git a/bpkg/pkg-purge.cxx b/bpkg/pkg-purge.cxx
index 260b287..57e098d 100644
--- a/bpkg/pkg-purge.cxx
+++ b/bpkg/pkg-purge.cxx
@@ -32,7 +32,7 @@ namespace bpkg
 
     string n (args.next ());
 
-    database db (open (c));
+    database db (open (c, trace));
     transaction t (db.begin ());
 
     shared_ptr<package> p (db.find<package> (n));
diff --git a/bpkg/pkg-status.cxx b/bpkg/pkg-status.cxx
index 27e9780..a5eab3e 100644
--- a/bpkg/pkg-status.cxx
+++ b/bpkg/pkg-status.cxx
@@ -46,7 +46,7 @@ namespace bpkg
       }
     }
 
-    database db (open (c));
+    database db (open (c, trace));
     transaction t (db.begin ());
 
     using query = odb::query<package>;
diff --git a/bpkg/pkg-unpack.cxx b/bpkg/pkg-unpack.cxx
index 7116649..f78543e 100644
--- a/bpkg/pkg-unpack.cxx
+++ b/bpkg/pkg-unpack.cxx
@@ -28,6 +28,7 @@ namespace bpkg
   pkg_unpack (database& db, const dir_path& c, const dir_path& d, bool purge)
   {
     tracer trace ("pkg_unpack(dir)");
+    db.tracer (trace); // "Tail" call, never restored.
 
     if (!exists (d))
       fail << "package directory " << d << " does not exist";
@@ -81,6 +82,7 @@ namespace bpkg
   pkg_unpack (database& db, const dir_path& c, const string& name)
   {
     tracer trace ("pkg_unpack(pkg)");
+    db.tracer (trace); // "Tail" call, never restored.
 
     transaction t (db.begin ());
     shared_ptr<package> p (db.find<package> (name));
@@ -176,7 +178,7 @@ namespace bpkg
     const dir_path& c (o.directory ());
     level4 ([&]{trace << "configuration: " << c;});
 
-    database db (open (c));
+    database db (open (c, trace));
 
     shared_ptr<package> p;