From: Alexander Lakhin <exclusion@gmail.com>
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
To: tgl@sss.pgh.pa.us
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)
Date: Wed, 18 Dec 2019 09:00:00 +0300
Message-ID: <b2b8cc4c-b7d7-0d1b-f6ee-a02bbef5bdd0@gmail.com> (raw)
In-Reply-To: <20191218.122526.233778911708036076.horikyota.ntt@gmail.com>
References: <18124.1576527433@sss.pgh.pa.us>
<58a715ac-d118-e7c1-733a-46fa252b345b@gmail.com>
<23073.1576626626@sss.pgh.pa.us>
<20191218.122526.233778911708036076.horikyota.ntt@gmail.com>
Hello,
18.12.2019 6:25, Kyotaro Horiguchi wrote:
> At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in
>>
>> Now, it's mighty suspicious that this has a timeout of 30 sec
>> which is exactly how long we made pgwin32_open retry for ---
>> but how is it that this test is causing an ERROR_ACCESS_DENIED
>> failure? And if it was, how did we get past that before?
Not exactly, we set timeout for 1 sec. It seems we have this timeout
occurred many times.
>> It does look suspiciously like this wait is triggering on these
>> machines and somehow getting masked in most other test cases.
>> If you compare the per-step runtimes in jacana's last successful
>> run,
>>
>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2019-12-16%2013%3A01%3A26
>>
>> with those after this patch went in,
>>
>> https://buildfarm.postgresql.org/cgi-bin/shocw_log.pl?nm=jacana&dt=2019-12-17%2004%3A16%3A40
>>
>> there's clearly something very wrong. fairywren likewise.
> The immediate cause of the failure seems to be a slowdown of startup
> or recovery. It took only 8 minutes in the successful case but 25
> minutes even though stopped on the way in the failure case.
>
> In the failure case, it took 30 seconds to move only 26.1MB from
> 15E8C48 to 30013A0. just around 0.3 seconds for a move of the same
> size (15E9C48->3000DE8 (26.1MB)) in the successful case (*1). In the
> sucessful case, the time took from archiving 00000002.history to
> removing old segments is 0.15 s, but about 3.5 s in the failure case
> (*2).
>
> Seemingly the immediate cause of the timeout looks like just an
> extreme slowdown of file read, but it took 2 seconds to move within a
> page from 3000C18 to 3000C50. So I suspect that 6d7547c219 might slow
> down readTimeLineHistory() significantly in the case.
>
> regards.
>
>
Yes, some tests are really slowed down (namely, test-decoding-check,
pg_basebackup-check, ...).
ProcessMonitor shows:
"8:11:57.1428800
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","SUCCESS",...
"8:11:57.1429851
AM","postgres.exe","2640","SetRenameInformationFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state.tmp","SUCCESS",...
"8:11:57.1432041
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","SUCCESS",""
"8:11:57.1432964
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",""
"8:11:57.1435137
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",...
"8:11:57.1435709
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",""
"8:11:57.1437251
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.2451100
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.3571077
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.4643527
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.5778052
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.6825679
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.7921704
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.9018507
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.0109597
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.1204329
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.2300829
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.2302124
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.3393345
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.4484310
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.5584079
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.6683586
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.7773396
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.8858091
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.9955264
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.1050665
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.2137752
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.3234641
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.3261361
AM","postgres.exe","2640","QueryOpen","C:\Windows\System32\kernel.appcore.dll","FAST
IO DISALLOWED",""
https://web.archive.org/web/20150317121919/http://support.microsoft.com/en-us/kb/113996
tells that STATUS_FILE_IS_A_DIRECTORY is mapped to ERROR_ACCESS_DENIED too.
It seems that the cause of the issue is in fsync_fname_ext:
fd = OpenTransientFile(fname, flags);
/*
* Some OSs don't allow us to open directories at all (Windows returns
* EACCES), just ignore the error in that case. If desired also
silently
* ignoring errors about unreadable files. Log others.
*/
if (fd < 0 && isdir && (errno == EISDIR || errno == EACCES))
return 0;
Maybe we need to take isdir into account before calling
OpenTransientFile on Windows...
Please look at the simple patch that makes the recoverycheck test pass.
Best regards,
Alexander
Attachments:
[text/x-patch] fix- fsync_fname_ext.patch (1.3K, ../b2b8cc4c-b7d7-0d1b-f6ee-a02bbef5bdd0@gmail.com/2-fix-%20fsync_fname_ext.patch)
download | inline diff:diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.cindex f4ab19f8b7..09f341ffaa 100644--- a/src/backend/storage/file/fd.c+++ b/src/backend/storage/file/fd.c@@ -3383,6 +3383,12 @@ fsync_fname_ext(const char *fname, bool isdir, bool ignore_perm, int elevel)
int flags;
int returncode;
+#ifdef WIN32+ /* Windows doesn't allow us to open directories at all.+ */+ if (isdir)+ return 0;+#endif
/*
* Some OSs require directories to be opened read-only whereas other
* systems don't allow us to fsync files opened read-only; so we need both
@@ -3394,17 +3400,12 @@ fsync_fname_ext(const char *fname, bool isdir, bool ignore_perm, int elevel)
flags |= O_RDWR;
else
flags |= O_RDONLY;
-
fd = OpenTransientFile(fname, flags);
/*
- * Some OSs don't allow us to open directories at all (Windows returns- * EACCES), just ignore the error in that case. If desired also silently- * ignoring errors about unreadable files. Log others.+ * If desired silently ignore errors about unreadable files. Log others.
*/
- if (fd < 0 && isdir && (errno == EISDIR || errno == EACCES))- return 0;- else if (fd < 0 && ignore_perm && errno == EACCES)+ if (fd < 0 && ignore_perm && errno == EACCES)
return 0;
else if (fd < 0)
{
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: exclusion@gmail.com, horikyota.ntt@gmail.com, tgl@sss.pgh.pa.us, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)
In-Reply-To: <b2b8cc4c-b7d7-0d1b-f6ee-a02bbef5bdd0@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox