BUG #4958: Stats collector hung on WaitForMultipleObjectsEx while attempting to recv a datagram

Luke Koops wrote:

Description: Stats collector hung on WaitForMultipleObjectsEx while
attempting to recv a datagram
Details:

While running a load test with 80 processes connected to postgres, of which
62 were generating load, the stats collector got blocked on
WaitForMultipleObjectsEx which was called with INFINITE timeout. The stack
trace for the hung thread follows:

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too. The process seems stuck for no good
reason. I wondered at the time if it could be a kernel issue. I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck. (I mean I couldn't find a way to do it on
Windows).

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Sat, Aug 1, 2009 at 01:49, Alvaro Herrera<alvherre@commandprompt.com> wrote:

Luke Koops wrote:

Description:        Stats collector hung on WaitForMultipleObjectsEx while
attempting to recv a datagram
Details:

While running a load test with 80 processes connected to postgres, of which
62 were generating load, the stats collector got blocked on
WaitForMultipleObjectsEx which was called with INFINITE timeout.  The stack
trace for the hung thread follows:

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too.  The process seems stuck for no good
reason.  I wondered at the time if it could be a kernel issue.  I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck.  (I mean I couldn't find a way to do it on
Windows).

I have seen this as well, but only in cases where there has been
broken firewall software or such things involved. I have seen a couple
of reports from the field though.

Anyway, this really is a should-never-happen thing. As soon as a new
packet is sent in, WaitForMultipleObjectsEx() should return right
away. And given that backends regularly send packets over, it
shouldn't be an issue even if we miss one...

To generate packets, you should be able to use for example "nc" that
is available as a win32 binary as well.

--
Magnus Hagander
Self: http://www.hagander.net/
Work: http://www.redpill-linpro.com/

Hi,

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too.  The process seems stuck for no good
reason.  I wondered at the time if it could be a kernel issue.  I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck.  (I mean I couldn't find a way to do it on
Windows).

I have seen this as well, but only in cases where there has been
broken firewall software or such things involved. I have seen a couple
of reports from the field though.

Anyway, this really is a should-never-happen thing. As soon as a new
packet is sent in, WaitForMultipleObjectsEx() should return right
away. And given that backends regularly send packets over, it
shouldn't be an issue even if we miss one...

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Regards,
Nikhils
--
http://www.enterprisedb.com

On Mon, Aug 3, 2009 at 15:47, Nikhil
Sontakke<nikhil.sontakke@enterprisedb.com> wrote:

Hi,

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too.  The process seems stuck for no good
reason.  I wondered at the time if it could be a kernel issue.  I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck.  (I mean I couldn't find a way to do it on
Windows).

I have seen this as well, but only in cases where there has been
broken firewall software or such things involved. I have seen a couple
of reports from the field though.

Anyway, this really is a should-never-happen thing. As soon as a new
packet is sent in, WaitForMultipleObjectsEx() should return right
away. And given that backends regularly send packets over, it
shouldn't be an issue even if we miss one...

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

From what I understand, none of you have an environment where you can
reliably reproduce this? That means it's going to be a PITA to try to
figure out if we're actually fixing anything :S

--
Magnus Hagander
Self: http://www.hagander.net/
Work: http://www.redpill-linpro.com/

Hi,

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too.  The process seems stuck for no good
reason.  I wondered at the time if it could be a kernel issue.  I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck.  (I mean I couldn't find a way to do it on
Windows).

I have seen this as well, but only in cases where there has been
broken firewall software or such things involved. I have seen a couple
of reports from the field though.

Anyway, this really is a should-never-happen thing. As soon as a new
packet is sent in, WaitForMultipleObjectsEx() should return right
away. And given that backends regularly send packets over, it
shouldn't be an issue even if we miss one...

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows and
it's socket logic behaves properly most of the times :), most of the
calls should come out within the first few tries, so changing 5 to an
infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

Regards,
Nikhils

From what I understand, none of you have an environment where you can
reliably reproduce this? That means it's going to be a PITA to try to
figure out if we're actually fixing anything :S

