[BUGS] BUG #4958: Stats collector hung on WaitForMultipleObjectsEx while attempting to recv a datagram
The following bug has been logged online: Bug reference: 4958 Logged by: Luke Koops Email address: luke.ko...@entrust.com PostgreSQL version: 8.3.7 Operating system: Windows 2003 EE SP2 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: -- 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 Leading up to the hang, the DB was not under high load. The CPU was running at 80%, but less than a fifth of that was due to PostgreSQL. The underlying disk subsystems were routinely 90% idle. The txlogs are on a 4 disk RAID-10 array and the data is on a 5 disk RAID-5 array (15K RPM). This is a performance test environment for a product that will include PostgreSQL as an embedded database. I have the debug symbols for this build, and a process dump of the stats collector. I have have not been able to reproduce this problem. It seems to be relatively rare, so I'm lucky to have seen it before any of our customers. Even if the problem cannot be reproduced reliability, I think there is enough information that would help the community to make corrections in the code. After filtering out everything that is expected output, there was nothing informative in the postgres logs (from 24 hours prior to the hang until 8 hours after). We are accessing the DB over ODBC. All of our processes are running on the same server as PostgreSQL. The DB is 52GB in size, so I cannot targzupload it. I estimate that 4-8 GB of the size is due to the lack of autovacuum after stats collection stopped. I doubt that this issue is due to the schema or contents of the DB. I have verified, using TDIMon, that the back ends are sending the statistics. That was a bit redundant since the collector is clearly hung. Here are the settings in my system that differ from the defaults: logging_collector = on log_line_prefix = '%m,' autovacuum_naptime = 10s autovacuum_analyze_scale_factor = 0.05 autovacuum_vacuum_scale_factor = 0.1 autovacuum_vacuum_cost_limit = 1000 log_autovacuum_min_duration = 0 I have customized the vacuum rules for a few "hot" tables that are limited to 1 or a few rows, but are frequently updated (whenever the system does anything). Here is a dump of pg_autovacuum: vacrelid | enabled | vac_base_thresh | vac_scale_factor | anl_base_thresh | anl_scale_factor | vac_ cost_delay | vac_cost_limit | freeze_min_age | freeze_max_age --+-+-+--+-+ --+- ---+++ 16507 | t | 1 | -1 | 1 | -1 | 0 | 10 | -1 | -1 16511 | t | 1 | -1 | 1 | -1 | 0 | 10 | -1 | -1 16541 | t | 1 | -1 | 1 | -1 | 0 | 10 | -1 | -1 (3 rows) I created a new cluster on the same system and the stats collector worked just fine. -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #4958: Stats collector hung on WaitForMultipleObjectsEx while attempting to recv a datagram
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.sonta...@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 -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #4958: Stats collector hung on WaitForMultipleObjectsEx while attempting to recv a datagram
> 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 (0x2746/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 -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
[BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
The following bug has been logged online: Bug reference: 5038 Logged by: Luke Koops Email address: luke.ko...@entrust.com PostgreSQL version: 8.3.7 Operating system: Windows 2003 Server Enterprise Edition Description:WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving. Details: On my system, one of the WAL files is pending deletion. The handle is being held by one of the postgres backend processes, but that is another potential bug. At first, the unlink worked, and the .ready and .done files were deleted. But the WAL file still shows up in the pg_xlog directory listing. Note: the WAL file did get archived properly. There was no error reported at the time. When it comes time to recycle the log files, RemoveOldXLogFiles() calls ReadDir() to get the list of files, then it calls XLogArchiveCheckDone() which, if it cannot find a .done or a .ready file, calls XLogArchiveNotify(). XLogArchiveNotify() creates the .ready file again. This causes the archiver to call the archive command on the old WAL file that is pending deletion. The copy command will fail and all subsequent archive attempts will keep trying to copy the old WAL file that is pending deletion. At this point, none of the WAL files will get shipped and the pg_xlog folder will start filling up. Before calling XLogArchiveCheckDone(), RemoveOldXLogFiles() makes a number of tests to make sure the name is for a legitimate XLOG. This would be a good time to make sure the file is real, not pending deletion. That would prevent the creation of the .ready file and WAL archiving would continue to work. It might be a good idea to log something at the DEBUG level if a directory entry is encoutered that matches the naming conventions but is not a real file. You could probably reproduce this behaviour by changing the permissions on a WAL file, although you wouldn't be able to test a fix in the same way. I have not reliably reproduced the WAL file handle "leak" in the postgres back end. I believe may be related to statements timing out. My system currently has statement_timeout=1min, but that will be removed. I will report the "leak" when I have a better handle (no pun) on the situation. -Luke -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
> -Original Message- > From: Tom Lane [mailto:t...@sss.pgh.pa.us] > Sent: Monday, September 07, 2009 1:17 PM > To: Heikki Linnakangas > Cc: Luke Koops; pgsql-bugs@postgresql.org > Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion > in pg_xlog folder, this interferes with WAL archiving. > > Heikki Linnakangas writes: > > Perhaps we should try to close the old WAL file sooner. > > There is zero hope of making that work. What we probably > need to do is fix the code that scans pg_xlog so that it > ignores files that are pending deletion. (I assume there's > some way to find that out on > Windows.) On *nux systems, unlink removes the link from the directory. When other processes get a directory listing, the file will no longer be listed. On Windows, the file name continues to show up in directory listings. The file is in a state called pending deletion. Windows documentation doesn't give a specific test for this state. Perhaps you could use _access(). From http://support.microsoft.com/kb/159199 This file is in a state known as pending deletion. This file has been deleted, but there are still handles open to it. NTFS will wait until all handles to this file are closed before updating the index. If an attempt is made to access the file, however, NTFS will deny the attempt. Because the file is listed in the index, but is effectively deleted, you can see the file but you cannot access it. Windows NT returns an "Access Denied" error message when you attempt to manipulate the file. You are not able to view the permissions, the owner, or the contents of the file. The file does, however, show up in a DIR listing in File Manager and in Explorer. This occurs even though the user trying to access the file has permissions to the file. Even an administrator will be unable to take ownership of this file. > > regards, tom lane > -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
For those of you who are still looking at this, I tried to reproduce the issue
by holding one of the WAL files open with another program (just opened it with
the cygwin build of less.exe for windows). That didn't do the trick. It
prevented unlink or rename from working at all. I wrote a program (open.exe)
that opens the file using pgwin32_open() and passed in the same parameters that
postgres uses when opening a WAL file. That allowed the file to be renamed.
And, when deleted, the open file went into the pending deletion state.
I used open.exe to hold onto a WAL file that was going to be recycled. The
recycling worked, but what is going to happen down the road when the handle is
released, leaving a gap in the WAL file sequence. Or if it is not released,
when a backend tries to open the WAL file and does not have access to it?
When open.exe was holding onto a WAL file that was going to be deleted, the
deletion worked. The file went into the deletion pending state. The archive
status for the WAL file went through the .ready ==> .done ==> {no status file}
==> .ready sequence. At that point Postgres repeatedly tries to archive the
WAL file.
I reported earlier that I believe postgres leaked the file handle to the WAL
file. I don't believe that is the case. We have a process that only checks
data in the database for integrity. It is only reading. I think it opened the
WAL file initially, perhaps the backend had some maintenance work to do when
that session started and had to write something to the WAL and then never moved
on to a new one.
Now that I can reproduce the pending deletion case, I'm working on code to
detect it reliably and, hopefully, efficiently.
-Luke
> -Original Message-
> From: pgsql-bugs-ow...@postgresql.org
> [mailto:pgsql-bugs-ow...@postgresql.org] On Behalf Of Luke Koops
> Sent: Monday, September 07, 2009 4:30 PM
> To: 'Tom Lane'; Heikki Linnakangas
> Cc: pgsql-bugs@postgresql.org
> Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion
> in pg_xlog folder, this interferes with WAL archiving.
>
> > -Original Message-
> > From: Tom Lane [mailto:t...@sss.pgh.pa.us]
> > Sent: Monday, September 07, 2009 1:17 PM
> > To: Heikki Linnakangas
> > Cc: Luke Koops; pgsql-bugs@postgresql.org
> > Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion
> in pg_xlog
> > folder, this interferes with WAL archiving.
> >
> > Heikki Linnakangas writes:
> > > Perhaps we should try to close the old WAL file sooner.
> >
> > There is zero hope of making that work. What we probably
> need to do
> > is fix the code that scans pg_xlog so that it ignores files
> that are
> > pending deletion. (I assume there's some way to find that out on
> > Windows.)
> On *nux systems, unlink removes the link from the directory.
> When other processes get a directory listing, the file will
> no longer be listed. On Windows, the file name continues to
> show up in directory listings. The file is in a state called
> pending deletion. Windows documentation doesn't give a
> specific test for this state. Perhaps you could use _access().
>
> From http://support.microsoft.com/kb/159199
>
> This file is in a state known as pending deletion. This file
> has been deleted, but there are still handles open to it.
> NTFS will wait until all handles to this file are closed
> before updating the index. If an attempt is made to access
> the file, however, NTFS will deny the attempt. Because the
> file is listed in the index, but is effectively deleted, you
> can see the file but you cannot access it.
>
> Windows NT returns an "Access Denied" error message when you
> attempt to manipulate the file. You are not able to view the
> permissions, the owner, or the contents of the file. The file
> does, however, show up in a DIR listing in File Manager and
> in Explorer. This occurs even though the user trying to
> access the file has permissions to the file. Even an
> administrator will be unable to take ownership of this file.
>
> >
> > regards, tom lane
> >
>
> --
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs
>
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
Tom, If you first delete the file and it goes into deletion pending, then subsequent attempts to rename or delete will fail. Heikki is proposing that the file be renamed before it is first deleted. -Luke > -Original Message- > From: Tom Lane [mailto:t...@sss.pgh.pa.us] > Sent: Wednesday, September 09, 2009 3:06 PM > To: Heikki Linnakangas > Cc: Luke Koops; pgsql-bugs@postgresql.org > Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion > in pg_xlog folder, this interferes with WAL archiving. > > Heikki Linnakangas writes: > > One option is to rename the file before deleting it. > > I was under the impression that renaming would fail in the > same cases where deletion fails, ie something else holding > the file open ... > > regards, tom lane > -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
My case is that a backend was holding the file open. It was not some other unhelpful program. That's why I had to write a program that held the file open with the same flags that postgres uses (including FILE_SHARE_DELETE). We have a process that wrote to the DB, and then for many days it only read from the DB, so it didn't move on to another WAL file. -Luke > -Original Message- > From: Tom Lane [mailto:t...@sss.pgh.pa.us] > Sent: Wednesday, September 09, 2009 3:20 PM > To: Luke Koops > Cc: Heikki Linnakangas; pgsql-bugs@postgresql.org > Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion > in pg_xlog folder, this interferes with WAL archiving. > > Luke Koops writes: > > Heikki is proposing that the file be renamed before > it is first deleted. > > Indeed, and what I'm saying is that that will still fail if > some unhelpful program is holding the file open without > FILE_SHARE_DELETE. > Which is what I understood your case to be ... > > regards, tom lane > -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Re: [BUGS] BUG #5038: WAL file is pending deletion in pg_xlog folder, this interferes with WAL archiving.
I picked up the patch and verified both fixes on 8.3.7. In one test, Handles to two different WAL files were being held by two different backends. The WAL files were renamed to .deleted after I forced a switch xlog. Eventually the .deleted files disappeared. In one case the backend exited. In the other, the backend moved on to the latest WAL file. In another test, I opened a WAL file so that it could not be renamed or deleted. The appropriate error was logged and the .done file remained. The error is logged quite frequently. When released the WAL file it was soon deleted. If you get into a case where the rename works but the unlink fails (I don't see how this could happen in real life, except possibly for a race condition with AV software), you will have a situation where there is a .done file that does not match any WAL logs, and you will have a .deleted file that won't get cleaned up. I couldn't reproduce this, so I faked it by adding a .done file back into the archive_status folder after it was deleted. The orphaned .done file doesn't cause any trouble. It doesn't get cleaned up, it doesn't generate any log messages, and it doesn't interfere with WAL file recycling or removal (unlike the trouble that is caused by orphaned .ready files). The patch looks good. Thank-you, -Luke > -Original Message- > From: Heikki Linnakangas [mailto:heikki.linnakan...@enterprisedb.com] > Sent: Thursday, September 10, 2009 5:44 AM > Cc: Tom Lane; Luke Koops; pgsql-bugs@postgresql.org > Subject: Re: [BUGS] BUG #5038: WAL file is pending deletion > in pg_xlog folder, this interferes with WAL archiving. > > Heikki Linnakangas wrote: > > Tom Lane wrote: > >> Heikki Linnakangas writes: > >>> No, it's a backend that's holding the file open, with > FILE_SHARE_DELETE. > >> If that's the only case we care about covering, then > rename might be > >> enough. I was just wondering what it would take to solve the more > >> general problem of something holding it open with the > wrong flags at > >> the time we want to get rid of it. > > > > Yes, that's a separate problem, and I think we should > address that too. > > That's what I thought was going on in OP's case at first, > the patch I > > posted in my first reply should address that. > > > > I'll try to reproduce that case too, and verify that the > patch fixes it. > > Ok, I've committed a patch along those lines. The file is now > renamed before unlinking (on Windows), and the return code of > rename() and > unlink() is checked, so that we don't delete the .done file > if the WAL file deletion failed. This fixes both scenarios, > the one OP reported with another backend keeping the file > open, and the one where a different process keeps a file open > without FILE_SHARE_DELETE. > > I considered making failure to rename or delete a WARNING > instead of ERROR, so that RemoveOldXLogFiles() would still > clean up any other old WAL files. However, when a file is > recycled, we throw an error anyway if the rename fails in > InstallXLogFileSegment(), so it doesn't seem like it would > buy us much. > > BTW, it seems that errno is not set on Windows when rename > fails, but we still try to print the OS error message in > InstallXLogFileSegment(). > When I tested the case where another process is keeping the > file locked, for example, I got this: > > ERROR: could not rename file > "pg_xlog/000100010073" to > "pg_xlog/000100010092" (initialization of log > file 1, segment 146): No such file or directory > > even though the file clearly exists, it's just locked. I'm > not sure where errno is coming from in that case, and if we > should do something about that, but that exceeds my appetite > for fixing Windows issues right now. > > -- > Heikki Linnakangas > EnterpriseDB http://www.enterprisedb.com > -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
