From 16c2f740821811e3d87e21c989aff3cc8fa1bb58 Mon Sep 17 00:00:00 2001
From: bert hubert <bert.hubert@netherlabs.nl>
Date: Sat, 15 Sep 2018 16:25:39 +0200
Subject: [PATCH] Enhance query-logging with timing for MySQL, PostgreSQL and
 SQLite

---
 modules/gmysqlbackend/smysql.cc | 10 +++++++++-
 modules/gpgsqlbackend/spgsql.cc | 13 ++++++++++++-
 pdns/ssqlite3.cc                | 17 +++++++++++++----
 3 files changed, 34 insertions(+), 6 deletions(-)

diff --git a/modules/gmysqlbackend/smysql.cc b/modules/gmysqlbackend/smysql.cc
index 67ccac095b..1d851daa91 100644
--- 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 cfd2361592..e2052d83f2 100644
--- 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 4e29436bbf..62b223ceb2 100644
--- 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;
 
-- 
2.47.2