The latest buildfarm report from trout,
http://www.pgbuildfarm.org/cgi-bin/s...-16%2014:36:19
shows a failure mode that we've seen recently on snake, but not for a
long time on any non-Windows machines: the stats test fails with
symptoms suggesting that the stats counters aren't getting incremented.

Dave Page spotted the reason for this during the recent code sprint.
The stats collector is dying with

FATAL: could not read statistics message: A blocking operation was interrupted by a call to WSACancelBlockingCall.

If you look through the above-mentioned report's postmaster log, you'll
see several occurrences of this, indicating that the stats collector is
being restarted by the postmaster and then dying again.

After a bit of digging in our code, I realized that the above text is
probably the system's translation of WSAEINTR, which we equate EINTR
to, and thus that what's happening is just "recv() returned EINTR,
even though the socket had already tested read-ready". I'm not sure
whether that's considered normal behavior on Unixen but it is clearly
possible with our Win32 implementation of recv() --- any pending signal
will make it happen. So it seems an appropriate fix for the stats
collector is

len = recv(pgStatSock, (char *) &msg,
sizeof(PgStat_Msg), 0);
if (len < 0)
+ {
+ if (errno == EINTR)
+ continue;
ereport(ERROR,
(errcode_for_socket_access(),
errmsg("could not read statistics message: %m")));
+ }

and we had better look around to make sure all other calls of send()
and recv() treat EINTR as expected too.

But ... AFAICS the only signal that could plausibly be arriving at the
stats collector is SIGALRM from its own use of setitimer() to schedule
stats file writes. So it seems that this failure occurs when the alarm
fires between the select() and recv() calls; which is possible but it
seems a mighty narrow window. So I'm not 100% convinced that this is
the correct explanation of the problem --- we've seen snake fail this
way repeatedly, and here we have trout doing it three times within one
regression run. Can anyone think of a reason why the timing might fall
just so with a higher probability than one would expect? Perhaps
pgwin32_select() has got a problem that makes it not dispatch signals
as it seems to be trying to do?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

I wrote:
> But ... AFAICS the only signal that could plausibly be arriving at the
> stats collector is SIGALRM from its own use of setitimer() to schedule
> stats file writes. So it seems that this failure occurs when the alarm
> fires between the select() and recv() calls; which is possible but it
> seems a mighty narrow window. So I'm not 100% convinced that this is
> the correct explanation of the problem --- we've seen snake fail this
> way repeatedly, and here we have trout doing it three times within one
> regression run. Can anyone think of a reason why the timing might fall
> just so with a higher probability than one would expect? Perhaps
> pgwin32_select() has got a problem that makes it not dispatch signals
> as it seems to be trying to do?

Ah-hah, I see it. pgwin32_select() uses WaitForMultipleObjectsEx() with
an event for the socket read-ready plus an event for signal arrival.
It returns EINTR if the return code from WaitForMultipleObjectsEx shows
the signal-arrival event as fired. However, WaitForMultipleObjectsEx is
defined to return the number of the *first* event in the list that is
fired. This means that if the socket comes read-ready at the same time
the SIGALRM arrives, pgwin32_select() will ignore the signal, and it'll
be processed by the subsequent pgwin32_recv().

Now I don't know anything about the Windows scheduler, but I suppose it
gives processes time quantums like everybody else does. So "at the same
time" really means "within the same scheduler clock tick", which is not
so unlikely after all. In short, before the just-committed patch, the
Windows stats collector would fail if a stats message arrived during the
same clock tick that its SIGALRM timeout expired.

I think this explains not only the intermittent stats regression
failures, but the reports we've heard from Merlin and others about the
stats collector being unstable under load on Windows. The heavier the
load of stats messages, the more likely one is to arrive during the tick
when the timeout expires.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

