Why psycopg2 has the same 'psycopg2.extensions.connection' object id in forked processes ?

[kamyanskiy]

Good day, first I started discussion here sqlalchemy/sqlalchemy#7515, but we didn't gain answer there and one of maintainers advice me to ask here? because all goes to psycopg2 call.

So the question is when Flask application with SQLAlchemy (with psycopg2-binary) starts in forked processes (Gunicorn sync workers) I see that psycopg2.extensions.connection have the same object ids in different processes PIDs.

So in short words that call returns the same conn id :
https://github.com/psycopg/psycopg2/blob/master/lib/__init__.py#L122

So I worry about if the different processes are trying to use the same connection , its not safe am I right ?

Below I write down minimal app to reproduce issue and logs with my comments:

Environment

Linux Mint 20.1
Linux matrix 5.4.0-91-generic #102-Ubuntu SMP Fri Nov 5 16:31:28 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Python 3.9.9 (main, Nov 16 2021, 03:08:02)

Flask==2.0.2
gunicorn==20.1.0
psycopg2-binary==2.9.3
SQLAlchemy==1.4.29

gunicorn_example.py

import os
from typing import Dict, List
from pprint import pprint
from flask import Flask, jsonify
from sqlalchemy import create_engine, Integer, Column
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy.orm import sessionmaker
from psycopg2 import connect

host = "localhost"
user = "developer"
password = "password"
db = "db"
db_url = f"postgresql://{user}:{password}@{host}/{db}"

engine = create_engine(
    db_url,
    pool_size=5,     # default in SQLAlchemy
    max_overflow=10, # default in SQLAlchemy
    echo_pool='debug'
)

engine.dispose() # Recreate QueuePool, to discard all DBAPI connections.
print("pid: %s, engine id: %s" % (os.getpid(), id(engine)))

Session = sessionmaker(bind=engine)

Base = declarative_base()


class User(Base):
    __tablename__ = "user"

    id = Column(Integer, primary_key=True)

Base.metadata.create_all(engine)


def get_connections():
    """Return information about PG connections"""
    sql = """
    SELECT
        pid,
        state,
        query_start,
        query
    FROM pg_stat_activity
    WHERE datname = 'db'
    AND query NOT LIKE '%%FROM pg_stat_activity%%' and query_start is not null and application_name not like '%%DBeaver%%';
    """
    connection = connect(db_url)
    cursor = connection.cursor()
    cursor.execute(sql)
    connections = [
        {"pid": r[0], "state": r[1], "query": r[3]} for r in cursor.fetchall()
    ]
    cursor.close()
    connection.close()
    return connections

def get_pool_info() -> Dict:
    """Get information about the current connections and pool"""
    return {
        "process PID:":  '[%s]' % os.getpid(),
        "postgres connections": get_connections(),
        "pool id": id(engine.pool),
        "connections in current pool": (
            engine.pool.checkedin() + engine.pool.checkedout()
        ),
    }


app = Flask(__name__)


@app.route("/")
def make_query():
    session = Session()
    session.query(User).all()
    session.close()
    pprint(get_pool_info())
    return jsonify(get_pool_info())

App starts with command:

$ gunicorn --workers=2 gunicorn_example:app

And below logs:

[2021-12-30 14:34:19 +0300] [58423] [INFO] Starting gunicorn 20.1.0
[2021-12-30 14:34:19 +0300] [58423] [INFO] Listening at: http://127.0.0.1:8000 (58423)
[2021-12-30 14:34:19 +0300] [58423] [INFO] Using worker: sync
[2021-12-30 14:34:19 +0300] [58424] [INFO] Booting worker with pid: 58424
[2021-12-30 14:34:19 +0300] [58425] [INFO] Booting worker with pid: 58425
2021-12-30 14:34:19,338 INFO sqlalchemy.pool.impl.QueuePool Pool disposed. Pool size: 5  Connections in pool: 0 Current Overflow: -5 Current Checked out connections: 0
2021-12-30 14:34:19,338 INFO sqlalchemy.pool.impl.QueuePool Pool recreating
pid: 58424, engine id: 139760242462096
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ so we can see engine object in process id 58424 has id = 139760242462096

2021-12-30 14:34:19,344 INFO sqlalchemy.pool.impl.QueuePool Pool disposed. Pool size: 5  Connections in pool: 0 Current Overflow: -5 Current Checked out connections: 0
2021-12-30 14:34:19,344 INFO sqlalchemy.pool.impl.QueuePool Pool recreating
pid: 58425, engine id: 139760242466336
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ here is 2nd process with pid 58425 and different engine id = 139760242466336 , so as expected.

2021-12-30 14:34:19,347 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

2021-12-30 14:34:19,350 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> checked out from pool
2021-12-30 14:34:19,352 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> being returned to pool
2021-12-30 14:34:19,352 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> rollback-on-return

2021-12-30 14:34:19,353 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

2021-12-30 14:34:19,357 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> checked out from pool
2021-12-30 14:34:19,359 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> being returned to pool
2021-12-30 14:34:19,359 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> rollback-on-return

