Thread: Re: [BUGS] BUG #3242: FATAL: could not unlock semaphore: error code 298

On Fri, Apr 20, 2007 at 09:20:05AM +0200, Marcin Waldowski wrote:
> Hello.
> 
> I've made some analysis of PostgreSQL code. It looks like void 
> PGSemaphoreUnlock(PGSemaphore sema) from backend\port\win32_sema.c was 
> executed one time more than needed.

Certainly looks that way.

I've looked at the code there, and can't find a clear problem. One way it
could happen is if the actual PGSemaphoreUnlock() is called once more than
needed. 

CC:ing to hackers for this question:

Any chance that's happening? If this happens with SysV semaphores, will
they error out, or just say it was done and do nothing? (meaning should we
actuallyi be ignoring this error on windows?)

//Magnus

Magnus Hagander wrote:
> I've looked at the code there, and can't find a clear problem. One way it
> could happen is if the actual PGSemaphoreUnlock() is called once more than
> needed. 
>
> CC:ing to hackers for this question:
>
> Any chance that's happening? If this happens with SysV semaphores, will
> they error out, or just say it was done and do nothing? (meaning should we
> actuallyi be ignoring this error on windows?)
>   

Hmm, PGSemaphoreUnlock() actually ignore this error, only log that it 
happens. As I mentioned previously after it happens others connections 
were hung on update operations. What is strange we cannot reproduce this 
problem on Linux. But we can do this on Windows. What another 
information should we provide?

Regards, Marcin

On Fri, Apr 20, 2007 at 10:09:39AM +0200, Marcin Waldowski wrote:
> Magnus Hagander wrote:
> >I've looked at the code there, and can't find a clear problem. One way it
> >could happen is if the actual PGSemaphoreUnlock() is called once more than
> >needed. 
> >
> >CC:ing to hackers for this question:
> >
> >Any chance that's happening? If this happens with SysV semaphores, will
> >they error out, or just say it was done and do nothing? (meaning should we
> >actuallyi be ignoring this error on windows?)
> >  
> 
> Hmm, PGSemaphoreUnlock() actually ignore this error, only log that it 
> happens.

No. It does ereport(FATAL) which terminates the backend.


> As I mentioned previously after it happens others connections 
> were hung on update operations. What is strange we cannot reproduce this 
> problem on Linux. But we can do this on Windows. What another 
> information should we provide?

Doesn't the postmaster restart all other backends due to the FATAL error?
Are you saying that you can no longer make new connections to the server,
or is the problem coming from that the aplpication doesn't like that the
server kicked out all connections?

If you can produce a self-contained test-case, that would certainly make
debugging a lot easier. So if it's possible - but I realise that might not
be easy for a problem like this :-)

//Magnus

Magnus Hagander wrote:
>> Hmm, PGSemaphoreUnlock() actually ignore this error, only log that it 
>> happens.
>>     
>
> No. It does ereport(FATAL) which terminates the backend.
>
>   

Oh, now I see, sorry :) Indeed on this one connection we receive 
exception "FATAL: could not unlock semaphore", after that rollback 
failed because of IO error during write to connection and that was 
caused by "Connection reset by peer: socket write error".

>> As I mentioned previously after it happens others connections 
>> were hung on update operations. What is strange we cannot reproduce this 
>> problem on Linux. But we can do this on Windows. What another 
>> information should we provide?
>>     
>
> Doesn't the postmaster restart all other backends due to the FATAL error?
> Are you saying that you can no longer make new connections to the server,
> or is the problem coming from that the aplpication doesn't like that the
> server kicked out all connections?
>   

No, we are sure that he didn't do that. As I mentioned above one 
connection was terminated, but other ones were hung on update 
operations. In this state it was possible to create new connection from 
PGAdmin and do some select and update operations. In addition I can say 
that we use only read-commited transactions and all operations are based 
on prepared statemens which are reused.

> If you can produce a self-contained test-case, that would certainly make
> debugging a lot easier. So if it's possible - but I realise that might not
> be easy for a problem like this :-)
>   

Our test case is our application, but unfortunately I cannot send it to 
you. I will think about test case, but I need to find a time for writing 
it :( I can reproduce error and provide all information you need from 
PostgreSQL. Please instruct me what to do :)

Regards, Marcin

Marcin Waldowski wrote: 
>>
>> Doesn't the postmaster restart all other backends due to the FATAL 
>> error?
>> Are you saying that you can no longer make new connections to the 
>> server,
>> or is the problem coming from that the aplpication doesn't like that the
>> server kicked out all connections?
>>   
>
> No, we are sure that he didn't do that. As I mentioned above one 
> connection was terminated, but other ones were hung on update 
> operations. In this state it was possible to create new connection 
> from PGAdmin and do some select and update operations. In addition I 
> can say that we use only read-commited transactions and all operations 
> are based on prepared statemens which are reused.

It may mean that PGSemaphoreUnlock(PGSemaphore sema) was executed for 
unintended sema "object". That's why PGSemaphoreUnlock() for unintended 
sema "object" failed and PGSemaphoreUnlock() for intended sema "object" 
*never* happens. That would explain why other connections were hung on 
update operations.

