Bug #4251
closedUser data access through SQLAlchemy keeps a transaction open
100%
Description
Date: Fri, 25 May 2018 10:45:45 +0200
From: Radko Krkoš <krkos@cesnet.cz>
Subject: Visiaci dotazAhoj, všimol som si že krátko po štarte Mentatu sa spustí dotaz:
SELECT groups.name AS groups_name, groups.source AS groups_source,
groups.description AS groups_description, groups.enabled AS
groups_enabled, groups.parent_id AS groups_parent_id, groups.id AS
groups_id, groups.createtime AS groups_createtime FROM groups WHERE
groups.id = 7747;ktorý nikdy (20h+) nedobehne. Má niekto tušenie čo to je a ako to že to
ničomu v Mentate nevadí?
Na neskôr:
Zaujímavé je, že keď ten dotaz spustím ručne, prebehne normálne a okamžite.
Mek:
Smrdí mi to zapomenutým commitem...někde. Dotaz proběhne v pořádku, ale pak nezavolám commit a na straně serveru to asi zůstane viset.
Radko:
To asi nebude ono, po SELECTe to netreba.
Radko:
Už asi rozumiem čo si myslel. Zdá sa že to nejako blokuje iné spojenie.
Vyzerá to na COMMIT, ale nie nezavolaný ale zrejme naviac. Je ho tiež
vidieť v zozname bežiacich transakcií ale bez doby behu. Nemám ale
tušenie ako to debugovať. Rozmýšľal som či niečo nevolá COMMIT v slučke
aj bez dát ale čo som pozeral kód, tak by to tak byť nemalo.
Příklad výseku z pg_stat_activity:
datid | datname | pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query | backend_type
---------+---------------+-------+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------+-----------------+---------------------+---------------------+-------------+--------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------
7655235 | mentat_main | 1671 | 16384 | mentat | | ::1 | | 47378 | 2018-08-09 09:55:24.522505+02 | | 2018-08-09 09:55:32.502753+02 | 2018-08-09 09:55:32.502889+02 | Client | ClientRead | idle | | | ROLLBACK | client backend
16385 | mentat_events | 67217 | 16384 | mentat | | ::1 | | 42290 | 2018-08-07 10:48:28.172669+02 | | 2018-08-09 15:19:05.295189+02 | 2018-08-09 15:19:05.295292+02 | Client | ClientRead | idle | | | COMMIT | client backend
7655235 | mentat_main | 67226 | 16384 | mentat | | ::1 | | 42300 | 2018-08-07 10:48:29.268503+02 | 2018-08-07 10:48:29.277103+02 | 2018-08-09 15:14:49.378458+02 | 2018-08-09 15:14:49.378649+02 | Client | ClientRead | idle in transaction | | | SELECT groups.name AS groups_name, groups.source AS groups_source, groups.description AS groups_description, groups.enabled AS groups_enabled, groups.parent_id AS groups_parent_id, groups.createtime AS groups_createtime, groups.id AS groups_id +| client backend
| | | | | | | | | | | | | | | | | | FROM groups +|
| | | | | | | | | | | | | | | | | | WHERE groups.id = 297 |
(11 rows)
Nevíme, co to způsobuje, proč to visí, nebo zda je to z nějakého důvodu korektní.
Files
Related issues
Updated by Pavel Kácha over 6 years ago
- Subject changed from Visící dotaz to Hanging query
Updated by Pavel Kácha over 6 years ago
Note: Moved from email, continuation in english, please.
Updated by Pavel Kácha about 6 years ago
- Target version changed from Backlog to 2.1
Updated by Jan Mach about 6 years ago
- Target version changed from 2.1 to Backlog
Updated by Radko Krkoš almost 6 years ago
- Subject changed from Hanging query to User data access through SQLAlchemy keeps a transaction open
- Assignee changed from Jan Mach to Radko Krkoš
- Priority changed from Urgent to Low
Based on VC discussion: As this was present for quite some time and is not known to cause any problems, decreasing priority. On the other hand, this should be debugged eventually, so let's try a fresh set of eyes.
Updated by Pavel Kácha almost 6 years ago
- Related to Bug #4569: Hawat DB connection is not recreated if dropped added
Updated by Pavel Kácha almost 6 years ago
Added #4569 as related - as this query crashes first after db reconnection.
Updated by Radko Krkoš almost 5 years ago
- File 0001-Fix-Hanging-transaction-in-whois-plugin-configuratio.patch 0001-Fix-Hanging-transaction-in-whois-plugin-configuratio.patch added
- Assignee changed from Radko Krkoš to Jan Mach
- To be discussed changed from No to Yes
The issue was (finally) debugged and identified to be in mentat-enricher's whois plugin configuration load from database. The data handling was left to the SQLAlchemy's ORM code, but the query is in fact lazy executed. Therefore the correct way is to do no storage.session.commit() before the actual execution of the query, but to do a storage.session.rollback() after. According to documentation [1], the Session's commit() method commits the transaction and begins a new one (at least in the only still supported autocommit=False mode). On the other hand, the rollback() method [2] closes the transaction and another one is started only when required by the Session (next query is executed).
This is the correct way as it does not leave the transaction open anymore, helping PostgreSQL's MVCC handling and also only starting transaction on true configuration reload, shortening the actual configuration update cycle to one reload cycle, instead of 2.
The general take from here is that if using SQLAlchemy, after Session.query() always call rollback() instead of commit(). The second one is never correct, it can just be only a little incorrect.
The attached patch vs devel contains the fix. Let us discuss this and I am handing this over to Mek.
[1] https://docs.sqlalchemy.org/en/14/orm/session_api.html#sqlalchemy.orm.session.Session.commit
[2] https://docs.sqlalchemy.org/en/14/orm/session_api.html#sqlalchemy.orm.session.Session.rollback
Updated by Jan Mach almost 5 years ago
- Target version changed from Backlog to 2.6
Updated by Jan Mach almost 5 years ago
- Related to Task #6205: Review encapsulation of SQLAlchemy and Psycopg2 DBALs added
Updated by Jan Mach almost 5 years ago
- Status changed from New to Feedback
- % Done changed from 0 to 100
I have deployed patch created by Radko Krkoš with some additional tweaks by myself and confirm, that no idle in transaction row is visible in pg_stat_activity table.
Updated by Jan Mach almost 5 years ago
- Status changed from Feedback to Closed
- To be discussed changed from Yes to No
Fixed the issue with closing and reopening database connections. Closing.