--
 Magnus Hagander
 Self: http://www.hagander.net/
 Work: http://www.redpill-linpro.com/

--
http://www.enterprisedb.com

On Mon, Aug 3, 2009 at 16:12, Nikhil
Sontakke<nikhil.sontakke@enterprisedb.com> wrote:

Hi,

ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

I have seen this problem too.  The process seems stuck for no good
reason.  I wondered at the time if it could be a kernel issue.  I
remember trying to send some data to the collector to verify whether
it'd wake up, but no luck.  (I mean I couldn't find a way to do it on
Windows).

I have seen this as well, but only in cases where there has been
broken firewall software or such things involved. I have seen a couple
of reports from the field though.

Anyway, this really is a should-never-happen thing. As soon as a new
packet is sent in, WaitForMultipleObjectsEx() should return right
away. And given that backends regularly send packets over, it
shouldn't be an issue even if we miss one...

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows and
it's socket logic behaves properly most of the times :), most of the
calls should come out within the first few tries, so changing 5 to an
infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

No, if we kill the stats collector that will destroy all sockets, and
when the new one starts all the sockets it operates on are fresh and
new. So it doesn't show that the flaw is in our code - but it also
doesn't show that it's in the kernel or runtime libraries.

--
Magnus Hagander
Self: http://www.hagander.net/
Work: http://www.redpill-linpro.com/

Hi,

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows and
it's socket logic behaves properly most of the times :), most of the
calls should come out within the first few tries, so changing 5 to an
infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

No, if we kill the stats collector that will destroy all sockets, and
when the new one starts all the sockets it operates on are fresh and
new. So it doesn't show that the flaw is in our code - but it also
doesn't show that it's in the kernel or runtime libraries.

AFAICS in the code, the inherited pgStatSock socket FD remains the
same across the restart of the stats collector process...

Regards,
Nikhils
--
http://www.enterprisedb.com

On Mon, Aug 3, 2009 at 16:20, Nikhil
Sontakke<nikhil.sontakke@enterprisedb.com> wrote:

Hi,

And this fact should lend credence to Alvaro's (as well as mine)
suspicions that it seems to be a Windows kernel issue.

As a consequence, Magnus I was wondering if having a loop similar to
the WRITE handling of waiting for a fixed timeout in a loop (rather
than an INFINITE call to WaitForMultipleObjectsEx) inside the
pgwin32_waitforsinglesocket() function will help for the READ case
too? I believe Teogor Sigaev had raised a similar concern a while back
about it:

http://www.nabble.com/-GENERAL--Stats-collector-frozen--td8569977i20.html

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows and
it's socket logic behaves properly most of the times :), most of the
calls should come out within the first few tries, so changing 5 to an
infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

No, if we kill the stats collector that will destroy all sockets, and
when the new one starts all the sockets it operates on are fresh and
new. So it doesn't show that the flaw is in our code - but it also
doesn't show that it's in the kernel or runtime libraries.

AFAICS in the code, the inherited pgStatSock socket FD remains the
same across the restart of the stats collector process...

Partially correct, I think.

Each backend has it's own handle on win32, since we use EXEC_BACKEND
(this includes the "utility processes" like the stats collector). When
we start the new one, we are going to use DuplicateHandle() in
save_backend_variables(). This will therefor get it a new handle, but
they are both pointing to the same kernel object. I don't know if
WaitForMultipleObjectsEx() is going to see these as two different
objects or not, but I think it does.

--
Magnus Hagander
Self: http://www.hagander.net/
Work: http://www.redpill-linpro.com/

Hi,

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change the
INIFINTE on line 318 of socket.c to a fixed value. That will loop down
to WSARecv() which should exit with WSAEWOULDBLOCK which will cause us
to do a short sleep and come back. But we'd have to change the limit
of 5 somehow then, since in theory we should wait forever. Maybe that
outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows and
it's socket logic behaves properly most of the times :), most of the
calls should come out within the first few tries, so changing 5 to an
infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

No, if we kill the stats collector that will destroy all sockets, and
when the new one starts all the sockets it operates on are fresh and
new. So it doesn't show that the flaw is in our code - but it also
doesn't show that it's in the kernel or runtime libraries.

