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

On Sun, Aug 3, 2008 at 11:16 AM, Federico Di Gregorio <fog-NGVKUo/i/[email protected]> wrote:
> Hi Marco,
>
> if I remember correctly, SELECT FOR UPDATE place a lock on the selected
> rows so this _can_ be a deadlock problem.

Yes, SELECT FOR UPDATE do places a lock on the rows. In my testcase,
I'm basically performing over and over (using ab) the same sequence of
operations; they are, more or less:

SELECT FOR UPDATE to get the value of the counter
UPDATE to increase the counter

even though there are other tables involved they should not be
involved in this kind of problem.

And, transaction isolation level is SERIALIZABLE.

> 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.

Yes, I know; the version of psycopg is quite old, and I'm considering
a migration path; the problem is that I've to consider a migration
path for psycopg, python, Zope and PostgreSQL (altough, admitedly,
this one seems the less probelmatic to me).

> Which version of PostgreSQL are you
> using?

7.4.13 (on a debian etch, if it is useful).


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



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