BUG #2712: could not fsync segment: Permission denied

in verbose mode, the log shows a little bit more:

2006-10-23 03:23:14 LOG: 42501: could not fsync segment 0 of relation
1663/3964774/6411190: Permission denied
2006-10-23 03:23:14 LOCATION: mdsync, md.c:785
2006-10-23 03:23:14 ERROR: XX000: storage sync failed on magnetic disk:
Permission denied
2006-10-23 03:23:14 LOCATION: smgrsync, smgr.c:888

- thomas

----- Original Message -----
From: "Thomas H" <me@alternize.com>
To: <pgsql-bugs@postgresql.org>
Sent: Monday, October 23, 2006 1:28 AM
Subject: [BUGS] BUG #2712: could not fsync segment: Permission denied

"Thomas H" <me@alternize.com> writes:

Operating system: windows 2003 standard
Description: could not fsync segment: Permission denied

The usual answer to this has been that you're running some
overenthusiastic antivirus software.

regards, tom lane

unfortunately not.
and this is not happening with 8.1

regards,
thomas

----- Original Message -----
From: "Tom Lane" <tgl@sss.pgh.pa.us>
To: "Thomas H" <me@alternize.com>
Cc: <pgsql-bugs@postgresql.org>
Sent: Monday, October 23, 2006 4:07 AM
Subject: Re: [BUGS] BUG #2712: could not fsync segment: Permission denied

there is defenitely something terribly wrong in the windows 8.2b1 regarding
file access/locking. 2nd total db lockup today due to file access locks (all
hold by postmaster):

{...}
2006-10-23 17:48:10 LOG: 42501: could not fsync segment 0 of relation
1663/3964774/6419608: Permission denied
2006-10-23 17:48:10 LOCATION: mdsync, md.c:785
2006-10-23 17:48:10 ERROR: XX000: storage sync failed on magnetic disk:
Permission denied
2006-10-23 17:48:10 LOCATION: smgrsync, smgr.c:888
2006-10-23 17:48:10 LOG: 00000: duration: 327.999 ms statement: SELECT
threads.*, first.login AS first_user, last.login AS last_user FROM
forum.threads JOIN users.users AS first ON first.id = threads.t_first_user
LEFT JOIN users.users AS last ON last.id = threads.t_last_user WHERE t_b_id
= 4 AND t_status_deleted = false ORDER BY t_status_sticky DESC, t_last_post
DESC
2006-10-23 17:48:10 LOCATION: exec_simple_query, postgres.c:1007
2006-10-23 17:48:14 LOG: 00000: could not rename file
"pg_xlog/00000001000000040000002E" to "pg_xlog/000000010000000400000037",
continuing to try
2006-10-23 17:48:14 LOCATION: pgrename, dirmod.c:142
2006-10-23 18:12:05 LOG: 00000: received fast shutdown request
2006-10-23 18:12:05 LOCATION: pmdie, postmaster.c:1903
2006-10-23 18:12:05 LOG: 00000: aborting any active transactions
2006-10-23 18:12:05 LOCATION: pmdie, postmaster.c:1910
2006-10-23 18:12:05 FATAL: 57P01: terminating connection due to
administrator command
2006-10-23 18:12:05 LOCATION: ProcessInterrupts, postgres.c:2465
2006-10-23 18:12:06 ERROR: XX000: could not rename file
"pg_xlog/00000001000000040000002E" to "pg_xlog/000000010000000400000037"
(initialization of log file 4, segment 55): A blocking operation was
interrupted by a call to WSACancelBlockingCall.
2006-10-23 18:12:06 LOCATION: InstallXLogFileSegment, xlog.c:2201
{...}

from 17:48:14 on pgsql didn't handle anymore queries until shutdown. as soon
as one restarts postmaster, the file locks are cleared up.

and no, there are no other file locking tools (av scanners and the such)
running - 8.1 on the same box (even on same partition) run fine.

regarnds,
- thomas