AFAICS in the code, the inherited pgStatSock socket FD remains the
same across the restart of the stats collector process...

Partially correct, I think.

Each backend has it's own handle on win32, since we use EXEC_BACKEND
(this includes the "utility processes" like the stats collector). When
we start the new one, we are going to use DuplicateHandle() in
save_backend_variables(). This will therefor get it a new handle, but
they are both pointing to the same kernel object. I don't know if
WaitForMultipleObjectsEx() is going to see these as two different
objects or not, but I think it does.

Hmm, got it. Nothing like adding more confusion into the mix :)

Regards,
Nikhils
--
http://www.enterprisedb.com

There was no firewall in place, or more correctly the Windows Firewall is configured to be off. There is no other firewall installed on the system.

To get to this point in the code, the return value from WSARecv() was WSAEWOULDBLOCK. The socket is set for overlapped IO and is a datagram socket. MSDN documentation says that means there are too many outstanding overlapped IO requests. I don't know if "too many" applies to just this socket or to the system as a whole. The documentation isn't clear about how to handle the return code in this situation.

We don't need to know if this is a Kernel issue, a bug in winsock, or an undocumented behaviour. Regardless, it can be treated as a fault.

Knowing that it is possible for WaitForMultipleObjectsEx to lock up means that it is not safe to call with an INFINITE timeout. The workaround that's being discussed is beginning to look like the one at line 172 of socket.c. It's bad enough that there is a WSASend in pgwin32_waitforsinglesocket(). I doubt you also want to add a WSARecv. There should be a cleaner way to handle both of these situations.

I am planning to eventually kill the stats collector and see if that clears up the hanging issue, but I want to keep the system state in place for a bit longer in case there is some other diagnostic steps I should try. I've exhausted everything I could think of.

-Luke

-----Original Message-----
From: Nikhil Sontakke [mailto:nikhil.sontakke@enterprisedb.com]
Sent: Monday, August 03, 2009 10:38 AM
To: Magnus Hagander
Cc: Alvaro Herrera; Luke Koops; pgsql-bugs@postgresql.org
Subject: Re: [BUGS] BUG #4958: Stats collector hung on WaitForMultipleObjectsEx while attempting to recv a datagram

Hi,

Maybe. I'm unsure if it's enough to just try another
WaitForSingleObjectEx() on it, or if we need to actually issue a
WSARecv() on it as well. Maybe it would be enough to just change
the INIFINTE on line 318 of socket.c to a fixed value. That will
loop down to WSARecv() which should exit with WSAEWOULDBLOCK which
will cause us to do a short sleep and come back. But we'd have to
change the limit of 5 somehow then, since in theory we should wait
forever. Maybe that outer loop should just be a for(;;), what do you think?

Yes, line 318 seems to be a much better location to me. If Windows
and it's socket logic behaves properly most of the times :), most
of the calls should come out within the first few tries, so
changing 5 to an infinite loop shouldn't hurt those normal use cases in theory.

OTOH, I was wondering what if we kill the stats collector and on a
restart the socket communication resumes properly. Would that
conclusively mean that it is a flaw in our code?

No, if we kill the stats collector that will destroy all sockets,
and when the new one starts all the sockets it operates on are fresh
and new. So it doesn't show that the flaw is in our code - but it
also doesn't show that it's in the kernel or runtime libraries.

AFAICS in the code, the inherited pgStatSock socket FD remains the
same across the restart of the stats collector process...

Partially correct, I think.

Each backend has it's own handle on win32, since we use EXEC_BACKEND
(this includes the "utility processes" like the stats collector). When
we start the new one, we are going to use DuplicateHandle() in
save_backend_variables(). This will therefor get it a new handle, but
they are both pointing to the same kernel object. I don't know if
WaitForMultipleObjectsEx() is going to see these as two different
objects or not, but I think it does.

Hmm, got it. Nothing like adding more confusion into the mix :)

Regards,
Nikhils
--
http://www.enterprisedb.com

Hi,

