Opened 4 months ago

Last modified 4 months ago

#35672 closed Bug

Using database connection pooling, threads do not return the connection — at Version 9

Reported by: André S. Hansen Owned by:
Component: Database layer (models, ORM) Version: 5.1
Severity: Normal Keywords:
Cc: Florian Apolloner Triage Stage: Unreviewed
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description (last modified by André S. Hansen)

I am testing the new db connection pooling, which increased the performance greatly, typically lowering api response times from 30ms -> 20ms on my dev env.

However, after a while i started getting 

psycopg_pool.PoolTimeout : couldn't get a connection after 30.00 sec

Further investigation shows the reason was a Threaded Middleware orm interaction, like this simplified code.

class TimeMonitorMiddleware(object):
    batched_logs: List[RequestLog] = []

    def __call__(self, request: WSGIRequest) -> HttpResponse:
        # ...
  
        # Save batched logs
        if len(self.batched_logs) >= 50:
            Thread(target=RequestLog.objects.bulk_create, args=(batched_logs,)).start()

        return response

Using settings

{
   "ENGINE": os.environ.get("DB_ENGINE", "django.db.backends.postgresql"),
   "OPTIONS": {"pool": True}
}

Extra info:

  • Python 3.12.1
  • Django 5.1
  • psycopg 3.2.1
  • psycopg-pool 3.2.2
  • Local docker image hosted postgresql database using image "postgres"

Change History (9)

comment:1 by André S. Hansen, 4 months ago

Description: modified (diff)

comment:2 by Sarah Boyce, 4 months ago

Cc: Florian Apolloner added
Resolution: → needsinfo
Status: new → closed

Hi Andre, I think we need more information to understand whether/where Django is at fault here

I believe you have this error because the connection pool is full, this could mean that Django is not closing connections after using them. For us to be able to identify where this is happening, can you share a minimal Django project and steps to reproduce?

comment:3 by Florian Apolloner, 4 months ago

Hi André, it would probably help if you enabled the psycopg.pool logger and then check if the connections are returned to the pool properly. Also what is your request rate and how long are the requests taking? How are you running the django server? What are the postgresql connection limits?

comment:4 by André S. Hansen, 4 months ago

I did some more testing and figured out the source of the problem. When i disabled a Middleware Threaded connection to the database, the bug stopped happening. My current theory is that the thread dont return the connection to the pool. I am investigating now how i should properly do this with Threads.

Simplified version of code

class TimeMonitorMiddleware(object):
    batched_logs: List[RequestLog] = []

    def __call__(self, request: WSGIRequest) -> HttpResponse:
        # ...
  
        # Save batched logs
        if len(self.batched_logs) >= 50:
            Thread(target=RequestLog.objects.bulk_create, args=(batched_logs,)).start()

        return response
Last edited 4 months ago by André S. Hansen (previous) (diff)

comment:5 by André S. Hansen, 4 months ago

Summary: Using database connection pooling raises PoolTimeout after a while → Using database connection pooling with threads raises PoolTimeout after a while

comment:6 by André S. Hansen, 4 months ago

Summary: Using database connection pooling with threads raises PoolTimeout after a while → Using database connection pooling, threads do not return the connection

comment:7 by André S. Hansen, 4 months ago

Description: modified (diff)
Resolution: needsinfo
Status: closed → new

comment:8 by André S. Hansen, 4 months ago

Description: modified (diff)

comment:9 by André S. Hansen, 4 months ago

Description: modified (diff)

Example error logs

Logs

