database: Log runtime of SQL queries

Signed-off-by: Michael Tremer <michael.tremer@ipfire.org>

diff --git a/src/buildservice/database.py b/src/buildservice/database.py
index ec4742009c6c94662fbf6fa053343938a1a1828e..27db380664e7dddfc570ad3cfec2908a1b4bf031 100644 (file)
--- a/src/buildservice/database.py
+++ b/src/buildservice/database.py
@@ -11,6 +11,7 @@
 import itertools
 import logging
 import psycopg2
+import time
 
 # Setup logging
 log = logging.getLogger("pbs.database")
@@ -166,15 +167,30 @@ class Connection(object):
                return self._db.cursor()
 
        def _execute(self, cursor, query, parameters, kwparameters):
-               #log.debug("Executing SQL: %s" % (query % (kwparameters or parameters)))
+               log.debug(
+                               "Executing query: %s" % \
+                                               cursor.mogrify(query, kwparameters or parameters).decode(),
+               )
+
+               # Store the time when the query started
+               t = time.monotonic()
 
                try:
                        return cursor.execute(query, kwparameters or parameters)
+
+               # Catch any errors
                except OperationalError:
                        log.error("Error connecting to database on %s", self.host)
                        self.close()
                        raise
 
+               # Log how long the query took
+               finally:
+                       # Determine duration the query took
+                       d = time.monotonic() - t
+
+                       log.debug("Query took %.2fms" % (d * 1000.0))
+
        def transaction(self):
                return Transaction(self)