Knowing that it is possible for WaitForMultipleObjectsEx to lock up means that it is not safe to call with an INFINITE timeout.  The workaround that's being discussed is beginning to look like the one at line 172 of socket.c.  It's bad enough that there is a WSASend in pgwin32_waitforsinglesocket().  I doubt you also want to add a WSARecv.  There should be a cleaner way to handle both of these situations.

The change at line 318 in socket.c and using an infinite loop there as
proposed by Magnus, makes much more sense IMO.

I am planning to eventually kill the stats collector and see if that clears up the hanging issue, but I want to keep the system state in place for a bit longer in case there is some other diagnostic steps I should try.  I've exhausted everything I could think of.

Yeah it will be interesting to see if the collector starts functioning
fine after the restart. That might hint that the kernel object
representing the socket is maybe fine but would not prove conclusively
that the issue is with PG code because the layer used by
WaitForMultipleObjectsEx might have issues too.

Regards,
Nikhils
--
http://www.enterprisedb.com

Yeah it will be interesting to see if the collector starts
functioning fine after the restart. That might hint that the
kernel object representing the socket is maybe fine but would
not prove conclusively that the issue is with PG code because
the layer used by WaitForMultipleObjectsEx might have issues too.

This morning I planned to verify that stats collection was still not working before killing the stats collector and allowing it to restart. I had a psql session open from the previous day, but I closed it and tried to start a new session. I log each session and wanted to start a new log.

Now, I am unable to start a new psql session. I get this error on the client side:
| psql: could not send startup packet: Connection reset by peer (0x00002746/10054)
|
and this error on the server side:
| 2009-08-06 10:48:59.542 EDT,LOG: could not receive data from client: No connection could be made because the target machine actively refused it.
| 2009-08-06 10:48:59.542 EDT,LOG: incomplete startup packet

I didn't find too much in the archives about this. It's what happens if you just connect to 5432 (with telnet for example) and then drop the connection.

Occasionally (3-6% of the time), I get this on the client side:
| C:\postgres\bin>psql
| psql: server closed the connection unexpectedly
| This probably means the server terminated abnormally
| before or while processing the request.
and this on the server side:
| 2009-08-06 11:16:27.933 EDT,LOG: could not receive data from client: No connection could be made because the target machine actively refused it.

When this sequence happens, I can see a backend postgres.exe process start up and then exit very quickly. Note the absence of the "incomplete startup package" message.

Could it be related to the stats collector problem? The stats collector on this system has been hung for over 6 weeks, so the timing of this problem is quite delayed.

I have windbg on this system along with the source and the symbols, so I could look for anything in the debugger.

-Luke

Luke Koops wrote:

When this sequence happens, I can see a backend postgres.exe process
start up and then exit very quickly. Note the absence of the
"incomplete startup package" message.

Could it be related to the stats collector problem? The stats
collector on this system has been hung for over 6 weeks, so the timing
of this problem is quite delayed.

Maybe you should try a network sniffer and see if you can spot anything
weird. I think Wireshark can decode the Postgres protocol.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Fri, Jul 31, 2009 at 10:59 AM, Luke Koops <luke.koops@entrust.com> wrote:

-- postgres.exe!mainCRTStartup --
ntoskrnl.exe!KiSwapContext+0x26
ntoskrnl.exe!KiSwapThread+0x2e5
ntoskrnl.exe!KeWaitForSingleObject+0x346
ntoskrnl.exe!KiSuspendThread+0x18
ntoskrnl.exe!KiDeliverApc+0x117
ntoskrnl.exe!KiSwapThread+0x300
ntoskrnl.exe!KeWaitForMultipleObjects+0x3d7
ntoskrnl.exe!ObpWaitForMultipleObjects+0x202
ntoskrnl.exe!NtWaitForMultipleObjects+0xe9
ntoskrnl.exe!KiFastCallEntry+0xfc
ntdll.dll!KiFastSystemCallRet
ntdll.dll!NtWaitForMultipleObjects+0xc
kernel32.dll!WaitForMultipleObjectsEx+0x11a
postgres.exe!pgwin32_waitforsinglesocket+0x1ed
postgres.exe!pgwin32_recv+0x90
postgres.exe!PgstatCollectorMain+0x17f
postgres.exe!SubPostmasterMain+0x33a
postgres.exe!main+0x168
postgres.exe!__tmainCRTStartup+0x10f
kernel32.dll!BaseProcessStart+0x23

