Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

How would I get psycopg2 logging of query execution time?

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]
like image 455
jmhead Avatar asked Sep 18 '15 21:09

jmhead


People also ask

What is execution time in PostgreSQL?

In PostgreSQL, execution time for this query is 3.4 seconds, so optimization is required.

Is Psycopg2 asynchronous?

Asynchronous notificationsPsycopg allows asynchronous interaction with other database sessions using the facilities offered by PostgreSQL commands LISTEN and NOTIFY.

What is cursor in Psycopg2?

The Cursor class of the psycopg library provide methods to execute the PostgreSQL commands in the database using python code. Using the methods of it you can execute SQL statements, fetch data from the result sets, call procedures. You can create Cursor object using the cursor() method of the Connection object/class.

Is Psycopg2 connection thread-safe?

Thread and process safetyThe Psycopg module and the connection objects are thread-safe: many threads can access the same database either using separate sessions and creating a connection per thread or using the same connection and creating separate cursors.


1 Answers

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.

like image 192
pbuck Avatar answered Sep 19 '22 18:09

pbuck