I think it sounds quite reasonable to be one of possibilities ;)

Regards, Marcin

Magnus Hagander <magnus@hagander.net> writes:
> On Fri, Apr 20, 2007 at 09:20:05AM +0200, Marcin Waldowski wrote:
>>> I've looked at the code there, and can't find a clear problem. One way it
>>> could happen is if the actual PGSemaphoreUnlock() is called once more than
>>> needed. 

> CC:ing to hackers for this question:

> Any chance that's happening? If this happens with SysV semaphores, will
> they error out, or just say it was done and do nothing? (meaning should we
> actuallyi be ignoring this error on windows?)

How is it possible for a semaphore to be unlocked "too many times"?
It's supposed to be a running counter of the net V's minus P's, and
yes it had better be able to count higher than one.  Have we chosen
the wrong Windows primitive to implement this?
        regards, tom lane

Tom Lane wrote:
> Magnus Hagander <magnus@hagander.net> writes:
>> On Fri, Apr 20, 2007 at 09:20:05AM +0200, Marcin Waldowski wrote:
>>>> I've looked at the code there, and can't find a clear problem. One way it
>>>> could happen is if the actual PGSemaphoreUnlock() is called once more than
>>>> needed. 
> 
>> CC:ing to hackers for this question:
> 
>> Any chance that's happening? If this happens with SysV semaphores, will
>> they error out, or just say it was done and do nothing? (meaning should we
>> actuallyi be ignoring this error on windows?)
> 
> How is it possible for a semaphore to be unlocked "too many times"?
> It's supposed to be a running counter of the net V's minus P's, and
> yes it had better be able to count higher than one.  Have we chosen
> the wrong Windows primitive to implement this?

No, it's definitly the right primitive. But we're creating it with a max
count of 1. Not sure if that's right or not, too tired to think straight
about that right now, but here's a summary:

* Object is "signalled" when count > 0.

* We create with an initial count of 1.

* Calling WaitFor...() decreases the count. We call waitFor() in
PGsemaphoreLock(). If count reaches zero, waitfor() will block.

* Calling ReleaseSemaphore() increases the count. If count leaves zero
for 1, a blocking waitfor() is released. If count ends up >1 (or
whatever the limit is set to), we get said error. We call
ReleaseSemaphore() in PGSemaphoreUnlock().


So basically this says we've called PGSemaphoreUnlock() more times than
we've called PGSemaphoreLock().


Should we be creating it with a higher maximum value, and that's it? (it
sounds like it, but I'm not entirely sure)

//Magnus

Magnus Hagander <magnus@hagander.net> writes:
> Tom Lane wrote:
>> How is it possible for a semaphore to be unlocked "too many times"?
>> It's supposed to be a running counter of the net V's minus P's, and
>> yes it had better be able to count higher than one.  Have we chosen
>> the wrong Windows primitive to implement this?

> No, it's definitly the right primitive. But we're creating it with a max
> count of 1.

That's definitely wrong.  There are at least three reasons for a PG
process's semaphore to be signaled (heavyweight lock release, LWLock
release, pin count waiter), and at least two of them can occur
concurrently (eg, if deadlock checker fires, it will need to take
LWLocks, but there's nothing saying that the original lock won't be
released while it waits for an LWLock).

The effective max count on Unixen is typically in the thousands,
and I'd suggest the same on Windows unless there's some efficiency
reason to keep it small (in which case, maybe ten would do).

I'm astonished that we've not seen this reported before.  Has the
Windows sema code always been like that?
        regards, tom lane

Tom Lane wrote:
> Magnus Hagander <magnus@hagander.net> writes:
>> Tom Lane wrote:
>>> How is it possible for a semaphore to be unlocked "too many times"?
>>> It's supposed to be a running counter of the net V's minus P's, and
>>> yes it had better be able to count higher than one.  Have we chosen
>>> the wrong Windows primitive to implement this?
> 
>> No, it's definitly the right primitive. But we're creating it with a max
>> count of 1.
> 
> That's definitely wrong.  There are at least three reasons for a PG
> process's semaphore to be signaled (heavyweight lock release, LWLock
> release, pin count waiter), and at least two of them can occur
> concurrently (eg, if deadlock checker fires, it will need to take
> LWLocks, but there's nothing saying that the original lock won't be
> released while it waits for an LWLock).
> 
> The effective max count on Unixen is typically in the thousands,
> and I'd suggest the same on Windows unless there's some efficiency
> reason to keep it small (in which case, maybe ten would do).

AFAIK there's no problem with huge numbers (it takes an int32, and the
documentation says nothing about a limit - I'm sure it's just a 32-bit
counter in the kernel). I'll give that a shot.

Marcin - can you test a source patch? Or should I try to build you a
binary for testing? It'd be good if you can confirm that it works before
we commit anything, I think.


> I'm astonished that we've not seen this reported before.  Has the
> Windows sema code always been like that?

