Advice on debugging what seems a deadlock with Zope and psycopg

Hi all.

I'm asking advice on something which can seems a little of archeology,
here. In particulare, I have and application:

- running on Zope 2.8.8
- python2.3
- psycopg 1.1.21

After got some reports of occasional "freezes" under load of the
server, I set up a little testbed with ab, in order to
check if I was able to reproduce the problem.

The problem was so nice to show quickly. Zope was frozen, with all his
threads waiting.

Now, I followed the recipe to attach gdb to a running Zope; I can see
five threads right now:


(gdb) info threads
  5 Thread 0xb5b2fb90 (LWP 8935)  0xffffe410 in __kernel_vsyscall ()
  4 Thread 0xb5328b90 (LWP 8936)  0xffffe410 in __kernel_vsyscall ()
  3 Thread 0xb4b27b90 (LWP 8937)  0xffffe410 in __kernel_vsyscall ()
  2 Thread 0xb4326b90 (LWP 8938)  0xffffe410 in __kernel_vsyscall ()
  1 Thread 0xb7d518c0 (LWP 8922)  0xffffe410 in __kernel_vsyscall ()


and this is the backtrace for each of them:

(gdb) thread 1
[Switching to thread 1 (Thread 0xb7d518c0 (LWP 8922))]#0  0xffffe410
in __kernel_vsyscall ()
(gdb) bt 7
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7ed9d05 in sem_wait@@GLIBC_2.1 () from /lib/i686/cmov/libpthread.so.0
#2  0x080d884d in PyThread_acquire_lock ()
#3  0x080aec0d in PyEval_RestoreThread ()
#4  0xb7752c63 in ?? () from /usr/lib/python2.3/lib-dynload/select.so
#5  0x081331b0 in ?? ()
#6  0xbfd590b8 in ?? ()

(gdb) thread 2
[Switching to thread 2 (Thread 0xb4326b90 (LWP 8938))]#0  0xffffe410
in __kernel_vsyscall ()
(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7e1eae7 in poll () from /lib/i686/cmov/libc.so.6
#2  0xb7882c7f in ?? () from /usr/lib/libpq.so.5
#3  0xb4322abc in ?? ()
#4  0x00000001 in ?? ()
#5  0xffffffff in ?? ()
#6  0x00000001 in ?? ()
#7  0xb4322abc in ?? ()
#8  0x00000000 in ?? ()


(gdb) thread 3
[Switching to thread 3 (Thread 0xb4b27b90 (LWP 8937))]#0  0xffffe410
in __kernel_vsyscall ()
(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7ed9d05 in sem_wait@@GLIBC_2.1 () from /lib/i686/cmov/libpthread.so.0
#2  0x080d884d in PyThread_acquire_lock ()
#3  0x080aec0d in PyEval_RestoreThread ()
#4  0x080dc2a7 in ?? ()
#5  0x09db99e8 in ?? ()
#6  0x00000001 in ?? ()
#7  0xb4b2390c in ?? ()


(gdb) thread 4
[Switching to thread 4 (Thread 0xb5328b90 (LWP 8936))]#0  0xffffe410
in __kernel_vsyscall ()
(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7e1eae7 in poll () from /lib/i686/cmov/libc.so.6
#2  0xb7882c7f in ?? () from /usr/lib/libpq.so.5
#3  0xb5324e7c in ?? ()
#4  0x00000001 in ?? ()
#5  0xffffffff in ?? ()


(gdb) thread 5
[Switching to thread 5 (Thread 0xb5b2fb90 (LWP 8935))]#0  0xffffe410
in __kernel_vsyscall ()
(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7eda589 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7ed5ba6 in _L_lock_95 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7ed558a in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4  0xb789a66f in dispose_pgconn (self=0x9ef7b60) at ././cursor.c:122
#5  0xb789ab61 in psyco_curs_destroy (self=0x9ef7b60) at ././cursor.c:195
#6  0x08078eef in ?? ()
#7  0x09ef7b60 in ?? ()
#8  0x014fb664 in ?? ()


I also did a ps axf | grep postgres, and here is the result:

 3446 ?        S      0:00 /usr/lib/postgresql/7.4/bin/postmaster -D
/var/lib/postgresql/7.4/main
 3449 ?        S      0:02  \_ postgres: stats buffer process
 3450 ?        S      0:09  |   \_ postgres: stats collector process
 8939 ?        S      0:00  \_ postgres: postgres PAFlow-emmebi
127.0.0.1 idle in transaction
 8940 ?        S      0:00  \_ postgres: postgres PAFlow-emmebi
127.0.0.1 SELECT waiting
 8941 ?        S      0:00  \_ postgres: postgres PAFlow-emmebi
127.0.0.1 idle in transaction
 8942 ?        S      0:00  \_ postgres: postgres PAFlow-emmebi
127.0.0.1 SELECT waiting

If that can be useful, here is a result of SELECT * from pg_stat_activity:

SELECT * from pg_stat_activity ;
  datid  |    datname    | procpid | usesysid | usename  |
current_query     |          query_start
---------+---------------+---------+----------+----------+-----------------------+-------------------------------
 4924008 | PAFlow-emmebi |    8939 |        1 | postgres | <IDLE> in
transaction | 2008-08-03 09:32:10.224879+02
 4924008 | PAFlow-emmebi |    8940 |        1 | postgres | SELECT *
        FROM numeroprotocollo
        WHERE
            anno = 2008
        AND
            aoo = 'Demos'
        AND
            ambito = 'esterno'
        FOR UPDATE              | 2008-08-03 09:32:10.122449+02
 4924008 | PAFlow-emmebi |    8941 |        1 | postgres | <IDLE> in
transaction | 2008-08-03 09:32:10.005701+02
 4924008 | PAFlow-emmebi |    8942 |        1 | postgres | SELECT *
        FROM numeroprotocollo
        WHERE
            anno = 2008
        AND
            aoo = 'Demos'
        AND
            ambito = 'esterno'
        FOR UPDATE              | 2008-08-03 09:32:10.236836+02
 4924008 | PAFlow-emmebi |    8969 |        1 | postgres | <IDLE>
          | 2008-08-03 09:36:18.575381+02
(5 righe)


(I hope it is still readable).

Now, my question is: is this caused by some (unforgivable ;) ) mistake
I did in developing my application?


I would appreciate any help into inspecting this problem.

Thank you all in advance.

Regards
Marco


-- 
Marco Bizzarri
http://iliveinpisa.blogspot.com/