search

oracle / python-cx_Oracle

Python interface to Oracle Database now superseded by python-oracledb
https://oracle.github.io/python-cx_Oracle
Other
887 stars 361 forks source link

Paramiko / SSHTunnel hang #594

Open markfinn opened 2 years ago

markfinn commented 2 years ago

I'm on version 7.3, dealing with an issue similar to #158 that seems to have a similar solution.

When using a pure python ssh tunnel with a cx_oracle pool still hangs for me. Using an external tunnel is fine.

Based on the fix in #158 (releasing the GIL) I checked out what threads where waiting inside the cx_Oracle.so and think that the call to dpiStmt_close() inside cxoCursor_close() might also need the GIL released while waiting. Doing that seems to fix my hang. I don't really have any understanding of which dpi functions make external calls, so I don't know if this also should have included the dpiStmt_release() call.

static PyObject *cxoCursor_close(cxoCursor *cursor, PyObject *args)
{
+    int status;
     if (cxoCursor_isOpen(cursor) < 0)
         return NULL;
     Py_CLEAR(cursor->bindVariables);
     Py_CLEAR(cursor->fetchVariables);
     if (cursor->handle) {
-        if (dpiStmt_close(cursor->handle, NULL, 0) < 0)
+        Py_BEGIN_ALLOW_THREADS
+        status = dpiStmt_close(cursor->handle, NULL, 0);
+        Py_END_ALLOW_THREADS
+        if (status < 0)
             return cxoError_raiseAndReturnNull();
         dpiStmt_release(cursor->handle);
         cursor->handle = NULL;
    }
    cursor->isOpen = 0;

    Py_RETURN_NONE;
}
anthony-tuininga commented 2 years ago

Thanks, @markfinn. This documentation will tell you which ODPI-C calls may generate a round trip (and therefore should have the GIL released). I'll have this one fixed. I will also put the call to dpiStmt_release() inside the block where the GIL is released -- not because it is necessary but just because the GIL isn't needed anyway!

markfinn commented 2 years ago

Thanks! I assume my chances of getting this fixed in a 7.3.x are roughly zero? Some day I'll have the time to get to python 3... Some day.

anthony-tuininga commented 2 years ago

Hmm, the ODPI-C documentation I referenced suggests that dpiStmt_close() does NOT require a round-trip! That suggests there may be something more in play here. Do you have a sample that demonstrates the problem?

As for patching 7.3, yeah, that ship sailed a while ago! Well over 90% of the downloads are now for cx_Oracle 8. It looks like you have made your own patch anyway. Hopefully you can join the Python 3 party relatively soon anyway! ;-)

markfinn commented 2 years ago

Now that you say that, I can see it isn't in a round trip, but it is instead waiting on a lock. My guess is that that lock is held by a different thread that IS in a round trip. I hate to say it, but everything that can ever even wait on a non-python-managed lock should probably release the GIL.

Boiling down the code to something to reproduce it as a race condition might be really hard but I can reproduce the deadlock in about 3 seconds every time. Are there debug any capabilities that will show what locks are held or waiting by the layers under cx_Oracle?

Here are the threads involved. I would guess one of the two in "read" (cxoConnection_init or cxoCursor_execute) is holding a lock that blocks dpiStmt_close(), and that the the read can't complete because SSHTunnel needs the GIL. 