so in some reason I see that psycopg2 conections in both processes have the same addresses (and I tried to get id(conn), beleive me they re the same)

2021-12-30 14:34:19,347 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
...
2021-12-30 14:34:19,353 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f1c779d6900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

So question - why, is it really the same connection ? If I check postgres opened connections, in fact I see 2 connections as expected, but these identical IDs in logs is very confuse me.

So maybe if here somebody has power to explain me what happening, please will be too appreciated :)

[kamyanskiy]

Is psycopg inside has magic to return the same connection object from memory to different forked processes ?

[dvarrazzo]

When a process is forked, the memory allocated is copied for the new process. The id of the python object is its address memory, but that's a virtual address in the process address space. You will see the same with any Python object.

Thank you for the assumption that psycopg has magic inside, but unfortunately that's not the case.

What you are doing, by the way, will not work, because you are also duplicating the socket. From the libpq docs:

On Unix, forking a process with open libpq connections can lead to unpredictable results because the parent and child processes share the same sockets and operating system resources. For this reason, such usage is not recommended, though doing an exec from the child process to load a new executable is safe.

If you are writing a multiprocess program you should create the database connections after forking.

[kamyanskiy]

thank you for answer @dvarrazzo
so my idea was that when I call

engine.dispose() # Recreate QueuePool, to discard all DBAPI connections.

and into each forked process, connection for each new engine will be re-created. Another thing that kill my mind, that I do nothing with code, and time to time when app starts I see all things as expected. So I can start app and I see idential connection ids. But sometimes they are really different.

(.venv39) ➜  gunicorn-example-multiprocess gunicorn --workers=2 gunicorn_example:app
[2021-12-30 15:31:36 +0300] [63522] [INFO] Starting gunicorn 20.1.0
[2021-12-30 15:31:36 +0300] [63522] [INFO] Listening at: http://127.0.0.1:8000 (63522)
[2021-12-30 15:31:36 +0300] [63522] [INFO] Using worker: sync
[2021-12-30 15:31:36 +0300] [63523] [INFO] Booting worker with pid: 63523
[2021-12-30 15:31:36 +0300] [63524] [INFO] Booting worker with pid: 63524
2021-12-30 15:31:36,528 INFO sqlalchemy.pool.impl.QueuePool Pool disposed. Pool size: 5  Connections in pool: 0 Current Overflow: -5 Current Checked out connections: 0

2021-12-30 15:31:36,528 INFO sqlalchemy.pool.impl.QueuePool Pool recreating
pid: 63523, engine id: 140183299345856
2021-12-30 15:31:36,537 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f7ef7c52900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

2021-12-30 15:31:36,541 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c52900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> checked out from pool
2021-12-30 15:31:36,543 INFO sqlalchemy.pool.impl.QueuePool Pool disposed. Pool size: 5  Connections in pool: 0 Current Overflow: -5 Current Checked out connections: 0
2021-12-30 15:31:36,543 INFO sqlalchemy.pool.impl.QueuePool Pool recreating
pid: 63524, engine id: 140183299896800
2021-12-30 15:31:36,543 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c52900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> being returned to pool
2021-12-30 15:31:36,543 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c52900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> rollback-on-return

2021-12-30 15:31:36,551 DEBUG sqlalchemy.pool.impl.QueuePool Created new connection <connection object at 0x7f7ef7c53900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0>
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^  They are different here as expected.

2021-12-30 15:31:36,555 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c53900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> checked out from pool
2021-12-30 15:31:36,557 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c53900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> being returned to pool
2021-12-30 15:31:36,557 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f7ef7c53900; dsn: 'user=developer password=xxx dbname=db host=localhost', closed: 0> rollback-on-return

[dvarrazzo]

Yes, sorry for the hurried up response earlier: I see now that new connections are created in the two processes. I also see that Python objects (app, engine) have different ids.

I don't have anything in mind. Maybe C objects get allocated from a pool that has less variance than the Python ones?

However I have tried your test, with some changes, and I see different connection ids:

2021-12-30 13:57:13,062 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f235cabe400; dsn: 'host=localhost user=piro dbname=piro', closed: 0> rollback-on-return
{'connections in current pool': 1,
 'pool id': 139789883653088,
 'postgres connections': [{'conn_id': 139789855352128,
...

2021-12-30 13:57:13,248 DEBUG sqlalchemy.pool.impl.QueuePool Connection <connection object at 0x7f235cac0400; dsn: 'host=localhost user=piro dbname=piro', closed: 0> rollback-on-return
{'connections in current pool': 1,
 'pool id': 139789906194240,
 'postgres connections': [{'conn_id': 139789855360320,
...

so... maybe just a chance?

[kamyanskiy]

@dvarrazzo
that interesting that after a while if you break server execution by Ctrl+C , then you start app again, it might to be reproduced )))

[kamyanskiy]

""" I don't have anything in mind. Maybe C objects get allocated from a pool that has less variance than the Python ones? """

yes it might be, vary probably, but looking for 'titan of programming' who can explain me that ))