Add a DEBUG_SQL_QUERIES to log info about the executed SQL queries

fix #3324

CMakeLists.txt

@@ -193,6 +193,9 @@ file(GLOB source_network
         src/network/*.[hc]pp)
 add_library(network OBJECT ${source_network})
 
+option(DEBUG_SQL_QUERIES
+       "If set to true, every SQL statement executed will be logged and timed"
+       OFF)
 if(SQLITE3_FOUND OR PQ_FOUND)
   file(GLOB source_database
           src/database/*.[hc]pp)

INSTALL.rst

@@ -96,6 +96,9 @@ The list of available options:
   - POLL: use the standard poll(2). This is the default value on all non-Linux
     platforms.
 
+- DEBUG_SQL_QUERIES: If set to ON, additional debug logging and timing will be
+  done for every SQL query that is executed. The default is OFF.
+
 - WITH_BOTAN and WITHOUT_BOTAN: The first force the usage of the Botan library,
   if it is not found, the configuration process will fail. The second will
   make the build process ignore the Botan library, it will not be used even

src/biboumi.h.cmake

@@ -12,3 +12,5 @@
 #cmakedefine PROJECT_NAME "${PROJECT_NAME}"
 #cmakedefine HAS_GET_TIME
 #cmakedefine HAS_PUT_TIME
+#cmakedefine DEBUG_SQL_QUERIES
+

src/database/count_query.hpp

@@ -16,6 +16,9 @@ struct CountQuery: public Query
 
     int64_t execute(DatabaseEngine& db)
     {
+#ifdef DEBUG_SQL_QUERIES
+      const auto timer = this->log_and_time();
+#endif
       auto statement = db.prepare(this->body);
       int64_t res = 0;
       if (statement->step() != StepResult::Error)

src/database/insert_query.hpp

@@ -39,6 +39,10 @@ struct InsertQuery: public Query
   template <typename... T>
   void execute(DatabaseEngine& db, std::tuple<T...>& columns)
   {
+#ifdef DEBUG_SQL_QUERIES
+    const auto timer = this->log_and_time();
+#endif
+
     auto statement = db.prepare(this->body);
     this->bind_param(columns, *statement);
 

src/database/postgresql_engine.cpp

@@ -3,6 +3,8 @@
 
 #include <utils/scopeguard.hpp>
 
+#include <database/query.hpp>
+
 #include <database/postgresql_engine.hpp>
 
 #include <database/postgresql_statement.hpp>
@@ -51,6 +53,10 @@ std::set<std::string> PostgresqlEngine::get_all_columns_from_table(const std::st
 
 std::tuple<bool, std::string> PostgresqlEngine::raw_exec(const std::string& query)
 {
+#ifdef DEBUG_SQL_QUERIES
+  log_debug("SQL QUERY: ", query);
+  const auto timer = make_sql_timer();
+#endif
   PGresult* res = PQexec(this->conn, query.data());
   auto sg = utils::make_scope_guard([res](){
       PQclear(res);

src/database/query.hpp

@@ -1,5 +1,7 @@
 #pragma once
 
+#include <biboumi.h>
+
 #include <utils/optional_bool.hpp>
 #include <database/statement.hpp>
 #include <database/column.hpp>
@@ -13,6 +15,20 @@ void actual_bind(Statement& statement, const std::string& value, int index);
 void actual_bind(Statement& statement, const std::size_t value, int index);
 void actual_bind(Statement& statement, const OptionalBool& value, int index);
 
+#ifdef DEBUG_SQL_QUERIES
+#include <utils/scopetimer.hpp>
+
+inline auto make_sql_timer()
+{
+  return make_scope_timer([](const std::chrono::steady_clock::duration& elapsed)
+                          {
+                            const auto seconds = std::chrono::duration_cast<std::chrono::seconds>(elapsed);
+                            const auto rest = elapsed - seconds;
+                            log_debug("Query executed in ", seconds.count(), ".", rest.count(), "s.");
+                          });
+}
+#endif
+
 struct Query
 {
     std::string body;
@@ -22,6 +38,18 @@ struct Query
     Query(std::string str):
         body(std::move(str))
     {}
+
+#ifdef DEBUG_SQL_QUERIES
+    auto log_and_time()
+    {
+       std::ostringstream os;
+       os << this->body << "; ";
+       for (const auto& param: this->params)
+         os << "'" << param << "' ";
+       log_debug("SQL QUERY: ", os.str());
+       return make_sql_timer();
+    }
+#endif
 };
 
 template <typename ColumnType>
@@ -58,3 +86,4 @@ operator<<(Query& query, const Integer& i)
   actual_add_param(query, i);
   return query;
 }
+

src/database/select_query.hpp

@@ -110,6 +110,10 @@ struct SelectQuery: public Query
     {
       std::vector<Row<T...>> rows;
 
+#ifdef DEBUG_SQL_QUERIES
+      const auto timer = this->log_and_time();
+#endif
+
       auto statement = db.prepare(this->body);
       statement->bind(std::move(this->params));
 

src/database/sqlite3_engine.cpp

@@ -6,6 +6,8 @@
 
 #include <database/sqlite3_statement.hpp>
 
+#include <database/query.hpp>
+
 #include <utils/tolower.hpp>
 #include <logger/logger.hpp>
 #include <vector>
@@ -57,6 +59,11 @@ std::unique_ptr<DatabaseEngine> Sqlite3Engine::open(const std::string& filename)
 
 std::tuple<bool, std::string> Sqlite3Engine::raw_exec(const std::string& query)
 {
+#ifdef DEBUG_SQL_QUERIES
+  log_debug("SQL QUERY: ", query);
+  const auto timer = make_sql_timer();
+#endif
+
   char* error;
   const auto result = sqlite3_exec(db, query.data(), nullptr, nullptr, &error);
   if (result != SQLITE_OK)

src/database/update_query.hpp

@@ -64,6 +64,10 @@ struct UpdateQuery: public Query
   template <typename... T>
   void execute(DatabaseEngine& db, const std::tuple<T...>& columns)
   {
+#ifdef DEBUG_SQL_QUERIES
+      const auto timer = this->log_and_time();
+#endif
+
     auto statement = db.prepare(this->body);
     this->bind_param(columns, *statement);
     this->bind_id(columns, *statement);

src/utils/scopetimer.hpp

@@ -0,0 +1,17 @@
+#include <utils/scopeguard.hpp>
+
+#include <chrono>
+
+#include <logger/logger.hpp>
+
+template <typename Callback>
+auto make_scope_timer(Callback cb)
+{
+  const auto start_time = std::chrono::steady_clock::now();
+  return utils::make_scope_guard([start_time, cb = std::move(cb)]()
+                                 {
+                                   const auto now = std::chrono::steady_clock::now();
+                                   const auto elapsed = now - start_time;
+                                   cb(elapsed);
+                                 });
+}