Thread 43 (Thread 0x7fffdfebb640 (LWP 1445928) "python"):
#0  futex_wait (private=0, expected=2, futex_word=0x555555f35520) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x555555f35520, private=0) at lowlevellock.c:50
#2  0x00007ffff39beec2 in lll_mutex_lock_optimized (mutex=0x555555f35520) at pthread_mutex_lock.c:49
#3  ___pthread_mutex_lock (mutex=0x555555f35520) at pthread_mutex_lock.c:89
#4  0x00007fffec64b08e in kpureq2 () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffec616c8d in OCIStmtPrepare2 () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007ffff2536a74 in dpiOci__stmtPrepare2 () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#7  0x00007ffff253eead in dpiStmt__prepare () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#8  0x00007ffff2525ab2 in dpiConn_prepareStmt () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#9  0x00007ffff25114db in cxoCursor_internalPrepare () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#10 0x00007ffff25144c6 in cxoCursor_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 42 (Thread 0x7fffe07fd640 (LWP 1445927) "python"):
#0  futex_wait (private=0, expected=2, futex_word=0x555555f35520) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x555555f35520, private=0) at lowlevellock.c:50
#2  0x00007ffff39beec2 in lll_mutex_lock_optimized (mutex=0x555555f35520) at pthread_mutex_lock.c:49
#3  ___pthread_mutex_lock (mutex=0x555555f35520) at pthread_mutex_lock.c:89
#4  0x00007fffec665b37 in kpugparm () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007ffff25345e8 in dpiOci__paramGet () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#6  0x00007ffff253dbb5 in dpiStmt__createQueryVars () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#7  0x00007ffff253e6b6 in dpiStmt__execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#8  0x00007ffff253f6ee in dpiStmt_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#9  0x00007ffff251452a in cxoCursor_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 41 (Thread 0x7fffe2c8e640 (LWP 1445926) "python"):
#0  futex_wait (private=0, expected=2, futex_word=0x555555f35520) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x555555f35520, private=0) at lowlevellock.c:50
#2  0x00007ffff39beec2 in lll_mutex_lock_optimized (mutex=0x555555f35520) at pthread_mutex_lock.c:49
#3  ___pthread_mutex_lock (mutex=0x555555f35520) at pthread_mutex_lock.c:89
#4  0x00007fffeef646d3 in kpuexec () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffeef5d9a9 in OCIStmtExecute () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007ffff2536610 in dpiOci__stmtExecute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#7  0x00007ffff253e590 in dpiStmt__execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#8  0x00007ffff253f6ee in dpiStmt_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#9  0x00007ffff251452a in cxoCursor_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 40 (Thread 0x7fffe3f12640 (LWP 1445925) "python"):
#0  __GI___libc_read (nbytes=8208, buf=0x555555f41586, fd=13) at ../sysdeps/unix/sysv/linux/read.c:26
#1  __GI___libc_read (fd=13, buf=0x555555f41586, nbytes=8208) at ../sysdeps/unix/sysv/linux/read.c:24
#2  0x00007fffeef7e160 in snttread () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#3  0x00007fffeef7d0f0 in nttfprd () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#4  0x00007fffeef78f50 in nsbasic_brc () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffeef6f9c4 in nioqrc () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007fffeef89b69 in ttcdrv () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#7  0x00007fffeef73b79 in nioqwa () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#8  0x00007fffeef5e200 in upirtrc () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#9  0x00007fffeef6a2f6 in kpurcsc () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#10 0x00007fffeef62439 in kpuexec () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#11 0x00007fffeef5d9a9 in OCIStmtExecute () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#12 0x00007ffff2536610 in dpiOci__stmtExecute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#13 0x00007ffff253e590 in dpiStmt__execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#14 0x00007ffff253f6ee in dpiStmt_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#15 0x00007ffff251452a in cxoCursor_execute () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 39 (Thread 0x7fffe35d0640 (LWP 1445924) "python"):
#0  futex_wait (private=0, expected=2, futex_word=0x555555f35520) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x555555f35520, private=0) at lowlevellock.c:50
#2  0x00007ffff39beec2 in lll_mutex_lock_optimized (mutex=0x555555f35520) at pthread_mutex_lock.c:49
#3  ___pthread_mutex_lock (mutex=0x555555f35520) at pthread_mutex_lock.c:89
#4  0x00007fffec64d327 in kpustmtrelease () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffec616e14 in OCIStmtRelease () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007ffff2536b74 in dpiOci__stmtRelease () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#7  0x00007ffff253ebd1 in dpiStmt__close () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#8  0x00007ffff253f3e6 in dpiStmt_close () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#9  0x00007ffff2512337 in cxoCursor_close () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 6 (Thread 0x7fffe9a65640 (LWP 1445849) "python"):
#0  futex_wait (private=0, expected=2, futex_word=0x555555ea5190) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x555555ea5190, private=0) at lowlevellock.c:50
#2  0x00007ffff39beec2 in lll_mutex_lock_optimized (mutex=0x555555ea5190) at pthread_mutex_lock.c:49
#3  ___pthread_mutex_lock (mutex=0x555555ea5190) at pthread_mutex_lock.c:89
#4  0x00007fffed4bfbd5 in kpuspreltopool () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffed4bd5b1 in kpuspsessionrelease () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007fffed2dfc92 in OCISessionRelease () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#7  0x00007ffff253525f in dpiOci__sessionRelease () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#8  0x00007ffff2521fa9 in dpiConn__close () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#9  0x00007ffff2523e61 in dpiConn_close () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#10 0x00007ffff251adb0 in cxoSessionPool_release () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so

Thread 5 (Thread 0x7fffea3a7640 (LWP 1445848) "python"):
#0  __GI___libc_read (nbytes=8208, buf=0x555556601876, fd=28) at ../sysdeps/unix/sysv/linux/read.c:26
#1  __GI___libc_read (fd=28, buf=0x555556601876, nbytes=8208) at ../sysdeps/unix/sysv/linux/read.c:24
#2  0x00007fffeef7e160 in snttread () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#3  0x00007fffec83887d in nttrd () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#4  0x00007fffec735485 in nsprecv () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#5  0x00007fffec7febfa in nscon () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#6  0x00007fffec6fb305 in nsdo () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#7  0x00007fffec7f7637 in nsbasic_rc () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#8  0x00007fffec6f7332 in nscall3 () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#9  0x00007fffec6f4a9b in nscall () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#10 0x00007fffec7893df in niotns () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#11 0x00007fffec794066 in osncon () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#12 0x00007fffec63ccfd in kpuadef () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#13 0x00007fffec623897 in upiini () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#14 0x00007fffec63b93c in kpuatch () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#15 0x00007fffed4c136a in kpuspextend () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#16 0x00007fffed4c36d3 in kpuspgetfreesession () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#17 0x00007fffed4c0433 in kpuspgetpooledsession () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#18 0x00007fffed4bc38d in kpuspsessionget () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#19 0x00007fffed2dfb4c in OCISessionGet () from /home/mark/data/fedex/splits3_project_stuff/localinstall/venv/oracle/instantclient_12_2/libclntsh.so
#20 0x00007ffff2534eb8 in dpiOci__sessionGet () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#21 0x00007ffff25232b3 in dpiConn__create () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#22 0x00007ffff25384d0 in dpiPool__acquireConnection () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#23 0x00007ffff2524342 in dpiConn_create () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so
#24 0x00007ffff250e997 in cxoConnection_init () from /home/mark/data/fedex/workspace/splits3/venv-20190401-pypy711/site-packages/cx_Oracle.pypy-41.so