----- Original Message -----
From: "Thomas H." <me@alternize.com>
To: "Tom Lane" <tgl@sss.pgh.pa.us>
Cc: <pgsql-bugs@postgresql.org>
Sent: Monday, October 23, 2006 11:52 AM
Subject: Re: [BUGS] BUG #2712: could not fsync segment: Permission denied

The same problem exists in 8.1 too. See this thread

http://archives.postgresql.org/pgsql-bugs/2006-04/msg00177.php

Tom and Magnus tracked down a cause, but I don't think a fix was ever
implemented.

FWIW, we were bitten by the fsync problem which you noticed too.
Unfortunately we were never able to track down a cause (see the mailing
list archives). They are separate problems though.

Pete

"Thomas H." <me@alternize.com> 23.10.2006 18:21 >>>

there is defenitely something terribly wrong in the windows 8.2b1
regarding
file access/locking. 2nd total db lockup today due to file access locks
(all
hold by postmaster):

2006-10-23 17:48:10 LOCATION: exec_simple_query, postgres.c:1007
2006-10-23 17:48:14 LOG: 00000: could not rename file
"pg_xlog/00000001000000040000002E" to
"pg_xlog/000000010000000400000037", continuing to try

"Peter Brant" <Peter.Brant@wicourts.gov> writes:

The same problem exists in 8.1 too. See this thread
http://archives.postgresql.org/pgsql-bugs/2006-04/msg00177.php
Tom and Magnus tracked down a cause, but I don't think a fix was ever
implemented.

Thomas seems to have two different issues there: the "could not rename
file" problem on the pg_xlog file is probably explained by the mechanism
we identified back then (and I'm not sure why no fix has been
installed), but there is no known reason other than antivirus software
for the "could not fsync" problem.

As for fixing the problem we do understand: ISTM it's just an awful idea
for pgrename and pgunlink to be willing to loop forever. I think they
should time out and report the failure after some reasonable period
(say between 10 sec and a minute).

If we simply made that change, then the behavior when there's an idle
backend sitting on a filehandle for an old xlog segment would be that
checkpoints would fail at the MoveOfflineLogs stage, which would not
be fatal, but it'd be annoying. We'd probably want to further tweak
InstallXLogFileSegment so that rename failure isn't an ERROR, at least
not on Windows. (I think we could just make it return false, which'd
cause the caller to try to delete the xlog segment, which should work
even though rename doesn't.)

I'm not in a position to test this though. Magnus or Bruce?

regards, tom lane

The same problem exists in 8.1 too. See this thread

its only appearing in 8.2 here, i've just rechecked our logs...
is there any workaround? how did you get around that problem of having a
total lockdown?

thanks,
thomas

That might be one cause (or it might otherwise exacerbate the problem),
but it isn't the only cause. We weren't running anti-virus software and
neither is Thomas. Unfortunately with the last go around, we
collectively ran out of ideas before an underlying cause could be
identified.

Pete

Tom Lane <tgl@sss.pgh.pa.us> 23.10.2006 19:49 >>>

installed), but there is no known reason other than antivirus software
for the "could not fsync" problem.

Move to Linux. :-) In our case, everything but the database servers
were already Linux so it was an easy choice. Things have been rock
solid since then.

Once things get stuck, I don't think there is an alternative besides
"stop -m immediate". However, since the problem is caused by an idle
backend holding onto an old WAL segment, maybe having your middle
tier/connection pool close and reopen the connections to the database
every so often would function as a workaround. Somebody with more
knowledge of PG internals than I would have to define "every so often"
though (if the idea is viable at all).

Pete

"Thomas H." <me@alternize.com> 23.10.2006 20:00 >>>

is there any workaround? how did you get around that problem of having
a
total lockdown?

"Peter Brant" <Peter.Brant@wicourts.gov> writes:

FWIW, we were bitten by the fsync problem which you noticed too.
Unfortunately we were never able to track down a cause (see the mailing
list archives). They are separate problems though.

