python - How would I get psycopg2 logging of query execution time?

Question

I'm trying to get the performance statistics on queries executed by psycopg2, but the documentation / examples still seem fuzzy and not as clear as it could be.

I've at least got debugging working through the logger. What would I need to do to access the performance data for the query? I'm wanting to get the number for query execution time.

Is there a method I can access, or something else I need to initialize to output the query execution time?

Here's a pieced together extract of what I have so far:

import psycopg2
import psycopg2.extensions
from psycopg2.extras import LoggingConnection
import logging

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

# set higher up in script
db_settings = {
    "user": user,
    "password": password,
    "host": host,
    "database": dbname,
}

query_txt = "[query_txt_from file]"

conn = psycopg2.connect(connection_factory=LoggingConnection, **db_settings)
conn.initialize(logger)

cur = conn.cursor()
cur.execute(query_txt)

and I get

DEBUG:__main__: [the query executed]

Answer 1

Easy enough to set timestamp at start of execution and calculate duration at end. You'll need your own simple subclasses of LoggingConnection and LoggingCursor. See my example code.

This is based on source of MinTimeLoggingConnection you can find in psycopg2/extras.py source.

import time
import psycopg2
import psycopg2.extensions
from psycopg2.extras import LoggingConnection, LoggingCursor
import logging

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

# MyLoggingCursor simply sets self.timestamp at start of each query                                                                 
class MyLoggingCursor(LoggingCursor):
    def execute(self, query, vars=None):
        self.timestamp = time.time()
        return super(MyLoggingCursor, self).execute(query, vars)

    def callproc(self, procname, vars=None):
        self.timestamp = time.time()
        return super(MyLoggingCursor, self).callproc(procname, vars)

# MyLogging Connection:                                                                                                             
#   a) calls MyLoggingCursor rather than the default                                                                                
#   b) adds resulting execution (+ transport) time via filter()                                                                     
class MyLoggingConnection(LoggingConnection):
    def filter(self, msg, curs):
        return msg + "   %d ms" % int((time.time() - curs.timestamp) * 1000)

    def cursor(self, *args, **kwargs):
        kwargs.setdefault('cursor_factory', MyLoggingCursor)
        return LoggingConnection.cursor(self, *args, **kwargs)

db_settings = {
    ....
}

query_txt = "[query_text_from file]"

conn = psycopg2.connect(connection_factory=MyLoggingConnection, **db_settings)
conn.initialize(logger)

cur = conn.cursor()
cur.execute(query_text)

and you'll get:

DEBUG: __main__:[query]     3 ms

within your filter() you can change the formatting, or choose to not display, if less than some value.