We just had a customer hit a very similar problem on 9.1.3, running on
Windows Server 2008 SP2. They were able to extract the following
stack trace:

ntoskrnl.exe!KiSwapContext+0x7a
ntoskrnl.exe!KiCommitThreadWait+0x1d2
ntoskrnl.exe!KeWaitForMultipleObjects+0x271
ntoskrnl.exe!ObpWaitForMultipleObjects+0x294
ntoskrnl.exe!NtWaitForMultipleObjects+0xe5
ntoskrnl.exe!KiSystemServiceCopyEnd+0x13
ntdll.dll!ZwWaitForMultipleObjects+0xa
KERNELBASE.dll!WaitForMultipleObjectsEx+0xe8
kernel32.dll!WaitForMultipleObjectsExImplementation+0xb3
postgres.exe!pgwin32_waitforsinglesocket+0x26d
postgres.exe!pgwin32_recv+0xf0
postgres.exe!PgstatCollectorMain+0x1cc
postgres.exe!SubPostmasterMain+0x4c2
postgres.exe!main+0x1d0
postgres.exe!__tmainCRTStartup+0x11a
kernel32.dll!BaseThreadInitThunk+0xd
ntdll.dll!RtlUserThreadStart+0x1d

The customer finds that they can reproduce this on a variety of
systems under heavy load. However, removing the load doesn't fix the
problem; the system continues to spew pgstat wait timeout messages
into the logs. Autovacuum fails to DTRT due to lack of current stats
and things go downhill rapidly from there. Terminating the stats
collector process resolves the issue; the postmaster starts a new one
within 60 seconds and after that the pgstat wait timeout messages
cease and vacuuming consequently resumes.

Now, it looks to me like for this stack trace to happen,
PgstatCollectorMain() has got to call pgwin32_waitforsinglesocket (at
line 3002), and that function has to return true, so that got_data
gets set to true. Then PgstatCollectorMain() will call recv(), which
on Windows will really be pgwin32_recv, which will call
pgwin32_waitforsinglesocket, which must now hang. The fact that the
first pgwin32_waitforsinglesocket call returned true should mean that
the stats collector socket is ready for read, while the fact that the
second one did not return seems to imply that it's not ready for read,
close, or accept. So it almost looks like Windows can change its mind
about whether the socket is readable.

Or maybe we're telling it to change its mind. This sounds an awful
lot like something that could have been caused by the oversights fixed
in commit b85427f2276d02756b558c0024949305ea65aca5. Was there a
reason we didn't back-patch that?

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas@gmail.com> writes:

We just had a customer hit a very similar problem on 9.1.3, running on
Windows Server 2008 SP2. ...
The customer finds that they can reproduce this on a variety of
systems under heavy load.

Now, it looks to me like for this stack trace to happen,
PgstatCollectorMain() has got to call pgwin32_waitforsinglesocket (at
line 3002), and that function has to return true, so that got_data
gets set to true. Then PgstatCollectorMain() will call recv(), which
on Windows will really be pgwin32_recv, which will call
pgwin32_waitforsinglesocket, which must now hang. The fact that the
first pgwin32_waitforsinglesocket call returned true should mean that
the stats collector socket is ready for read, while the fact that the
second one did not return seems to imply that it's not ready for read,
close, or accept. So it almost looks like Windows can change its mind
about whether the socket is readable.

Or maybe we're telling it to change its mind. This sounds an awful
lot like something that could have been caused by the oversights fixed
in commit b85427f2276d02756b558c0024949305ea65aca5. Was there a
reason we didn't back-patch that?

Sure: it was unproven that that fixed anything at all, much less that it
was bug-free enough to be safe to backpatch. Neither of those things
has changed since May. If you want you can try making up a 9.1 with
those changes and giving it to this customer to see if it fixes their
problems --- but without some field testing of the sort, I'm pretty
hesitant to put it into back branches.