[13/Aug/2024 00:50:41] "POST /api/instances/2/actions/move/ HTTP/1.1" 200 91
couldn't get a connection after 30.00 sec
Traceback (most recent call last):
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 279, in ensure_connection
    self.connect()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 256, in connect
    self.connection = self.get_new_connection(conn_params)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\postgresql\base.py", line 348, in get_new_connection
    connection = self.pool.getconn()
                 ^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\psycopg_pool\pool.py", line 202, in getconn
    raise PoolTimeout(
psycopg_pool.PoolTimeout: couldn't get a connection after 30.00 sec

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\ninja\operation.py", line 192, in _run_authentication
    result = callback(request)
             ^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\ninja\security\apikey.py", line 23, in __call__
    return self.authenticate(request, key)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\ninja\security\session.py", line 17, in authenticate
    if request.user.is_authenticated:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\functional.py", line 251, in inner
    self._setup()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\functional.py", line 404, in _setup
    self._wrapped = self._setupfunc()
                    ^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\middleware.py", line 37, in <lambda>
    request.user = SimpleLazyObject(lambda: get_user(request))
                                            ^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\middleware.py", line 17, in get_user
    request._cached_user = auth.get_user(request)
                           ^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\__init__.py", line 209, in get_user
    user_id = _get_user_session_key(request)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\__init__.py", line 62, in _get_user_session_key
    return get_user_model()._meta.pk.to_python(request.session[SESSION_KEY])
                                               ~~~~~~~~~~~~~~~^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\base.py", line 55, in __getitem__
    return self._session[key]
           ^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\base.py", line 249, in _get_session
    self._session_cache = self.load()
                          ^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\db.py", line 55, in load
    s = self._get_session_from_db()
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\db.py", line 34, in _get_session_from_db
    return self.model.objects.get(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 645, in get
    num = len(clone)
          ^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 382, in __len__
    self._fetch_all()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 1928, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 91, in __iter__
    results = compiler.execute_sql(
              ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 37, in inner
    return original(compiler, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 94, in inner
    return execute_query_func()
           ^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 80, in <lambda>
    execute_query_func = lambda: original(compiler, *args, **kwargs)
                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\sql\compiler.py", line 1572, in execute_sql
    cursor = self.connection.cursor()
             ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 320, in cursor
    return self._cursor()
           ^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 296, in _cursor
    self.ensure_connection()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 278, in ensure_connection
    with self.wrap_database_errors:
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 279, in ensure_connection
    self.connect()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 256, in connect
    self.connection = self.get_new_connection(conn_params)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\postgresql\base.py", line 348, in get_new_connection
    connection = self.pool.getconn()
                 ^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\psycopg_pool\pool.py", line 202, in getconn
    raise PoolTimeout(
django.db.utils.OperationalError: couldn't get a connection after 30.00 sec
Internal Server Error: /api/instances/2/actions/move/
Traceback (most recent call last):
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 279, in ensure_connection
    self.connect()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 256, in connect
    self.connection = self.get_new_connection(conn_params)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\postgresql\base.py", line 348, in get_new_connection
    connection = self.pool.getconn()
                 ^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\psycopg_pool\pool.py", line 202, in getconn
    raise PoolTimeout(
psycopg_pool.PoolTimeout: couldn't get a connection after 30.00 sec

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
               ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Repos\untitledgame\backend\monitor\middleware.py", line 35, in __call__
    user_id=user_id_or_none(request.user),
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Repos\untitledgame\backend\game\api\utils.py", line 9, in user_id_or_none
    if isinstance(user, AnonymousUser):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\functional.py", line 280, in __getattribute__
    value = super().__getattribute__(name)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\functional.py", line 251, in inner
    self._setup()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\functional.py", line 404, in _setup
    self._wrapped = self._setupfunc()
                    ^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\middleware.py", line 37, in <lambda>
    request.user = SimpleLazyObject(lambda: get_user(request))
                                            ^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\middleware.py", line 17, in get_user
    request._cached_user = auth.get_user(request)
                           ^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\__init__.py", line 209, in get_user
    user_id = _get_user_session_key(request)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\auth\__init__.py", line 62, in _get_user_session_key
    return get_user_model()._meta.pk.to_python(request.session[SESSION_KEY])
                                               ~~~~~~~~~~~~~~~^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\base.py", line 55, in __getitem__
    return self._session[key]
           ^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\base.py", line 249, in _get_session
    self._session_cache = self.load()
                          ^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\db.py", line 55, in load
    s = self._get_session_from_db()
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\contrib\sessions\backends\db.py", line 34, in _get_session_from_db
    return self.model.objects.get(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\manager.py", line 87, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 645, in get
    num = len(clone)
          ^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 382, in __len__
    self._fetch_all()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 1928, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\query.py", line 91, in __iter__
    results = compiler.execute_sql(
              ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 37, in inner
    return original(compiler, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 94, in inner
    return execute_query_func()
           ^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\cachalot\monkey_patch.py", line 80, in <lambda>
    execute_query_func = lambda: original(compiler, *args, **kwargs)
                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\models\sql\compiler.py", line 1572, in execute_sql
    cursor = self.connection.cursor()
             ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 320, in cursor
    return self._cursor()
           ^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 296, in _cursor
    self.ensure_connection()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 278, in ensure_connection
    with self.wrap_database_errors:
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 279, in ensure_connection
    self.connect()
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\base\base.py", line 256, in connect
    self.connection = self.get_new_connection(conn_params)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\utils\asyncio.py", line 26, in inner
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\django\db\backends\postgresql\base.py", line 348, in get_new_connection
    connection = self.pool.getconn()
                 ^^^^^^^^^^^^^^^^^^^
  File "C:\Users\andre\.virtualenvs\backend-jnn8gBG-\Lib\site-packages\psycopg_pool\pool.py", line 202, in getconn
    raise PoolTimeout(
django.db.utils.OperationalError: couldn't get a connection after 30.00 sec
[13/Aug/2024 00:56:42] "POST /api/instances/2/actions/move/ HTTP/1.1" 500 235606
Note: See TracTickets for help on using tickets.
Back to Top