Project

General

Profile

Actions

Bug #4251

closed

User data access through SQLAlchemy keeps a transaction open

Added by Pavel Kácha over 4 years ago. Updated almost 3 years ago.

Status:
Closed
Priority:
Low
Assignee:
Category:
Development - Core
Target version:
Start date:
08/09/2018
Due date:
% Done:

100%

Estimated time:
To be discussed:
No

Description

Date: Fri, 25 May 2018 10:45:45 +0200
From: Radko Krkoš <>
Subject: Visiaci dotaz

Ahoj, 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

Related to Mentat - Bug #4569: Hawat DB connection is not recreated if droppedClosedRadko Krkoš01/17/2019

Actions
Related to Mentat - Task #6205: Review encapsulation of SQLAlchemy and Psycopg2 DBALsClosedRajmund Hruska01/24/2020

Actions
Actions #1

Updated by Pavel Kácha over 4 years ago

  • Subject changed from Visící dotaz to Hanging query
Actions #2

Updated by Pavel Kácha over 4 years ago

Note: Moved from email, continuation in english, please.

Actions #3

Updated by Pavel Kácha about 4 years ago

  • Target version changed from Backlog to 2.1
Actions #4

Updated by Jan Mach about 4 years ago

  • Priority changed from Normal to Urgent
Actions #5

Updated by Jan Mach about 4 years ago

  • Target version changed from 2.1 to Backlog
Actions #6

Updated by Radko Krkoš almost 4 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.

Actions #7

Updated by Pavel Kácha almost 4 years ago

  • Related to Bug #4569: Hawat DB connection is not recreated if dropped added
Actions #8

Updated by Pavel Kácha almost 4 years ago

Added #4569 as related - as this query crashes first after db reconnection.

Actions #9

Updated by Radko Krkoš almost 3 years ago

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

Actions #10

Updated by Jan Mach almost 3 years ago

  • Target version changed from Backlog to 2.6
Actions #11

Updated by Jan Mach almost 3 years ago

  • Related to Task #6205: Review encapsulation of SQLAlchemy and Psycopg2 DBALs added
Actions #12

Updated by Jan Mach almost 3 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.

Actions #13

Updated by Jan Mach almost 3 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.

Actions

Also available in: Atom PDF