Enhance query-logging with timing for MySQL, PostgreSQL and SQLite

diff --git a/modules/gmysqlbackend/smysql.cc b/modules/gmysqlbackend/smysql.cc
index 67ccac095b67ba69dff8fa5b5d90fba6329e5f47..1d851daa91e3094a8fc637a35f6ee1220963a2f0 100644 (file)
--- a/modules/gmysqlbackend/smysql.cc
+++ b/modules/gmysqlbackend/smysql.cc
@@ -162,7 +162,8 @@ public:
     if (!d_stmt) return this;
 
     if (d_dolog) {
-      g_log<<Logger::Warning<<"Query: " << d_query <<endl;
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": " << d_query << endl;
+      d_dtime.set();
     }
 
     if ((err = mysql_stmt_bind_param(d_stmt, d_req_bind))) {
@@ -221,10 +222,16 @@ public:
       }
     }
 
+    if(d_dolog) 
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<<d_dtime.udiffNoReset()<<" usec to execute"<<endl;
+
     return this;
   }
 
   bool hasNextRow() {
+    if(d_dolog && d_residx == d_resnum) {
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<<d_dtime.udiffNoReset()<<" total usec to last row"<<endl;
+    }
     return d_residx < d_resnum;
   }
 
@@ -399,6 +406,7 @@ private:
   
   bool d_prepared;
   bool d_dolog;
+  DTime d_dtime; // only used if d_dolog is set
   int d_parnum;
   int d_paridx;
   int d_fnum;

diff --git a/modules/gpgsqlbackend/spgsql.cc b/modules/gpgsqlbackend/spgsql.cc
index cfd23615925992741d1944dabe9249f4239a916a..e2052d83f244ee75653b4122b1533499f3d921be 100644 (file)
--- a/modules/gpgsqlbackend/spgsql.cc
+++ b/modules/gpgsqlbackend/spgsql.cc
@@ -78,7 +78,8 @@ public:
   SSqlStatement* execute() {
     prepareStatement();
     if (d_dolog) {
-      g_log<<Logger::Warning<<"Query: "<<d_query<<endl;
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": " << d_query << endl;
+      d_dtime.set();
     }
     d_res_set = PQexecPrepared(d_db(), d_stmt.c_str(), d_nparams, paramValues, paramLengths, NULL, 0);
     ExecStatusType status = PQresultStatus(d_res_set);
@@ -88,6 +89,11 @@ public:
       throw SSqlException("Fatal error during query: " + d_query + string(": ") + errmsg);
     }
     d_cur_set = 0;
+    if(d_dolog) {
+      auto diff = d_dtime.udiffNoReset();
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<< diff <<" usec to execute"<<endl;
+    }
+
     nextResult();
     return this;
   }
@@ -130,6 +136,10 @@ public:
 
   bool hasNextRow()
   {
+    if(d_dolog && d_residx == d_resnum) {
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<<d_dtime.udiff()<<" total usec to last row"<<endl;
+    }
+
     return d_residx<d_resnum;
   }
 
@@ -240,6 +250,7 @@ private:
   PGresult *d_res_set;
   PGresult *d_res;
   bool d_dolog;
+  DTime d_dtime; // only used if d_dolog is set
   bool d_prepared;
   int d_nparams;
   int d_paridx;

diff --git a/pdns/ssqlite3.cc b/pdns/ssqlite3.cc
index 4e29436bbf2611a1ba79025bdfd57d0e38bea070..62b223ceb2d2b76c1cd5cfe628460461b8205e04 100644 (file)
--- a/pdns/ssqlite3.cc
+++ b/pdns/ssqlite3.cc
@@ -77,8 +77,10 @@ public:
 
   SSqlStatement* execute() {
     prepareStatement();
-    if (d_dolog)
-      g_log<<Logger::Warning<< "Query: " << d_query << endl;
+    if (d_dolog) {
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": " << d_query << endl;
+      d_dtime.set();
+    }
     int attempts = d_db->inTransaction(); // try only once
     while(attempts < 2 && (d_rc = sqlite3_step(d_stmt)) == SQLITE_BUSY) attempts++;
 
@@ -89,9 +91,16 @@ public:
         throw SSqlException(string("CANTOPEN error in sqlite3, often caused by unwritable sqlite3 db *directory*: ")+string(sqlite3_errmsg(d_db->db())));
       throw SSqlException(string("Error while retrieving SQLite query results: ")+string(sqlite3_errmsg(d_db->db())));
     }
+    if(d_dolog) 
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<<d_dtime.udiffNoReset()<<" usec to execute"<<endl;
     return this;
   }
-  bool hasNextRow() { return d_rc == SQLITE_ROW; }
+  bool hasNextRow() {
+    if(d_dolog && d_rc != SQLITE_ROW) {
+      g_log<<Logger::Warning<< "Query "<<((long)(void*)this)<<": "<<d_dtime.udiffNoReset()<<" total usec to last row"<<endl;
+    }
+    return d_rc == SQLITE_ROW;
+  }
 
   SSqlStatement* nextRow(row_t& row) {
     row.clear();
@@ -144,7 +153,7 @@ private:
   int d_rc;
   bool d_dolog;
   bool d_prepared;
-
+  DTime d_dtime;
   void prepareStatement() {
     const char *pTail;