Actually, now that I look back in the archives, I think we had theorized
that the fsync errors come from attempting to fsync a file that's
already been deleted but some backend still has a reference to.
Apparently that leads to EACCES instead of ENOENT (which the code is
already prepared to expect).

http://archives.postgresql.org/pgsql-bugs/2006-04/msg00215.php

regards, tom lane

Actually, now that I look back in the archives, I think we had theorized
that the fsync errors come from attempting to fsync a file that's
already been deleted but some backend still has a reference to.
Apparently that leads to EACCES instead of ENOENT (which the code is
already prepared to expect).

with process explorer i can actually check which postgres.exe instance (in
all cases i've checked its just 1 instance, and always just 1 file) holds
the lock for the file in question. but will that help in determining why it
is still holding a reference?
the postgres instance that holds the lock eventually closes the filehandle
after some minutes. the process itself is not killed but continues
thereafter.

let me know if i can be of any assistance. since we do regurarly reindex one
table whose index size keeps growing despite of often vacuuming, the
fsync-problem happens almost 4-5 times per hour.

regards,
thomas

"Thomas H." <me@alternize.com> writes:

with process explorer i can actually check which postgres.exe instance (in
all cases i've checked its just 1 instance, and always just 1 file) holds
the lock for the file in question.

So which one is it?

the postgres instance that holds the lock eventually closes the filehandle
after some minutes. the process itself is not killed but continues
thereafter.

That sounds a bit like what I'd expect the bgwriter to do, but the
bgwriter is also the one trying to issue the fsync.

regards, tom lane

with process explorer i can actually check which postgres.exe instance
(in
all cases i've checked its just 1 instance, and always just 1 file) holds
the lock for the file in question.

So which one is it?

it's always one of the db-"slaves" and not "logger process", "stats
collector process" or "writer process":

right now its PID 4844 ("\BaseNamedObjects\pgident: postgres: db_outnow
outnow1 127.0.0.1(2122) idle") that tries to write
"D:\DB\PostgreSQL-8.2\data\base\3964774\6422331"

can i somehow check what object that file-OID belong(ed/s) to?

- thomas

"Thomas H." <me@alternize.com> writes:

right now its PID 4844 ("\BaseNamedObjects\pgident: postgres: db_outnow
outnow1 127.0.0.1(2122) idle") that tries to write
"D:\DB\PostgreSQL-8.2\data\base\3964774\6422331"

Do you actually mean it's trying to write that file? Or is it just
sitting there holding the open filehandle?

can i somehow check what object that file-OID belong(ed/s) to?

You can check in pg_class.relfilenode and pg_class.oid of that database
to see if you get a match. But our theory is that this table has been
deleted ...

regards, tom lane

"Thomas H." <me@alternize.com> writes:

right now its PID 4844 ("\BaseNamedObjects\pgident: postgres: db_outnow
outnow1 127.0.0.1(2122) idle") that tries to write
"D:\DB\PostgreSQL-8.2\data\base\3964774\6422331"

Do you actually mean it's trying to write that file? Or is it just
sitting there holding the open filehandle?

well, hard to tell :-)
according to the log-messages i would assume it is *trying* to write. but
the file in question isn't physically there anymore, it's just the open file
handle that keeps it from vanish totally - you do not have access to the
file (permission denied / access denied) if you for example try to read it
or its attributes in file explorer.

i've installed Filemon (http://www.sysinternals.com/Utilities/Filemon.html)
now. this gives more insight what happens to the file. in this case its file
6422806, the first error message appeared at 23:45:21, the last one at
23:45:26 (only short duration this time).

{....}
23:44:57 postgres.exe:1944 WRITE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS Offset: 16384 Length:
8192
23:44:57 postgres.exe:1944 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:44:57 postgres.exe:1944 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS Options: Open
Access: 00010080
23:44:57 postgres.exe:1944 QUERY INFORMATION
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
FileAttributeTagInformation
23:44:57 postgres.exe:1944 DELETE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:44:57 postgres.exe:1944 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:44:57 postgres.exe:1944 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806.1 NOT FOUND Options: Open
Access: 00010080
23:44:57 postgres.exe:5364 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:44:57 postgres.exe:2780 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:44:59 postgres.exe:6036 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:45:11 postgres.exe:5196 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:45:20 postgres.exe:1268 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:45:21 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:22 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:23 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:24 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:25 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:26 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F
23:45:26 postgres.exe:5428 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:45:26 postgres.exe:2200 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 SUCCESS
23:45:27 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 NOT FOUND Options: Open
Access: 0012019F

i have earlier log data for this file if needed, but at :45:27 was the last
entry. unfortunately i wasn't quick enough to find the blocking process in
processviewer, but i guess its pid 5196

can i somehow check what object that file-OID belong(ed/s) to?

You can check in pg_class.relfilenode and pg_class.oid of that database
to see if you get a match. But our theory is that this table has been
deleted ...

nothing there as assumed.

- thomas

"Thomas H." <me@alternize.com> writes:

Do you actually mean it's trying to write that file? Or is it just
sitting there holding the open filehandle?

well, hard to tell :-)
according to the log-messages i would assume it is *trying* to write.

The log messages you have don't make it clear which process is trying to
do the fsync, but I would expect it to be the bgwriter. (Possibly you
should modify log_line_prefix to include PID so we can tell a bit
better.)

regards, tom lane

The log messages you have don't make it clear which process is trying to
do the fsync, but I would expect it to be the bgwriter. (Possibly you
should modify log_line_prefix to include PID so we can tell a bit
better.)

you're right (as always :-)). its the "writer process" (pid 5196) that
outputs the error messages:

2006-10-24 00:09:09 [5196] ERROR: XX000: storage sync failed on magnetic
disk: Permission denied
2006-10-24 00:09:09 [5196] LOCATION: smgrsync, smgr.c:888
2006-10-24 00:09:10 [5196] LOG: 42501: could not fsync segment 0 of
relation 1663/3964774/6422947: Permission denied
2006-10-24 00:09:10 [5196] LOCATION: mdsync, md.c:785

and in this case, its process 5988 that keeps the file handle open (its
entry in pg_class is already deleted):

\BaseNamedObjects\pgident: postgres: db_outnow outnow1 127.0.0.1(2362) idle
D:\DB\PostgreSQL-8.2\data\base\3964774\6422947 (1 references, 1 handle)

... while pid 5196 constantly tries to open the file (for over 15min in this
case), until...

00:22:18 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422947 DELETE PEND Options: Open
Access: 0012019F
00:22:19 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422947 DELETE PEND Options: Open
Access: 0012019F
00:22:20 postgres.exe:5988 CLOSE
D:\DB\PostgreSQL-8.2\data\base\3964774\6422947 SUCCESS
00:22:20 postgres.exe:5196 OPEN
D:\DB\PostgreSQL-8.2\data\base\3964774\6422947 NOT FOUND Options: Open
Access: 0012019F

is that of any use? what more logging options would be interesting?

- thomas

"Thomas H." <me@alternize.com> writes:

i've installed Filemon (http://www.sysinternals.com/Utilities/Filemon.html)
now. this gives more insight what happens to the file.
...
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options: Open
Access: 0012019F

This is quite interesting, because it says that Filemon knows how to
distinguish a "delete pending" error from other errors. If we could
do that, then my prior worries about ignoring all EACCES errors would
go away. What's it looking at exactly?

regards, tom lane

i've installed Filemon
(http://www.sysinternals.com/Utilities/Filemon.html)
now. this gives more insight what happens to the file.
...
D:\DB\PostgreSQL-8.2\data\base\3964774\6422806 DELETE PEND Options:
Open
Access: 0012019F

This is quite interesting, because it says that Filemon knows
how to distinguish a "delete pending" error from other
errors. If we could do that, then my prior worries about
ignoring all EACCES errors would go away. What's it looking
at exactly?

filemon is a kernel mode filter driver. So it's looking at kernel-only
datastructures. AFAIK, there is no way to see that from userspace.

//Magnus