rmtree() failure on Windows
Houston, we have a problem.
Shown below is an extract from the traces of make installcheck in
contrib. It is decorated with some extra traces I built into
src/port/dirmod.c::rmtree(). It shows quite reproducible failure of
rmtree(), mostly at the rmdir calls, but even more worryingly there are
consistent unlink failures also.
At this stage I have no idea how to go about fixing it.
cheers
andrew
../../src/test/regress/pg_regress init int2 int4 int8 float4 float8 cash
oid timestamp timestamptz time timetz date interval macaddr inet cidr
text varchar char bytea bit varbit numeric
============== dropping database "regression" ==============
DROP DATABASE
../../src/test/regress/pg_regress cube
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/55646":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/55646"
../../src/test/regress/pg_regress dblink
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/69688":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/69688"
../../src/test/regress/pg_regress earthdistance
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72850":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72850"
../../src/test/regress/pg_regress _int
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72914":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72914"
../../src/test/regress/pg_regress ltree
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not unlink
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72987/80059":
No such file or directory
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/72987"
../../src/test/regress/pg_regress pg_trgm
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/80061":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/80061"
../../src/test/regress/pg_regress init md5 sha1 hmac-md5 hmac-sha1
blowfish rijndael crypt-des crypt-md5 crypt-blowfish crypt-xdes
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/82213":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/82213"
../../src/test/regress/pg_regress rtree_gist
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not unlink
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/83241/83277":
No such file or directory
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/83241"
../../src/test/regress/pg_regress seg
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not unlink
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/83283/86678":
No such file or directory
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/83283"
../../src/test/regress/pg_regress tablefunc
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/90065":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/90065"
../../src/test/regress/pg_regress tsearch
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/92694":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/92694"
../../src/test/regress/pg_regress tsearch2
============== dropping database "regression" ==============
DROP DATABASE
WARNING: rmtree could not rmdir
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/92782":
Directory not empty
WARNING: could not remove database directory
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/92782"
Andrew Dunstan <andrew@dunslane.net> writes:
Shown below is an extract from the traces of make installcheck in
contrib. It is decorated with some extra traces I built into
src/port/dirmod.c::rmtree(). It shows quite reproducible failure of
rmtree(), mostly at the rmdir calls, but even more worryingly there are
consistent unlink failures also.
I kinda suspect that what you are looking at is a problem with the
delayed-unlinking feature that we built to cope with Windows' inability
to unlink open files, ie, it's being a little too slow to do the
unlinks. Would you refresh my memory about exactly where and when the
unlink happens if the initial try fails?
regards, tom lane
Tom Lane wrote:
Andrew Dunstan <andrew@dunslane.net> writes:
Shown below is an extract from the traces of make installcheck in
contrib. It is decorated with some extra traces I built into
src/port/dirmod.c::rmtree(). It shows quite reproducible failure of
rmtree(), mostly at the rmdir calls, but even more worryingly there are
consistent unlink failures also.I kinda suspect that what you are looking at is a problem with the
delayed-unlinking feature that we built to cope with Windows' inability
to unlink open files, ie, it's being a little too slow to do the
unlinks. Would you refresh my memory about exactly where and when the
unlink happens if the initial try fails?
Same file, although Bruce says that looping code is now redundant, as we
open files in a way that allows unlinking even if they are open.
cheers
andrew
Andrew Dunstan <andrew@dunslane.net> writes:
Tom Lane wrote:
I kinda suspect that what you are looking at is a problem with the
delayed-unlinking feature that we built to cope with Windows' inability
to unlink open files, ie, it's being a little too slow to do the
unlinks. Would you refresh my memory about exactly where and when the
unlink happens if the initial try fails?Same file, although Bruce says that looping code is now redundant, as we
open files in a way that allows unlinking even if they are open.
Does the problem go away if you insert a "sleep 1" at the bottom of the
pg_regress script? I have been thinking of proposing that anyway,
because on some platforms I consistently get "database removal failed:
database "regression" is being accessed by other users" failures from
the contrib regression tests because the previous backend doesn't get
enough time to quit before the next test tries to drop and recreate the
regression database. I think what you are looking at may be some
variant of the same issue, ie, old backend still running.
regards, tom lane
Tom Lane schrieb:
Andrew Dunstan <andrew@dunslane.net> writes:
Shown below is an extract from the traces of make installcheck in
contrib. It is decorated with some extra traces I built into
src/port/dirmod.c::rmtree(). It shows quite reproducible failure of
rmtree(), mostly at the rmdir calls, but even more worryingly there are
consistent unlink failures also.I kinda suspect that what you are looking at is a problem with the
delayed-unlinking feature that we built to cope with Windows' inability
to unlink open files, ie, it's being a little too slow to do the
unlinks. Would you refresh my memory about exactly where and when the
unlink happens if the initial try fails?
You can have a look into the cygwin sources how we do that :)
kinda problematic.
http://sources.redhat.com/cgi-bin/cvsweb.cgi/winsup/cygwin/delqueue.cc?cvsroot=uberbaum
http://sources.redhat.com/cgi-bin/cvsweb.cgi/winsup/cygwin/syscalls.cc?cvsroot=uberbaum
in short:
if the return status of DeleteFileA() is ERROR_SHARING_VIOLATION, defer
deletion until the end of the process.
but win95 reports ERROR_ACCESS_DENIED and not ERROR_SHARING_VIOLATION as
NT does.
--
Reini Urban
http://xarch.tu-graz.ac.at/home/rurban/
Andrew Dunstan <andrew@dunslane.net> writes:
Another data point - when rmdir() fails it fails quickly, but when
unlink (i.e. our pg_unlink()) fails it takes a very long time (minutes)
to fail. And the file is actually not there. So it looks like we loop
over and over and keep getting EACCESS, and then get ENOENT, but the
last one that failed with EACCESS actually succeeded. *sigh*
... or someone else deleted it in between our last EACCESS failure and
the ENOENT try. What someone else would that be? More than likely,
the same guy who was holding it open to cause the EACCESS failures.
Perhaps there are paths in the code that don't go through win32_open?
regards, tom lane
Import Notes
Reply to msg id not found: 417D304B.7060101@dunslane.net
Tom Lane wrote:
Andrew Dunstan <andrew@dunslane.net> writes:
Another data point - when rmdir() fails it fails quickly, but when
unlink (i.e. our pg_unlink()) fails it takes a very long time (minutes)
to fail. And the file is actually not there. So it looks like we loop
over and over and keep getting EACCESS, and then get ENOENT, but the
last one that failed with EACCESS actually succeeded. *sigh*... or someone else deleted it in between our last EACCESS failure and
the ENOENT try. What someone else would that be? More than likely,
the same guy who was holding it open to cause the EACCESS failures.Perhaps there are paths in the code that don't go through win32_open?
Well, on looking at the MS API at
http://msdn.microsoft.com/library/en-us/vclib/html/vcrefRunTimeLibraryReference.asp
I see that opendir() and friends aren't there, which means we might be
at the mercy of what mingw does for us.
If I increase the sleep time before dropdb enormously (35 secs) the
unlink errors seem to go away, and instead they become rmdir errors like
the rest.
I am wondering if we need to look at using direct calls to the Windows
API (findfirst() and friends).
cheers
andrew
Andrew Dunstan <andrew@dunslane.net> writes:
If I increase the sleep time before dropdb enormously (35 secs) the
unlink errors seem to go away, and instead they become rmdir errors like
the rest.
Do you have anything equivalent to ps that you could use to check
whether there is still an old backend alive during this interval?
Does Windows forbid deleting a directory that is the current working
directory of some process (assuming they even have the same concept
of cwd as Unixen)? If so, is this the same error symptom you would get?
I am wondering if the rmdir failure occurs because an old backend is
still chdir'd into the database directory.
regards, tom lane
Tom Lane wrote:
Andrew Dunstan <andrew@dunslane.net> writes:
If I increase the sleep time before dropdb enormously (35 secs) the
unlink errors seem to go away, and instead they become rmdir errors like
the rest.Do you have anything equivalent to ps that you could use to check
whether there is still an old backend alive during this interval?Does Windows forbid deleting a directory that is the current working
directory of some process (assuming they even have the same concept
of cwd as Unixen)? If so, is this the same error symptom you would get?
I am wondering if the rmdir failure occurs because an old backend is
still chdir'd into the database directory.
No, testing shows you get "permission denied" rather than "directory not
empty" in this case.
cheers
andrew
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we have
deleted successfully.
Bottom line, this is a real mess. Surely postgres is not the only
application in the world that wants to be able to delete a directory
tree reliably on Windows. What do other apps do?
cheers
andrew
2004-10-26 10:26:35 [2496] LOG: connection received: host=127.0.0.1
port=1918
2004-10-26 10:26:35 [2496] LOG: connection authorized: user=pgrunner
database=template1
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/1247"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/1249"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/1255"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/1259"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16384"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16386"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16388"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16390"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16392"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16394"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16396"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16398"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16400"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16402"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16404"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16406"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16408"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16410"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16412"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16414"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16416"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16418"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16672"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16674"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16676"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16678"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16679"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16680"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16681"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16682"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16683"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16684"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16685"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16686"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16687"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16688"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16689"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16690"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16691"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16692"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16693"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16694"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16695"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16696"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16697"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16698"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16701"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16702"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16703"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16706"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16707"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16708"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16709"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16710"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16711"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16712"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16713"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16714"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16715"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16716"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16717"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16718"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16719"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16720"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16721"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16724"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16727"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16728"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16729"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16730"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16731"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16732"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16735"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16737"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16738"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16740"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16744"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16746"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16750"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16752"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16753"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16755"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16759"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/16761"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17158"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17160"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17162"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17163"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17165"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17167"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17168"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17170"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17172"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17173"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17175"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17177"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17178"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17180"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17182"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17183"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17185"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17187"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17388"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17990"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/17991"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/18593"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/18594"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/19196"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/19197"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/19799"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/19800"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/20402"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/20403"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/21005"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/21006"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/21007"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/21609"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/21610"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/22212"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/22213"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/22814"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/22815"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/23416"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/23433"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/23434"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/24036"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/24037"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/24651"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/24652"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/25298"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/25299"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/25976"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/25977"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/26654"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/26655"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/26657"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/26659"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/27196"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/27197"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/27733"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/27734"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28270"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28271"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28273"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28275"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28812"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/28813"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/29427"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/29428"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/29430"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/29432"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/30054"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/30055"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/30057"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/30059"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/31271"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/pg_internal.init"
2004-10-26 10:26:35 [2496] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230/PG_VERSION"
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '1249'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '1259'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '16676'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '16686'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '16687'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '16701'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '21006'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '21007'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '21609'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '21610'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '22212'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '22213'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '22814'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '22815'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '23416'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '23433'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '23434'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '24036'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '24037'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '24651'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '24652'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '25298'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '25299'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '25976'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '25977'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '26654'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '26655'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '26659'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '27196'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '28813'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '30055'
2004-10-26 10:26:35 [2496] WARNING: rmtree: dir
'C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/base/17230'
still has file '31271'
2004-10-26 10:27:04 [2496] WARNING: rmtree: waited 30 secs for rmdir,
continuing to try
2004-10-26 10:27:34 [2496] WARNING: rmtree: waited 60 secs for rmdir,
continuing to try
2004-10-26 10:28:04 [2496] WARNING: rmtree: waited 90 secs for rmdir,
continuing to try
2004-10-26 10:28:34 [2496] WARNING: rmtree: waited 120 secs for rmdir,
continuing to try
2004-10-26 10:29:04 [2496] WARNING: rmtree: waited 150 secs for rmdir,
continuing to try
2004-10-26 10:29:34 [2496] WARNING: rmtree: waited 180 secs for rmdir,
continuing to try
2004-10-26 10:30:04 [2496] WARNING: rmtree: waited 210 secs for rmdir,
continuing to try
2004-10-26 10:30:34 [2496] WARNING: rmtree: waited 240 secs for rmdir,
continuing to try
2004-10-26 10:31:04 [2496] WARNING: rmtree: waited 270 secs for rmdir,
continuing to try
2004-10-26 10:31:06 [2080] DEBUG: unlinking
"C:/msys/1.0/home/pgrunner/pgbuildfarm/root/HEAD/inst.blurfl/data/pg_xlog/xlogtemp.2080"
2004-10-26 10:31:09 [2496] WARNING: rmtree: rmdir took 274 secs/loops
2004-10-26 10:31:09 [2496] LOG: disconnection: session time: 0:04:34.11
user=pgrunner database=template1 host=127.0.0.1 port=1918
Andrew Dunstan <andrew@dunslane.net> writes:
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we have
deleted successfully.
If you rescan the directory after deleting the files, does it show
as empty?
Bottom line, this is a real mess. Surely postgres is not the only
application in the world that wants to be able to delete a directory
tree reliably on Windows. What do other apps do?
I'm wondering if this is a side effect of the way win32_open does
things. It's hard to believe that rmdir is that bogus in general,
but perhaps win32_open is causing us to exercise a corner case?
regards, tom lane
Tom Lane wrote:
Andrew Dunstan <andrew@dunslane.net> writes:
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we have
deleted successfully.If you rescan the directory after deleting the files, does it show
as empty?
No! That's how I got the list of "files it still thinks are there".
Gross, eh?
Bottom line, this is a real mess. Surely postgres is not the only
application in the world that wants to be able to delete a directory
tree reliably on Windows. What do other apps do?I'm wondering if this is a side effect of the way win32_open does
things. It's hard to believe that rmdir is that bogus in general,
but perhaps win32_open is causing us to exercise a corner case?
I don't know. I tried to reproduce it in a simple case using
fopen/fclose and wasn't able to.
cheers
andrew
Andrew Dunstan schrieb:
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we have
deleted successfully.
300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?
Why don't you use DeletFileA() instead of unlink()?
Or even better, why don't you use this delete on close snippet instead:
HANDLE h;
h = CreateFile (win32_name, 0, FILE_SHARE_READ, &sec_none_nih,
OPEN_EXISTING, FILE_FLAG_DELETE_ON_CLOSE, 0);
if (h != INVALID_HANDLE_VALUE)
{
(void) SetFileAttributes (win32_name, (DWORD) win32_name);
BOOL res = CloseHandle (h);
//syscall_printf ("%d = CloseHandle (%p)", res, h);
if (GetFileAttributes (win32_name) == INVALID_FILE_ATTRIBUTES)
{
//syscall_printf ("CreateFile (FILE_FLAG_DELETE_ON_CLOSE)
succeeded");
goto ok;
}
else
{
//syscall_printf ("CreateFile (FILE_FLAG_DELETE_ON_CLOSE) failed");
SetFileAttributes (win32_name, (DWORD) win32_name &
~(FILE_ATTRIBUTE_READONLY | FILE_ATTRIBUTE_SYSTEM));
}
}
}
/* Try a delete with attributes reset */
if (DeleteFile (win32_name))
{
syscall_printf ("DeleteFile after CreateFile/CloseHandle succeeded");
goto ok;
}
It should only happen a ERROR_SHARING_VIOLATION on NT systems with such
a long timeout. This is then a concurrency problem. win95 will not
return ERROR_SHARING_VIOLATION, only ERROR_ACCESS_DENIED
...
2004-10-26 10:31:09 [2496] WARNING: rmtree: rmdir took 274 secs/loops
2004-10-26 10:31:09 [2496] LOG: disconnection: session time: 0:04:34.11
user=pgrunner database=template1 host=127.0.0.1 port=1918
--
Reini Urban
http://xarch.tu-graz.ac.at/home/rurban/
problem area found. see below.
Reini Urban wrote:
Andrew Dunstan schrieb:
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we
have deleted successfully.300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?
success.
Why don't you use DeletFileA() instead of unlink()?
Or even better, why don't you use this delete on close snippet instead:
[snip]
Before I tried anything like that I tried one more thing. I disabled the
background writer and the problem stopped. So now we know the "culprit".
It should only happen a ERROR_SHARING_VIOLATION on NT systems with
such a long timeout. This is then a concurrency problem. win95 will
not return ERROR_SHARING_VIOLATION, only ERROR_ACCESS_DENIED
We don't support W95/W98/WME at all. The tests were done on XP-Pro.
cheers
andrew
Andrew Dunstan schrieb:
problem area found. see below.
Reini Urban wrote:Andrew Dunstan schrieb:
Here is some more info. Below is a trace from dropdb. There is a loop
around the rmdir() calls which I have set to time out at 600 seconds.
The call eventually succeeds after around 300 seconds (I've seen this
several times). It looks like we are the victim of some caching - the
directory still thinks it has some of the files it has told us we
have deleted successfully.300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?
success.
Oops! 5min timeout for success is certainly problematic.
Why don't you use DeletFileA() instead of unlink()?
Or even better, why don't you use this delete on close snippet instead:[snip]
Before I tried anything like that I tried one more thing. I disabled the
background writer and the problem stopped. So now we know the "culprit".
Good! Relieve.
It should only happen a ERROR_SHARING_VIOLATION on NT systems with
such a long timeout. This is then a concurrency problem. win95 will
not return ERROR_SHARING_VIOLATION, only ERROR_ACCESS_DENIEDWe don't support W95/W98/WME at all. The tests were done on XP-Pro.
Ah sorry. I forgot.
--
Reini Urban
http://xarch.tu-graz.ac.at/home/rurban/
Reini Urban wrote:
300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?success.
Oops! 5min timeout for success is certainly problematic.
You misunderstood. The 300 secs is not in waiting for unlink() to
return, it is in waiting for its effects to be seen by rmdir() (i.e. for
the entry to actually be cleared from the directory). unlink() is
returning very quickly. If the bgwriter is disabled then the entries are
cleared very quickly too (i.e. before we even get to rmdir())
cheers
andrew
Andrew Dunstan wrote:
Reini Urban wrote:
300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?success.
Oops! 5min timeout for success is certainly problematic.
You misunderstood. The 300 secs is not in waiting for unlink() to
return, it is in waiting for its effects to be seen by rmdir() (i.e. for
the entry to actually be cleared from the directory). unlink() is
returning very quickly. If the bgwriter is disabled then the entries are
cleared very quickly too (i.e. before we even get to rmdir())
What I am thinking is that the way we open these files allows us to
delete them while they are still open, but perhaps it doesn't allow us
to actually delete the directory that contains the files.
Also, it is possible bgwriter is keeping some files open in that
directory and that is causing the long delays.
--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
300 secs (!) fs timeout is really broken.
Looks more like a locking or network timeout issue.
What error codes does unlink(3) return?success.
Oops! 5min timeout for success is certainly problematic.
You misunderstood. The 300 secs is not in waiting for unlink() to
return, it is in waiting for its effects to be seen by
rmdir() (i.e. for
because the bgwriter obviously keeps them open, no ?
Andreas
Import Notes
Resolved by subject fallback
Andrew Dunstan <andrew@dunslane.net> writes:
Before I tried anything like that I tried one more thing. I disabled the
background writer and the problem stopped. So now we know the "culprit".
Okay. So what that says is that win32_open's claim to allow unlinking
an open file is a lie; or at least, it does not work the way the
equivalent facility on Unix does. It sounds to me like Windows is
simply marking the open file as to be deleted on last close --- the
directory entry remains present and so the directory can't be dropped
either.
One relatively low-impact workaround would be to force a checkpoint
(on Windows only) during DROP DATABASE, just before we actually fire
the rmtree() operation. The bgwriter is already coded to close all its
open files after a checkpoint ...
regards, tom lane
Tom Lane wrote:
Andrew Dunstan <andrew@dunslane.net> writes:
Before I tried anything like that I tried one more thing. I disabled the
background writer and the problem stopped. So now we know the "culprit".Okay. So what that says is that win32_open's claim to allow unlinking
an open file is a lie; or at least, it does not work the way the
equivalent facility on Unix does. It sounds to me like Windows is
simply marking the open file as to be deleted on last close --- the
directory entry remains present and so the directory can't be dropped
either.
Looks that way to me too.
One relatively low-impact workaround would be to force a checkpoint
(on Windows only) during DROP DATABASE, just before we actually fire
the rmtree() operation. The bgwriter is already coded to close all its
open files after a checkpoint ...
Works for me. If someone gives me a patch I'll be happy to test it.
I did wonder if there should be a call that instead of forcing a flush
could tell bgwriter just to forget about the file(s) because we're
discarding them. But that was just idle speculation - I haven't looked
at bgwriter at all.
cheers
andrew
Zeugswetter Andreas DAZ SD wrote:
You misunderstood. The 300 secs is not in waiting for unlink() to
return, it is in waiting for its effects to be seen by
rmdir() (i.e. forbecause the bgwriter obviously keeps them open, no ?
Yes.
cheers
andrew
Andrew Dunstan <andrew@dunslane.net> writes:
Tom Lane wrote:
One relatively low-impact workaround would be to force a checkpoint
(on Windows only) during DROP DATABASE, just before we actually fire
the rmtree() operation. The bgwriter is already coded to close all its
open files after a checkpoint ...
Works for me. If someone gives me a patch I'll be happy to test it.
Try putting "RequestCheckpoint(true)" in dbcommands.c just before
remove_dbtablespaces (about line 630).
It looks like the bgwriter is not quite up-to-speed for this, either;
you should rearrange things near line 350 of bgwriter.c so that
smgrcloseall is performed before marking the checkpoint done in shmem.
Else RequestCheckpoint could come back before the files are all closed.
I did wonder if there should be a call that instead of forcing a flush
could tell bgwriter just to forget about the file(s) because we're
discarding them. But that was just idle speculation - I haven't looked
at bgwriter at all.
Not necessary, as long as you put the checkpoint after the DropBuffers
call in dbcommands.c. The bgwriter won't find anything to write.
regards, tom lane
Andrew Dunstan <andrew@dunslane.net> writes:
You misunderstood. The 300 secs is not in waiting for unlink() to
return, it is in waiting for its effects to be seen by rmdir() (i.e. for
the entry to actually be cleared from the directory). unlink() is
returning very quickly. If the bgwriter is disabled then the entries are
cleared very quickly too (i.e. before we even get to rmdir())
More specifically, 300 seconds is the most time you'd have to wait for a
checkpoint to occur (with default checkpoint settings) ...
regards, tom lane
Tom Lane wrote:
Try putting "RequestCheckpoint(true)" in dbcommands.c just before
remove_dbtablespaces (about line 630).It looks like the bgwriter is not quite up-to-speed for this, either;
you should rearrange things near line 350 of bgwriter.c so that
smgrcloseall is performed before marking the checkpoint done in shmem.
Else RequestCheckpoint could come back before the files are all closed.
seems to do the trick. patch attached.
I did wonder if there should be a call that instead of forcing a flush
could tell bgwriter just to forget about the file(s) because we're
discarding them. But that was just idle speculation - I haven't looked
at bgwriter at all.Not necessary, as long as you put the checkpoint after the DropBuffers
call in dbcommands.c. The bgwriter won't find anything to write.
What about other databases? Or won't the forced checkpoint affect them?
cheers
andrew
Attachments:
dropdb.patchtext/x-patch; name=dropdb.patchDownload
Index: src/backend/commands/dbcommands.c
===================================================================
RCS file: /home/cvsmirror/pgsql/src/backend/commands/dbcommands.c,v
retrieving revision 1.145
diff -c -r1.145 dbcommands.c
*** src/backend/commands/dbcommands.c 17 Oct 2004 20:47:20 -0000 1.145
--- src/backend/commands/dbcommands.c 27 Oct 2004 23:48:10 -0000
***************
*** 32,37 ****
--- 32,38 ----
#include "commands/tablespace.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
+ #include "postmaster/bgwriter.h"
#include "storage/fd.h"
#include "storage/freespace.h"
#include "storage/sinval.h"
***************
*** 625,630 ****
--- 626,639 ----
FreeSpaceMapForgetDatabase(db_id);
/*
+ * On Windows, force a checkpoint so that the bgwriter doesn't hold any
+ * open files, which would cause rmdir() to fail.
+ */
+ #ifdef WIN32
+ RequestCheckpoint(true);
+ #endif
+
+ /*
* Remove all tablespace subdirs belonging to the database.
*/
remove_dbtablespaces(db_id);
Index: src/backend/postmaster/bgwriter.c
===================================================================
RCS file: /home/cvsmirror/pgsql/src/backend/postmaster/bgwriter.c,v
retrieving revision 1.9
diff -c -r1.9 bgwriter.c
*** src/backend/postmaster/bgwriter.c 12 Oct 2004 21:54:40 -0000 1.9
--- src/backend/postmaster/bgwriter.c 27 Oct 2004 23:05:10 -0000
***************
*** 347,352 ****
--- 347,361 ----
CreateCheckPoint(false, force_checkpoint);
/*
+ * After any checkpoint, close all smgr files. This is so we
+ * won't hang onto smgr references to deleted files
+ * indefinitely. (It is safe to do this because this process
+ * does not have a relcache, and so no dangling references
+ * could remain.)
+ */
+ smgrcloseall();
+
+ /*
* Indicate checkpoint completion to any waiting backends.
*/
BgWriterShmem->ckpt_done = BgWriterShmem->ckpt_started;
***************
*** 359,373 ****
*/
last_checkpoint_time = now;
- /*
- * After any checkpoint, close all smgr files. This is so we
- * won't hang onto smgr references to deleted files
- * indefinitely. (It is safe to do this because this process
- * does not have a relcache, and so no dangling references
- * could remain.)
- */
- smgrcloseall();
-
/* Nap for configured time before rechecking */
n = 1;
}
--- 368,373 ----
Andrew Dunstan <andrew@dunslane.net> writes:
Tom Lane wrote:
Try putting "RequestCheckpoint(true)" in dbcommands.c just before
remove_dbtablespaces (about line 630).
seems to do the trick. patch attached.
Patch applied.
Not necessary, as long as you put the checkpoint after the DropBuffers
call in dbcommands.c. The bgwriter won't find anything to write.
What about other databases? Or won't the forced checkpoint affect them?
For them, it's just an ordinary checkpoint. It's kind of a brute-force
solution, but I'm disinclined to worry about optimizing DROP DATABASE ...
regards, tom lane