gistfile1.sh

vinay@zeta-lucid:~/projects/scratch$ python satest.py
Engine id/echo settings:
ID: 0x8698d0c echo: False
ID: 0x869c0cc echo: True
ID: 0x869c42c echo: debug
sqlalchemy.engine.base.Engine INFO     0x869c0cc INSERT INTO items2 DEFAULT VALUES
sqlalchemy.engine.base.Engine INFO     0x869c0cc ()
sqlalchemy.engine.base.Engine INFO     0x869c0cc COMMIT
sqlalchemy.engine.base.Engine INFO     0x869c42c INSERT INTO items3 DEFAULT VALUES
sqlalchemy.engine.base.Engine INFO     0x869c42c ()
sqlalchemy.engine.base.Engine INFO     0x869c42c COMMIT

gistfile2.sh

vinay@zeta-lucid:~/projects/scratch$ python satime.py > satime.log
unwrapped: no echo: using <logging.Logger instance at 0xb73e5cec>:
run_queries_nologging 18.14
wrapped: no echo: using <satest.EngineLogger instance at 0xb73f570c>:
run_queries_nologging 17.54
unwrapped: with echo: using <logging.Logger instance at 0xb73ea0ac>:
run_queries_logging  33.90
wrapped: with echo: using <satest.EngineLogger instance at 0xb73fa10c>:
run_queries_logging  36.24

gistfile4.sh

vinay@zeta-lucid:~/projects/scratch$ python satest2.py
Engine id/echo settings:
ID: 0x8569cec echo: False
ID: 0x856e0ac echo: False
ID: 0x856e40c echo: False
INFO:sqlalchemy.engine.base.Engine:INSERT INTO items1 DEFAULT VALUES
INFO:sqlalchemy.engine.base.Engine:()
INFO:sqlalchemy.engine.base.Engine:COMMIT
INFO:sqlalchemy.engine.base.Engine:INSERT INTO items2 DEFAULT VALUES
INFO:sqlalchemy.engine.base.Engine:()
INFO:sqlalchemy.engine.base.Engine:COMMIT
INFO:sqlalchemy.engine.base.Engine:INSERT INTO items3 DEFAULT VALUES
INFO:sqlalchemy.engine.base.Engine:()
INFO:sqlalchemy.engine.base.Engine:COMMIT

satest.py

#
# A proof-of-concept showing how multiple SQLA engines can share a single
# logger, yet use engine echo setting and inject engine-specific data
# into log output
#
import logging
from sqlalchemy import create_engine, MetaData, Column, Integer, Table

#
# Declare three engines, each of which will have a different echo setting.
#
engine1 = create_engine('sqlite:///')
engine2 = create_engine('sqlite:///')
engine3 = create_engine('sqlite:///')

#
# For each engine, create a table so that we can do some operations against
# them
#
meta1 = MetaData(bind=engine1)
items1 = Table('items1', meta1,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta1.create_all()

meta2 = MetaData(bind=engine2)
items2 = Table('items2', meta2,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta2.create_all()

meta3 = MetaData(bind=engine3)
items3 = Table('items3', meta3,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta3.create_all()

#
# This table is used to map echo settings to logging levels.
#
LEVEL_MAP = {
    False: logging.NOTSET,
    True: logging.INFO,
    'debug': logging.DEBUG,
}

#
# This is a version of the LoggerAdapter which was introduced
# in 2.6. The version in 2.6 works slightly differently, so it
# can't be inherited from here: However, I've changed the 2.7.1
# and 3.2 implementations of LoggerAdapter so they will be
# suitable for use as base classes of EngineLogger in the future.
#
class EngineLogger:
    """
    A logger adapter (wrapper) for engines.
    """

    def __init__(self, engine):
        self.engine = engine
        self.logger = logging.getLogger('sqlalchemy.engine.base.Engine')

    def process(self, msg, kwargs):
        """
        Used to put context-specific information into the logs.
        
        The engine id is used here just as an example.
        """
        kwargs["extra"] = { 'engine': hex(id(self.engine)) }
        return msg, kwargs

    #
    # Boilerplate convenience methods
    #
    def debug(self, msg, *args, **kwargs):
        """
        Delegate a debug call to the underlying logger.
        """
        self.log(logging.DEBUG, msg, *args, **kwargs)

    def info(self, msg, *args, **kwargs):
        """
        Delegate an info call to the underlying logger.
        """
        self.log(logging.INFO, msg, *args, **kwargs)

    def warning(self, msg, *args, **kwargs):
        """
        Delegate a warning call to the underlying logger.
        """
        self.log(logging.WARNING, msg, *args, **kwargs)

    def error(self, msg, *args, **kwargs):
        """
        Delegate an error call to the underlying logger.
        """
        self.log(logging.ERROR, msg, *args, **kwargs)

    def exception(self, msg, *args, **kwargs):
        """
        Delegate an exception call to the underlying logger.
        """
        kwargs["exc_info"] = 1
        self.log(logging.ERROR, msg, *args, **kwargs)

    def critical(self, msg, *args, **kwargs):
        """
        Delegate a critical call to the underlying logger.
        """
        self.log(logging.CRITICAL, msg, *args, **kwargs)

    def log(self, level, msg, *args, **kwargs):
        """
        Delegate a log call to the underlying logger, after adding
        contextual information from this adapter instance.
        """
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger._log(level, msg, args, **kwargs)

    def isEnabledFor(self, level):
        """
        Is this logger enabled for level 'level'?
        """
        if self.logger.manager.disable >= level:
            return False
        return level >= self.getEffectiveLevel()

    def getEffectiveLevel(self):
        """
        What's the effective level for this logger?
        """
        level = LEVEL_MAP[self.engine.echo]
        if level == logging.NOTSET:
            level = self.logger.getEffectiveLevel()
        return level

def main():
    # leave engine1.echo to the default, False
    engine2.echo = True
    engine3.echo = 'debug'
    print('Engine id/echo settings:')
    for engine in (engine1, engine2, engine3):
        # Just for the purposes of this test script, we discard
        # the engine's logger (which has the hex suffix) and replace
        # it with a wrapper wrapping a common one for all engines.
        # If SQLA is patched to use this approach,
        # those hex-id loggers won't be created in the first
        # place.
        engine.logger = EngineLogger(engine)
        print('ID: %s echo: %s' % (hex(id(engine)), engine.echo))

    #
    # Just to show how you can insert engine-specific info into
    # the logs, we'll hack the formatter set up by SQLA to replace
    # the format string with one that has engine-specific info.
    #
    engine1.logger.logger.parent.handlers[0].formatter._fmt = '%(name)s %(levelname)-8s %(engine)-8s %(message)s'
    #
    # Let's do some operations against the different engines. Only
    # messages for operations against engine2 and engine3 should
    # show up.
    items1.insert(value=4000).execute()
    items2.insert(value=4000).execute()
    items3.insert(value=4000).execute()
    # But they all use the same underlying logger...
    # engineN.logger is the wrapper, and engineN.logger.logger
    # is the actual (wrapped) logger from stdlib logging
    assert engine1.logger.logger is engine2.logger.logger
    assert engine1.logger.logger is engine3.logger.logger

if __name__ == '__main__':
    main()

satest2.py

#
# A proof-of-concept showing how multiple SQLA engines can share a single
# logger, yet use engine echo setting and inject engine-specific data
# into log output
#
import logging
from sqlalchemy import create_engine, MetaData, Column, Integer, Table

#
# Declare three engines, each of which will have a different echo setting.
#
engine1 = create_engine('sqlite:///')
engine2 = create_engine('sqlite:///')
engine3 = create_engine('sqlite:///')

#
# For each engine, create a table so that we can do some operations against
# them
#
meta1 = MetaData(bind=engine1)
items1 = Table('items1', meta1,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta1.create_all()

meta2 = MetaData(bind=engine2)
items2 = Table('items2', meta2,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta2.create_all()

meta3 = MetaData(bind=engine3)
items3 = Table('items3', meta3,
    Column('item_id', Integer, primary_key=True),
    Column('value', Integer)
)
meta3.create_all()

#
# This table is used to map echo settings to logging levels.
#
LEVEL_MAP = {
    False: logging.NOTSET,
    True: logging.INFO,
    'debug': logging.DEBUG,
}

#
# This is a version of the LoggerAdapter which was introduced
# in 2.6. The version in 2.6 works slightly differently, so it
# can't be inherited from here: However, I've changed the 2.7.1
# and 3.2 implementations of LoggerAdapter so they will be
# suitable for use as base classes of EngineLogger in the future.
#
class EngineLogger:
    """
    A logger adapter (wrapper) for engines.
    """

    def __init__(self, engine):
        self.engine = engine
        self.logger = logging.getLogger('sqlalchemy.engine.base.Engine')

    def process(self, msg, kwargs):
        """
        Used to put context-specific information into the logs.
        
        The engine id is used here just as an example.
        """
        kwargs["extra"] = { 'engine': hex(id(self.engine)) }
        return msg, kwargs

    #
    # Boilerplate convenience methods
    #
    def debug(self, msg, *args, **kwargs):
        """
        Delegate a debug call to the underlying logger.
        """
        self.log(logging.DEBUG, msg, *args, **kwargs)

    def info(self, msg, *args, **kwargs):
        """
        Delegate an info call to the underlying logger.
        """
        self.log(logging.INFO, msg, *args, **kwargs)

    def warning(self, msg, *args, **kwargs):
        """
        Delegate a warning call to the underlying logger.
        """
        self.log(logging.WARNING, msg, *args, **kwargs)

    def error(self, msg, *args, **kwargs):
        """
        Delegate an error call to the underlying logger.
        """
        self.log(logging.ERROR, msg, *args, **kwargs)

    def exception(self, msg, *args, **kwargs):
        """
        Delegate an exception call to the underlying logger.
        """
        kwargs["exc_info"] = 1
        self.log(logging.ERROR, msg, *args, **kwargs)

    def critical(self, msg, *args, **kwargs):
        """
        Delegate a critical call to the underlying logger.
        """
        self.log(logging.CRITICAL, msg, *args, **kwargs)

    def log(self, level, msg, *args, **kwargs):
        """
        Delegate a log call to the underlying logger, after adding
        contextual information from this adapter instance.
        """
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger._log(level, msg, args, **kwargs)

    def isEnabledFor(self, level):
        """
        Is this logger enabled for level 'level'?
        """
        if self.logger.manager.disable >= level:
            return False
        return level >= self.getEffectiveLevel()

    def getEffectiveLevel(self):
        """
        What's the effective level for this logger?
        """
        level = LEVEL_MAP[self.engine.echo]
        if level == logging.NOTSET:
            level = self.logger.getEffectiveLevel()
        return level

def main():
    # leave engine1.echo to the default, False
    #engine2.echo = True
    #engine3.echo = 'debug'
    print('Engine id/echo settings:')
    for engine in (engine1, engine2, engine3):
        # Just for the purposes of this test script, we discard
        # the engine's logger (which has the hex suffix) and replace
        # it with a wrapper wrapping a common one for all engines.
        # If SQLA is patched to use this approach,
        # those hex-id loggers won't be created in the first
        # place.
        engine.logger = EngineLogger(engine)
        print('ID: %s echo: %s' % (hex(id(engine)), engine.echo))

    #
    # Just to show how you can insert engine-specific info into
    # the logs, we'll hack the formatter set up by SQLA to replace
    # the format string with one that has engine-specific info.
    #
    #engine1.logger.logger.parent.handlers[0].formatter._fmt = '%(name)s %(levelname)-8s %(engine)-8s %(message)s'
    #
    # Let's do some operations against the different engines. Only
    # messages for operations against engine2 and engine3 should
    # show up.
    logging.getLogger('sqlalchemy.engine').setLevel(logging.DEBUG)
    logging.basicConfig()
    items1.insert(value=4000).execute()
    items2.insert(value=4000).execute()
    items3.insert(value=4000).execute()
    # But they all use the same underlying logger...
    # engineN.logger is the wrapper, and engineN.logger.logger
    # is the actual (wrapped) logger from stdlib logging
    assert engine1.logger.logger is engine2.logger.logger
    assert engine1.logger.logger is engine3.logger.logger

if __name__ == '__main__':
    main()

satime.py

import logging
import satest
import sys
import timeit

def do_timing(func):

    t = timeit.Timer(func)

    elapsed = t.timeit(number=50000)

    print >> sys.stderr, "%-20s %5.2f" % (func.__name__, elapsed)


def run_queries_nologging():
    list(satest.items1.select().execute())


def run_queries_logging():
    list(satest.items2.select().execute())


def main():
    print >> sys.stderr, 'unwrapped: no echo: using %s:' % satest.engine1.logger
    do_timing(run_queries_nologging)
    satest.engine1.logger = satest.EngineLogger(satest.engine1)
    print >> sys.stderr, 'wrapped: no echo: using %s:' % satest.engine1.logger
    do_timing(run_queries_nologging)
    satest.engine2.echo = True
    print >> sys.stderr, 'unwrapped: with echo: using %s:' % satest.engine2.logger
    do_timing(run_queries_logging)
    satest.engine2.logger = satest.EngineLogger(satest.engine2)
    print >> sys.stderr, 'wrapped: with echo: using %s:' % satest.engine2.logger
    do_timing(run_queries_logging)

if __name__ == '__main__':
    main()