Re: Advice on debugging what seems a deadlock with Zope and psycopg

Hi Marco,

if I remember correctly, SELECT FOR UPDATE place a lock on the selected
rows so this _can_ be a deadlock problem. At first sight it does not
seem a psycopg problem but the version you're using is so old I don't
remember if there were locking bugs. Which version of PostgreSQL are you
using?

federico

Il giorno dom, 03/08/2008 alle 09.40 +0200, Marco Bizzarri ha scritto:
> 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
> 
> 
-- 
Federico Di Gregorio                         http://people.initd.org/fog
Debian GNU/Linux Developer                                [email protected]
INIT.D Developer                                           fog-NGVKUo/i/[email protected]
 Questo autista me l'ha fatta a cotone!
                                     -- sedicenne palermitana in autobus

_______________________________________________
Psycopg mailing list
Psycopg-IAPFreCvJWPBWskQ1e/[email protected]
http://lists.initd.org/mailman/listinfo/psycopg

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (GNU/Linux)

iEYEABECAAYFAkiVd3QACgkQvcCgrgZGjeu0bwCfcUVGdNZq/CoFj8qm74b5bwBO
04oAn3IKwUAk7I+8wPMBCk/jW4dfYMNr
=jw+G
-----END PGP SIGNATURE-----