Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
1.1.9, 1.1.10
-
None
-
None
-
None
-
MariaDB Server 10.11.8 (Tested also on 10.3)
Centos 7 (Tested also on Rocky 8 and 9)
MariaDB Connector/Python 1.1.10 (Tested also on 1.1.9)
MariaDB Connector/C 3.3.8
Sqlalchemy 1.4.51
Python: 3.8 (Tested also on 3.11)
-
3.8
Description
After upgrading MariaDB Connector/Python to the 1.1.10 version, parallel deletion queries hangs forever.
When I'm making parallel DB queries that affect the same subset of rows, the queries are blocked for 50 secs (default lock timeout) and then fail.
I'm using SQLALchemy as ORM. The issue, however, seems not be related to the SQLAlchemy as it works using the 1.1.8 version of the Python connector. Apparently, it started being an issue from version 1.1.9.
Code:
from concurrent.futures import ThreadPoolExecutor |
from datetime import datetime |
from time import perf_counter |
|
|
from sqlalchemy import create_engine |
from sqlalchemy.orm import sessionmaker, scoped_session |
|
|
from models import AccessToken |
|
|
engine = create_engine( |
"mysql+mariadbconnector://user:password@sql/user?charset=utf8", echo=True |
)
|
session_factory = sessionmaker(bind=engine) |
Session = scoped_session(session_factory) |
|
|
|
|
def run() -> None: |
session = Session() |
session.query(AccessToken).filter( |
AccessToken.valid_to < datetime(2020, 1, 1) |
).delete()
|
session.close()
|
|
|
with ThreadPoolExecutor(max_workers=10) as executor: |
futures = [executor.submit(run) for _ in range(10)] |
for future in futures: |
future.result()
|
The database shows me that the query is blocking, even if it's supposed to be superfast (I have an empty table, without any records)
SELECT r.trx_id AS waiting_trx_id, r.trx_mysql_thread_id AS waiting_thread_id, r.trx_query AS waiting_query, r.trx_started AS waiting_since, b.trx_id AS blocking_trx_id, b.trx_mysql_thread_id AS blocking_thread_id, b.trx_query AS blocking_query, b.trx_started AS blocking_since FROM INFORMATION_SCHEMA.INNODB_LOCK_WAITS AS w INNER JOIN INFORMATION_SCHEMA.INNODB_TRX AS r ON w.requesting_trx_id = r.trx_id INNER JOIN INFORMATION_SCHEMA.INNODB_TRX AS b ON w.blocking_trx_id = b.trx_id ORDER BY r.trx_started \G;
|
*************************** 1. row ***************************
|
waiting_trx_id: 812
|
waiting_thread_id: 136
|
waiting_query: DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
waiting_since: 2024-06-14 07:42:59
|
blocking_trx_id: 811
|
blocking_thread_id: 138
|
blocking_query: NULL
|
blocking_since: 2024-06-14 07:42:59
|
Logs from SQLAlchemy don't show anything suspicious:
2024-06-14 07:36:19,392 INFO sqlalchemy.engine.Engine SELECT DATABASE()
|
INFO | ThreadPoolExecutor-0_0 | SELECT DATABASE()
|
2024-06-14 07:36:19,392 INFO sqlalchemy.engine.Engine [raw sql] ()
|
INFO | ThreadPoolExecutor-0_0 | [raw sql] ()
|
2024-06-14 07:36:19,393 INFO sqlalchemy.engine.Engine SELECT @@sql_mode
|
INFO | ThreadPoolExecutor-0_0 | SELECT @@sql_mode
|
2024-06-14 07:36:19,393 INFO sqlalchemy.engine.Engine [raw sql] ()
|
INFO | ThreadPoolExecutor-0_0 | [raw sql] ()
|
2024-06-14 07:36:19,393 INFO sqlalchemy.engine.Engine SELECT @@lower_case_table_names
|
INFO | ThreadPoolExecutor-0_0 | SELECT @@lower_case_table_names
|
2024-06-14 07:36:19,393 INFO sqlalchemy.engine.Engine [raw sql] ()
|
INFO | ThreadPoolExecutor-0_0 | [raw sql] ()
|
2024-06-14 07:36:19,394 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_0 | BEGIN (implicit)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_0 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_7 | BEGIN (implicit)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_3 | BEGIN (implicit)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine [generated in 0.00037s] (datetime.datetime(2020, 1, 1, 0, 0),)
|
INFO | ThreadPoolExecutor-0_0 | [generated in 0.00037s] (datetime.datetime(2020, 1, 1, 0, 0),)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_2 | BEGIN (implicit)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_8 | BEGIN (implicit)
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_7 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,395 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_4 | BEGIN (implicit)
|
2024-06-14 07:36:19,396 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_1 | BEGIN (implicit)
|
2024-06-14 07:36:19,396 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_3 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,396 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
2024-06-14 07:36:19,396 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
2024-06-14 07:36:19,396 INFO sqlalchemy.engine.Engine BEGIN (implicit)
|
INFO | ThreadPoolExecutor-0_9 | BEGIN (implicit)
|
2024-06-14 07:36:19,397 INFO sqlalchemy.engine.Engine ROLLBACK
|
2024-06-14 07:36:19,397 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_6 | BEGIN (implicit)
|
2024-06-14 07:36:19,397 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_5 | BEGIN (implicit)
|
2024-06-14 07:36:19,397 INFO sqlalchemy.engine.Engine [cached since 0.00287s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
INFO | ThreadPoolExecutor-0_0 | ROLLBACK
|
2024-06-14 07:36:19,398 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_2 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,398 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,398 INFO sqlalchemy.engine.Engine [cached since 0.003554s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
2024-06-14 07:36:19,398 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_8 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_7 | [cached since 0.00287s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
2024-06-14 07:36:19,399 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_4 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,399 INFO sqlalchemy.engine.Engine DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
INFO | ThreadPoolExecutor-0_1 | DELETE FROM access_tokens WHERE access_tokens.valid_to < ?
|
2024-06-14 07:36:19,399 INFO sqlalchemy.engine.Engine [cached since 0.004597s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
2024-06-14 07:36:19,399 INFO sqlalchemy.engine.Engine [cached since 0.004847s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
INFO | ThreadPoolExecutor-0_3 | [cached since 0.003554s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
2024-06-14 07:36:19,400 INFO sqlalchemy.engine.Engine [cached since 0.005374s ago] (datetime.datetime(2020, 1, 1, 0, 0),)
|
I attached flamegraphs for both 1.1.8 version when everything works fine and 1.1.10. It seems like it blocks in this place: https://github.com/mariadb-corporation/mariadb-connector-python/blob/1.1/mariadb/connections.py#L85
