From 7e64a2e361adcdbd2fce5ad76051a150b4de062d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?louiz=E2=80=99?= Date: Sun, 14 Jan 2018 21:46:49 +0100 Subject: Add a DEBUG_SQL_QUERIES to log info about the executed SQL queries fix #3324 --- CMakeLists.txt | 3 +++ INSTALL.rst | 3 +++ src/biboumi.h.cmake | 2 ++ src/database/count_query.hpp | 3 +++ src/database/insert_query.hpp | 4 ++++ src/database/postgresql_engine.cpp | 6 ++++++ src/database/query.hpp | 29 +++++++++++++++++++++++++++++ src/database/select_query.hpp | 4 ++++ src/database/sqlite3_engine.cpp | 7 +++++++ src/database/update_query.hpp | 4 ++++ src/utils/scopetimer.hpp | 17 +++++++++++++++++ 11 files changed, 82 insertions(+) create mode 100644 src/utils/scopetimer.hpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 155b73a..d19a84e 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/INSTALL.rst b/INSTALL.rst index 0d99d4c..b0bf4be 100644 --- a/INSTALL.rst +++ b/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 diff --git a/src/biboumi.h.cmake b/src/biboumi.h.cmake index 5bc1004..fa99cd4 100644 --- a/src/biboumi.h.cmake +++ b/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 + diff --git a/src/database/count_query.hpp b/src/database/count_query.hpp index e8d24ef..118ce44 100644 --- a/src/database/count_query.hpp +++ b/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) diff --git a/src/database/insert_query.hpp b/src/database/insert_query.hpp index 17cc245..9726424 100644 --- a/src/database/insert_query.hpp +++ b/src/database/insert_query.hpp @@ -39,6 +39,10 @@ struct InsertQuery: public Query template void execute(DatabaseEngine& db, std::tuple& columns) { +#ifdef DEBUG_SQL_QUERIES + const auto timer = this->log_and_time(); +#endif + auto statement = db.prepare(this->body); this->bind_param(columns, *statement); diff --git a/src/database/postgresql_engine.cpp b/src/database/postgresql_engine.cpp index 150ca42..984a959 100644 --- a/src/database/postgresql_engine.cpp +++ b/src/database/postgresql_engine.cpp @@ -3,6 +3,8 @@ #include +#include + #include #include @@ -51,6 +53,10 @@ std::set PostgresqlEngine::get_all_columns_from_table(const std::st std::tuple 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); diff --git a/src/database/query.hpp b/src/database/query.hpp index 7f8aecb..547138f 100644 --- a/src/database/query.hpp +++ b/src/database/query.hpp @@ -1,5 +1,7 @@ #pragma once +#include + #include #include #include @@ -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 + +inline auto make_sql_timer() +{ + return make_scope_timer([](const std::chrono::steady_clock::duration& elapsed) + { + const auto seconds = std::chrono::duration_cast(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 @@ -58,3 +86,4 @@ operator<<(Query& query, const Integer& i) actual_add_param(query, i); return query; } + diff --git a/src/database/select_query.hpp b/src/database/select_query.hpp index af2ac1c..5a17f38 100644 --- a/src/database/select_query.hpp +++ b/src/database/select_query.hpp @@ -110,6 +110,10 @@ struct SelectQuery: public Query { std::vector> 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)); diff --git a/src/database/sqlite3_engine.cpp b/src/database/sqlite3_engine.cpp index 92d514b..ae4a146 100644 --- a/src/database/sqlite3_engine.cpp +++ b/src/database/sqlite3_engine.cpp @@ -6,6 +6,8 @@ #include +#include + #include #include #include @@ -57,6 +59,11 @@ std::unique_ptr Sqlite3Engine::open(const std::string& filename) std::tuple 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) diff --git a/src/database/update_query.hpp b/src/database/update_query.hpp index 32befc0..a29ac3f 100644 --- a/src/database/update_query.hpp +++ b/src/database/update_query.hpp @@ -64,6 +64,10 @@ struct UpdateQuery: public Query template void execute(DatabaseEngine& db, const std::tuple& 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); diff --git a/src/utils/scopetimer.hpp b/src/utils/scopetimer.hpp new file mode 100644 index 0000000..7d3db9b --- /dev/null +++ b/src/utils/scopetimer.hpp @@ -0,0 +1,17 @@ +#include + +#include + +#include + +template +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); + }); +} -- cgit v1.2.3