From: bert hubert <bert.hubert@netherlabs.nl>
Date: Sat, 15 Sep 2018 14:25:39 +0000 (+0200)
Subject: Enhance query-logging with timing for MySQL, PostgreSQL and SQLite
X-Git-Tag: dnsdist-1.3.3~92^2
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=16c2f740821811e3d87e21c989aff3cc8fa1bb58;p=thirdparty%2Fpdns.git

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

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;