regards, tom lane

On Tue, Aug 7, 2012 at 2:22 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Robert Haas <robertmhaas@gmail.com> writes:

We just had a customer hit a very similar problem on 9.1.3, running on
Windows Server 2008 SP2. ...
The customer finds that they can reproduce this on a variety of
systems under heavy load.

Now, it looks to me like for this stack trace to happen,
PgstatCollectorMain() has got to call pgwin32_waitforsinglesocket (at
line 3002), and that function has to return true, so that got_data
gets set to true. Then PgstatCollectorMain() will call recv(), which
on Windows will really be pgwin32_recv, which will call
pgwin32_waitforsinglesocket, which must now hang. The fact that the
first pgwin32_waitforsinglesocket call returned true should mean that
the stats collector socket is ready for read, while the fact that the
second one did not return seems to imply that it's not ready for read,
close, or accept. So it almost looks like Windows can change its mind
about whether the socket is readable.

Or maybe we're telling it to change its mind. This sounds an awful
lot like something that could have been caused by the oversights fixed
in commit b85427f2276d02756b558c0024949305ea65aca5. Was there a
reason we didn't back-patch that?

Sure: it was unproven that that fixed anything at all, much less that it
was bug-free enough to be safe to backpatch. Neither of those things
has changed since May. If you want you can try making up a 9.1 with
those changes and giving it to this customer to see if it fixes their
problems --- but without some field testing of the sort, I'm pretty
hesitant to put it into back branches.

Well, we had the customer try out 9.2beta, and they were unable to
reproduce the issue there. Woo-hoo. Does that qualify as sufficient
evidence for back-patching this?

(BTW, I think commit 9b63e9869ffaa4d6d3e8bf45086a765d8f310f1c contains
a thinko in one of the comments: shouldn't "a crock of the first
water" be "a crock of the first order"?)

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Excerpts from Robert Haas's message of mar ago 21 14:54:28 -0400 2012:

(BTW, I think commit 9b63e9869ffaa4d6d3e8bf45086a765d8f310f1c contains
a thinko in one of the comments: shouldn't "a crock of the first
water" be "a crock of the first order"?)

I was interested by that phrase when I saw the commit, and as usual when
I see a phrase from Tom that looks like it might mean something
interesting, I looked it up. Apparently "of the first water" means "of
the highest quality" or "of the most extreme kind":
http://idioms.thefreedictionary.com/of+the+first+water
(Curiously enough, the example usage for the first sense in that site
mentions some gentleman by name of Tom.)

I have learned a few neat English language tricks by paying careful
attention to Tom's choice of words. There doesn't seem to be many
people in these lists that use English in just the same way.

--
Álvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Alvaro Herrera <alvherre@2ndquadrant.com> writes:

Excerpts from Robert Haas's message of mar ago 21 14:54:28 -0400 2012:

(BTW, I think commit 9b63e9869ffaa4d6d3e8bf45086a765d8f310f1c contains
a thinko in one of the comments: shouldn't "a crock of the first
water" be "a crock of the first order"?)

I was interested by that phrase when I saw the commit, and as usual when
I see a phrase from Tom that looks like it might mean something
interesting, I looked it up. Apparently "of the first water" means "of
the highest quality" or "of the most extreme kind":
http://idioms.thefreedictionary.com/of+the+first+water

Yeah, that was intentional not a typo. I think modern usage of this
phrase is largely confined to gemstones though, as in "diamond of the
first water".
http://www.phrases.org.uk/meanings/137550.html

Meanwhile, back at the ranch: I'm fine with applying that patch now that
it's had some field testing.

regards, tom lane

On Tue, Aug 21, 2012 at 4:30 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Meanwhile, back at the ranch: I'm fine with applying that patch now that
it's had some field testing.

Attached is a version that applies OK to 9.1, after resolving some
conflicts. Review appreciated. It wasn't exactly clear to me how to
handle the ereport/elog calls.

What to do pre-9.1 is a bit less clear to me, as the latch machinery
doesn't exist at all in those versions. Some of the fixes can
probably still be pulled out and applied, though.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company