Autoloading table from database causes ~1 minute delay when shutting down PostgreSQL

When I connect to a PostgreSQL database and autoload a table, and do nothing else, shutting down PostgreSQL hangs for about a minute, unless I call engine.dispose() before doing so.

I'm not sure if this is a bug or something that I missed in the documentation. I only found out yesterday by trial and error how to solve this, and it wasn't clear from me from the docs that I needed to do this.

My environment:

Windows 7 Professional SP1
Python 2.7.8 64 bit
PostgreSQL 9.3.3
SQLAlchemy==1.0.5
psycopg2==2.6.1

(Also happens with:

SQLAlchemy==0.9.3
psycopg2==2.5.3)

Repro code:

import logging
from sqlalchemy import *


logger = logging.getLogger(__name__)


def repro(_host, _port, _username, _password, _dbname, _table_name):
    """Reproduce slow PostgreSQL shutdown issue.

    Keyword arguments:
    _host -- The host address of the PostgreSQL database server.
    _port -- The port used by the PostgreSQL database server.
    _username -- The username to be used with the PostgreSQL database server.
    _password -- The password for the PostgreSQL database server.
    _dbname -- The name of the database in the PostgreSQL database server.
    _table_name -- The name of any table in the database.
    """

    # Maximum logging.

    # See http://docs.sqlalchemy.org/en/rel_0_9/core/engines.html#configuring-logging.
    # "set to logging.INFO for SQL query output"
    logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)
    # "set to logging.INFO or lower to log connection pool checkouts/checkins."
    logging.getLogger("sqlalchemy.pool").setLevel(logging.INFO)
    # "set to logging.INFO for information on mapper configurations."
    logging.getLogger("sqlalchemy.orm").setLevel(logging.INFO)
    # See http://docs.sqlalchemy.org/en/rel_0_9/dialects/postgresql.html.
    # "The psycopg2 dialect will log Postgresql NOTICE messages via the
    #  sqlalchemy.dialects.postgresql logger"
    logging.getLogger("sqlalchemy.dialects.postgresql").setLevel(logging.INFO)

    # Create engine for the indended database.
    engine = _create_engine(_host, _port, _username, _password, _dbname, True)

    # Load tables from the database.
    metadata = MetaData(bind=engine)
    a_table = Table(_table_name, metadata, autoload=True)

    # With the following line disabled, shutting down PostgreSQL will take about 1 minute longer.
    # engine.dispose()


def _build_database_URI(_host, _port, _username, _password, _dbname):
    return "postgresql+psycopg2://{user}:{password}@{host}:{port}/{dbname}".\
        format(user=_username, password=_password, host=_host, port=_port, dbname=_dbname)

def _create_engine(_host, _port, _username, _password, _dbname, _debug):
    return create_engine(_build_database_URI(_host, _port, _username, _password, _dbname), echo=_debug, echo_pool=_debug)


if __name__ == "__main__":
    # Set up logging.
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_handler.setFormatter(logging.Formatter('%(message)s'))

    root_logger = logging.getLogger("")
    root_logger.setLevel(logging.DEBUG)
    root_logger.addHandler(console_handler)

    logger.info("Connecting to the database...")
    repro(
        _host = "localhost",
        _port = 5439,
        _username = "<user>",
        _password = "<password>",
        _dbname = "<db name>",
        _table_name ="<any table name>"        
    )

    logger.info("Connected to the database. Try stopping the PostgreSQL server.")

    raw_input("Press enter to stop...")

Repro steps:

Start PostgreSQL server.
Start Python code above.
Shut down PostgreSQL server.

Stopping the PostgreSQL server takes about a minute (and may fail).

Enable the engine.dispose() line, repeat, shutting down PostgreSQL takes under a second.

My use case is unusual: I have a Windows executable that starts and stops its own local PostgreSQL server.

I can sorta see in retrospect that the autoloading does something that stops the shutdown from proceeding smoothly, but overall this behavior was surprising to me.

The documentation of engine.dispose() does not indicate to me that this is something I need to call to enable a smooth PostgreSQL shutdown. I also couldn't find other obvious "here's how to shut down bits of SQLAlchemy" advice in the documentation.

Once I had more or less accidentally reduced the problem to these few lines, I found this solution by going through the APIs of Engine, Metadata, and Table, and trying to call everything that sounded like it should be called during shutdown.

Comments (13)