It could be an 8.2 problem, actually, since we had new semaphore code
there.  Looking at

http://developer.postgresql.org/cvsweb.cgi/pgsql/src/backend/port/win32/Attic/sema.c?rev=1.13;content-type=text%2Fx-cvsweb-markup,
it looks like we may have used a *semaphore* with just one as top, but
then kept a counter in userspace as well... (Haven't looked through the
details of the code, but it looks that way from a casual view)

//Magnus

Magnus Hagander wrote:
>>
>> The effective max count on Unixen is typically in the thousands,
>> and I'd suggest the same on Windows unless there's some efficiency
>> reason to keep it small (in which case, maybe ten would do).
>>     
>
> AFAIK there's no problem with huge numbers (it takes an int32, and the
> documentation says nothing about a limit - I'm sure it's just a 32-bit
> counter in the kernel). I'll give that a shot.
>
>   

Linux manpage suggests local max is 32767, so that's probably a good 
value to try.

cheers

andrew

Magnus Hagander wrote:
> Tom Lane wrote:
>   
>> Magnus Hagander <magnus@hagander.net> writes:
>>     
>>> No, it's definitly the right primitive. But we're creating it with a max
>>> count of 1.
>>>       
>> That's definitely wrong.  There are at least three reasons for a PG
>> process's semaphore to be signaled (heavyweight lock release, LWLock
>> release, pin count waiter), and at least two of them can occur
>> concurrently (eg, if deadlock checker fires, it will need to take
>> LWLocks, but there's nothing saying that the original lock won't be
>> released while it waits for an LWLock).
>>
>> The effective max count on Unixen is typically in the thousands,
>> and I'd suggest the same on Windows unless there's some efficiency
>> reason to keep it small (in which case, maybe ten would do).
>>     
>
> AFAIK there's no problem with huge numbers (it takes an int32, and the
> documentation says nothing about a limit - I'm sure it's just a 32-bit
> counter in the kernel). I'll give that a shot.
>   

Magnus, Tom, thank you for finding what causes the problem :) I hope 
that was also a reason why other transactions were hung (because that is 
a prior, I think).

> Marcin - can you test a source patch? Or should I try to build you a
> binary for testing? It'd be good if you can confirm that it works before
> we commit anything, I think.
>   

Of course I will check fix :) I will be able to do tests on monday. I 
think source path should be enought, despite I've newer build PostgreSQL 
on Windows (I definitely should try). If i have problems then I will ask 
you for binary.

Regards, Marcin

Marcin Waldowski wrote:
> Magnus Hagander wrote:
>> Tom Lane wrote:
>>
>>> Magnus Hagander <magnus@hagander.net> writes:
>>>
>>>> No, it's definitly the right primitive. But we're creating it with a
>>>> max
>>>> count of 1.
>>>>
>>> That's definitely wrong.  There are at least three reasons for a PG
>>> process's semaphore to be signaled (heavyweight lock release, LWLock
>>> release, pin count waiter), and at least two of them can occur
>>> concurrently (eg, if deadlock checker fires, it will need to take
>>> LWLocks, but there's nothing saying that the original lock won't be
>>> released while it waits for an LWLock).
>>>
>>> The effective max count on Unixen is typically in the thousands,
>>> and I'd suggest the same on Windows unless there's some efficiency
>>> reason to keep it small (in which case, maybe ten would do).
>>>
>>
>> AFAIK there's no problem with huge numbers (it takes an int32, and the
>> documentation says nothing about a limit - I'm sure it's just a 32-bit
>> counter in the kernel). I'll give that a shot.
>>
>
> Magnus, Tom, thank you for finding what causes the problem :) I hope
> that was also a reason why other transactions were hung (because that is
> a prior, I think).
>
>> Marcin - can you test a source patch? Or should I try to build you a
>> binary for testing? It'd be good if you can confirm that it works before
>> we commit anything, I think.
>>
>
> Of course I will check fix :) I will be able to do tests on monday. I
> think source path should be enought, despite I've newer build PostgreSQL
> on Windows (I definitely should try). If i have problems then I will ask
> you for binary.

Great, please try the attached trivial patch.

//Magnus
Index: src/backend/port/win32_sema.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/port/win32_sema.c,v
retrieving revision 1.4
diff -c -r1.4 win32_sema.c
*** src/backend/port/win32_sema.c    5 Jan 2007 22:19:35 -0000    1.4
--- src/backend/port/win32_sema.c    22 Apr 2007 18:19:13 -0000
***************
*** 82,88 ****
      sec_attrs.bInheritHandle = TRUE;

      /* We don't need a named semaphore */
!     cur_handle = CreateSemaphore(&sec_attrs, 1, 1, NULL);
      if (cur_handle)
      {
          /* Successfully done */
--- 82,88 ----
      sec_attrs.bInheritHandle = TRUE;

      /* We don't need a named semaphore */
!     cur_handle = CreateSemaphore(&sec_attrs, 1, 32767, NULL);
      if (cur_handle)
      {
          /* Successfully done */