> Ah-hah, I see it. pgwin32_select() uses WaitForMultipleObjectsEx() with
> an event for the socket read-ready plus an event for signal arrival.
> It returns EINTR if the return code from WaitForMultipleObjectsEx shows
> the signal-arrival event as fired. However, WaitForMultipleObjectsEx is
> defined to return the number of the *first* event in the list that is
> fired. This means that if the socket comes read-ready at the same time
> the SIGALRM arrives, pgwin32_select() will ignore the signal, and it'll
> be processed by the subsequent pgwin32_recv().
>
> Now I don't know anything about the Windows scheduler, but I suppose it
> gives processes time quantums like everybody else does. So "at the same
> time" really means "within the same scheduler clock tick", which is not
> so unlikely after all. In short, before the just-committed patch, the
> Windows stats collector would fail if a stats message arrived during the
> same clock tick that its SIGALRM timeout expired.
>
> I think this explains not only the intermittent stats regression
> failures, but the reports we've heard from Merlin and others about the
> stats collector being unstable under load on Windows. The heavier the
> load of stats messages, the more likely one is to arrive during the tick
> when the timeout expires.


There's a second problem in pgwin32_waitforsinglesocket() that may be
getting in your way.

Inside of pgwin32_waitforsingleselect(), we create a kernel
synchronization object (an Event) and associate that Event with the
socket. When the TCP/IP stack detects interesting traffic on the
socket, it signals the Event object (interesting in this case is READ,
WRITE, CLOSE, or ACCEPT, depending on the caller) and that wakes up the
call to WaitForMultipleObjectsEx().

That all works fine, unless you have two or more sockets in the backend
(the important part is that src/include/port/win32.h #define's select()
and other socket-related function - if you compile a piece of network
code that happens to #include port/win32.h, you'll get the pgwin32_xxx()
versions).

The problem is that, each time you go through
pgwin32_waitforsinglesocket(), you tie the *same* kernel object
(waitevent is static) to each socket. If you have more than one socket,
you'll tie each socket to the same kernel event. The kernel will signal
that Event whenever interesting traffic appears on *any* of the sockets.
The net effect is that, if you are waiting for activity on socket A, any
activity on socket B will also awaken WaitForMultipleObjects(). If you
then try to read from socket A, you'll get an "operation would block
error" because nothing happened on socket A.

The fix is pretty simple - just call WSAEventSelect( s, waitevent, 0 )
after WaitForMultipleObjectsEx() returns. That disassociates the socket
from the Event (it will get re-associated the next time
pgwin32_waitforsingleselect() is called.

I ran into this problem working on the PL/pgSQL debugger and I haven't
gotten around to posting a patch yet, sorry.

-- Korry (korryd@enterprisedb.com)

korry <korry@appx.com> writes:
> The problem is that, each time you go through
> pgwin32_waitforsinglesocket(), you tie the *same* kernel object
> (waitevent is static) to each socket.

> The fix is pretty simple - just call WSAEventSelect( s, waitevent, 0 )
> after WaitForMultipleObjectsEx() returns. That disassociates the socket
> from the Event (it will get re-associated the next time
> pgwin32_waitforsingleselect() is called.

Hmm. Presumably we don't do this a whole lot (use multiple sockets) or
we'd have noticed before. Perhaps better would be to keep an additional
static variable saying which socket the event is currently associated
to, and only issue the extra WSAEventSelect calls if we need to change
it. Or is WSAEventSelect fast enough that it doesn't matter?

Anyway, someone with a Windows machine needs to code and test this ...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Is anyone working on this?

---------------------------------------------------------------------------

Tom Lane wrote:
> korry <korry@appx.com> writes:
> > The problem is that, each time you go through
> > pgwin32_waitforsinglesocket(), you tie the *same* kernel object
> > (waitevent is static) to each socket.
>
> > The fix is pretty simple - just call WSAEventSelect( s, waitevent, 0 )
> > after WaitForMultipleObjectsEx() returns. That disassociates the socket
> > from the Event (it will get re-associated the next time
> > pgwin32_waitforsingleselect() is called.
>
> Hmm. Presumably we don't do this a whole lot (use multiple sockets) or
> we'd have noticed before. Perhaps better would be to keep an additional
> static variable saying which socket the event is currently associated
> to, and only issue the extra WSAEventSelect calls if we need to change
> it. Or is WSAEventSelect fast enough that it doesn't matter?
>
> Anyway, someone with a Windows machine needs to code and test this ...
>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster

--
Bruce Momjian bruce@momjian.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq