We reproduced this problem and added logs in psycopg2, found a confusing thing and reported it to psycopg2.
It seems sqlalchemy & psycopg2 stack flow is: 1.from sqlalchemy to psycopg: pq_execute/pq_commit 2.from psycopg to sqlalchemy PyWeakref_NewRef(conn) 3.get exception in sqlalchemy, and do_rollback 4.from sqlalchemy to psycopg: pq_abort 5.psycopg get pthread_mutex_lock deadlock What we have done to reproduce it is: stop master pg-server and promote the slave pg-server to master, with moving FIP from old master to slave. At the same time, let nova-conductor do quite a lot db query requests. [1] https://github.com/psycopg/psycopg2/issues/703 在 2018年4月23日星期一 UTC+8下午9:45:04，Mike Bayer写道： > > On Mon, Apr 23, 2018 at 9:03 AM, <[email protected] <javascript:>> > wrote: > > Sorry for reply on this topic. > > > > We recently get the same problem in our production environment. > > > > I found a patch in other lib [1], and they added conn.close() in > exception > > psycopg2.ProgrammingError. > > > > Shall we do the same in [2] ? > > SQLAlchemy does things much more carefully than that, we parse the > error message for specific ones that correspond to "connection is no > longer usable", we call these "is_disconnect" but it can be any > invalidating condition. > > You can make these yourself, and they can also be made to be part of > oslo.db, using the handle_error event: > > > http://docs.sqlalchemy.org/en/latest/core/events.html?highlight=handle_error#sqlalchemy.events.ConnectionEvents.handle_error > > > within oslo.db you would want to propose a change here: > > > https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/exc_filters.py#L387 > > > > > > > > > > [1] https://github.com/aio-libs/aiopg/pull/415/files?diff=split > > > > [2] > > > https://github.com/zzzeek/sqlalchemy/blob/master/lib/sqlalchemy/engine/base.py#L1289 > > > > > > > 在 2017年11月13日星期一 UTC+8上午10:44:31，JinRong Cai写道： > >> > >> Hi Michael , > >> > >> I am using openstack with postgresql which sqlalchemy and oslo_db > module > >> were used. > >> And there are some problems after my pg database switched over. > >> > >> Here is my switch over process: > >> 1. nova-conductor(python application) is running with DB connection > >> strings point to vip , which is in primary site(A) of pg. > >> 2. switch VIP from primary(A) to new primary(B) > >> 3. switch over pg: shutdown primary(A), promopt standby(B) to new > primary. > >> 4. nova-conductor is running in the whole process. > >> > >> After some seconds, I found some nova-conductor processes are hang with > >> status futex_wait_queue_me, and the status of the query in DB is "idle > in > >> transaction", the transaction was not commited or rollbacked! > >> I think disconnection was handled in the oslo_db, which will send a > >> ping(select 1) to DB. > >> > >> If DB was switchd over, the connection in the pool would be set with > >> status invalid, and reconnect after next check out. > >> > >> ###error messages from nova-conductor > >> localhost nova-conductor ERROR [pid:36365] [MainThread] [tid:122397712] > >> [exc_filters.py:330 _raise_for_remaining_DBAPIError] > >> [req-2bd8a290-e17b-4178-80a6-4b36d5793d85] DBAPIError exception wrapped > from > >> (psycopg2.ProgrammingError) execute cannot be used while an > asynchronous > >> query is underway [SQL: 'SELECT 1'] > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call > >> last): > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters File > >> "/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in > >> _execute_context > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters context) > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters File > >> "/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in > >> do_execute > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters > cursor.execute(statement, > >> parameters) > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters ProgrammingError: execute > >> cannot be used while an asynchronous query is underway > >> 36365 ERROR oslo_db.sqlalchemy.exc_filters > >> localhost nova-conductor ERROR [pid:36365] [MainThread] > [tid:122397712] > >> [log.py:122 error] [req-2bd8a290-e17b-4178-80a6-4b36d5793d85] Error > closing > >> cursor > >> 36365 ERROR sqlalchemy.pool.QueuePool Traceback (most recent call > last): > >> 36365 ERROR sqlalchemy.pool.QueuePool File > >> "/python2.7/site-packages/sqlalchemy/engine/base.py", line 1226, in > >> _safe_close_cursor > >> 36365 ERROR sqlalchemy.pool.QueuePool cursor.close() > >> 36365 ERROR sqlalchemy.pool.QueuePool ProgrammingError: close cannot > be > >> used while an asynchronous query is underway > >> 36365 ERROR sqlalchemy.pool.QueuePool > >> > >> ###ps status of nova-conductor > >> POD6-Mongodb03:/var/log/uvp-getosstat/statistics20171106101500log # cat > >> /proc/33316/stack > >> [<ffffffff810e4c24>] futex_wait_queue_me+0xc4/0x120 > >> [<ffffffff810e5799>] futex_wait+0x179/0x280 > >> [<ffffffff810e782e>] do_futex+0xfe/0x5b0 > >> [<ffffffff810e7d60>] SyS_futex+0x80/0x180 > >> [<ffffffff81654e09>] system_call_fastpath+0x16/0x1b > >> [<ffffffffffffffff>] 0xffffffffffffffff > >> > >> ### stack of the nova-conductor process > >> POD6-Mongodb03:/tmp # pstack 33316 > >> #0 0x00002b8449e35f4d in __lll_lock_wait () from > /lib64/libpthread.so.0 > >> #1 0x00002b8449e31d02 in _L_lock_791 () from /lib64/libpthread.so.0 > >> #2 0x00002b8449e31c08 in pthread_mutex_lock () from > >> /lib64/libpthread.so.0 > >> #3 0x00002b84554c44ab in pq_abort () from > >> /python2.7/site-packages/psycopg2/_psycopg.so > >> #4 0x00002b84554c955e in psyco_conn_rollback () from > >> /python2.7/site-packages/psycopg2/_psycopg.so > >> #5 0x00002b8449b42b50 in PyEval_EvalFrameEx () from > >> /lib64/libpython2.7.so.1.0 > >> #6 0x00002b8449b42ad0 in PyEval_EvalFrameEx () from > >> /lib64/libpython2.7.so.1.0 > >> > >> The psycopg2 was trying to close the cursor, and try to get the mutex > lock > >> "pthread_mutex_lock", but it seems that the cursor was used by other > >> session. > >> > >> > >> Questions: > >> > >> 1. What the error "ProgrammingError: close cannot be used while an > >> asynchronous query is underway" mean? > >> AFAIK, these caused by psycopg2, which means a asynchronous query was > >> executed in one connection. > >> But the I think the sqlalchemy was thread safe since it was patched by > >> eventlet, see details in eventlet/support/psycopg2_patcher.py > >> And we can see different green thread number in the log, as: > >> [pid:36365] [MainThread] [tid:122397712] > >> [pid:36365] [MainThread] [tid:122397815] > >> So, I guess the connection pool in one process is safe. > >> > >> 2. The nova-conductor was a multi-thread python client, which forked > >> several child process. > >> ps -elf|grep -i nova-conductor > >> 30878 1 pool_s /usr/bin/nova-conductor > >> 36364 1 ep_pol /usr/bin/nova-conductor > >> 36365 1 futex_ /usr/bin/nova-conductor > >> 36366 1 ep_pol /usr/bin/nova-conductor > >> 36367 1 ep_pol /usr/bin/nova-conductor > >> 36368 1 ep_pol /usr/bin/nova-conductor > >> > >> If the nova-conductor was started with only one child, the problem was > not > >> happen. > >> Does this mean the connection/engine CAN NOT shared in these child > >> processes? > >> > >> Thanks. > > > > -- > > SQLAlchemy - > > The Python SQL Toolkit and Object Relational Mapper > > > > http://www.sqlalchemy.org/ > > > > To post example code, please provide an MCVE: Minimal, Complete, and > > Verifiable Example. See http://stackoverflow.com/help/mcve for a full > > description. > > --- > > You received this message because you are subscribed to the Google > Groups > > "sqlalchemy" group. > > To unsubscribe from this group and stop receiving emails from it, send > an > > email to [email protected] <javascript:>. > > To post to this group, send email to [email protected] > <javascript:>. > > Visit this group at https://groups.google.com/group/sqlalchemy. > > For more options, visit https://groups.google.com/d/optout. > -- SQLAlchemy - The Python SQL Toolkit and Object Relational Mapper http://www.sqlalchemy.org/ To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description. --- You received this message because you are subscribed to the Google Groups "sqlalchemy" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. Visit this group at https://groups.google.com/group/sqlalchemy. For more options, visit https://groups.google.com/d/optout.
