Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ihSNa-0000To-OC for pgsql-bugs@arkaria.postgresql.org; Wed, 18 Dec 2019 06:00:15 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1ihSNZ-0001Qw-2P for pgsql-bugs@arkaria.postgresql.org; Wed, 18 Dec 2019 06:00:13 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ihSNY-0001Qp-O5 for pgsql-bugs@lists.postgresql.org; Wed, 18 Dec 2019 06:00:12 +0000 Received: from mail-lj1-x241.google.com ([2a00:1450:4864:20::241]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1ihSNR-000285-Du for pgsql-bugs@lists.postgresql.org; Wed, 18 Dec 2019 06:00:12 +0000 Received: by mail-lj1-x241.google.com with SMTP id z17so694851ljk.13 for ; Tue, 17 Dec 2019 22:00:05 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:cc:references:from:message-id:date:user-agent :mime-version:in-reply-to:content-language; bh=vxz/gjRBAupGeAZ3RrFT8PbR/gZD+j/Yih4ONiucdks=; b=HBswauXhevp5G2w3D0Lr0vDscVMvx4E8K/STY2DkIA1bvwkk/Mu2Qrknu+coyDzt2P +MYt2Kwd8hsTlAFduUkB3WE0ClsJcE73UCCmOPhuCR6YAyJZ9kY4FrX1UQENlYRiKmnx iDrg7+pNFKFpZoiM5t6XOer6Z3Ax2IPLSAEaFy/YbkDorD8uKyCFp7mcu7ArVj3OGpPN rYa+5t/iBzks/0mm5yMwJ01qjBvF2tQXcAa3sUHNv6oF+PAks+em94bjz4RbaFk4NnlP evHH7EG0nSoR6ZLTtBFUhYYWxBk/RCGlyzcppIJZJV41UZB6Rzi0TD5KUVbHv4zADxdB vmvQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:cc:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language; bh=vxz/gjRBAupGeAZ3RrFT8PbR/gZD+j/Yih4ONiucdks=; b=tP1kW6onslRl6A8ceXMFn0cUUX20DQyoXfl704Gvc6GeeofORzQS0B5ebacAV2WNxi TTIDII3aw0j5IML1VdonQPjqPLe/MNF2UuGFnN/sY2X0kBuJzfSH3Rfo9MpD9PnMy+eW l1osHl81DWe+rHcScCxTof8Yjti2DmHy81oqrvZeGtZEbrFA+cbajKIqaeOZ67pA7C9h +GzFW04aeHUilVa91YU9Lx3//k/L/G8T46oGBCHQ9VC3QEHLPTO0EUOMkWAkCNYDTNwg EG/Z/bVBPVwnpPJphpXV4G6rGDBrZ7B9f67x8RfLishgRFlI2RpSfdWOSv+aEbx6OujM qPWw== X-Gm-Message-State: APjAAAXvsjmWatXzy/t/+6LbpSWCKa4EZIlVMTw8GRFWvHJkqLWIdbIq 9mLtKUHZA+SLKSMm9sMVV5IyivvW X-Google-Smtp-Source: APXvYqw6OjwALBmgmhMt9Xtf14H2GEA0UDcaWQCn20A3ngO1m+unEjkBilQ2caMiGsCCtSrqjPT6Hg== X-Received: by 2002:a05:651c:20a:: with SMTP id y10mr380945ljn.216.1576648803161; Tue, 17 Dec 2019 22:00:03 -0800 (PST) Received: from [1.0.0.7] ([178.155.4.219]) by smtp.gmail.com with ESMTPSA id w17sm464849lfn.22.2019.12.17.22.00.01 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 17 Dec 2019 22:00:02 -0800 (PST) Subject: Re: BUG #16161: pg_ctl stop fails sometimes (on Windows) To: Kyotaro Horiguchi , tgl@sss.pgh.pa.us Cc: pgsql-bugs@lists.postgresql.org 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> From: Alexander Lakhin Message-ID: Date: Wed, 18 Dec 2019 09:00:00 +0300 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Thunderbird/60.7.2 MIME-Version: 1.0 In-Reply-To: <20191218.122526.233778911708036076.horikyota.ntt@gmail.com> Content-Type: multipart/mixed; boundary="------------E94CD02243E275889541BCF9" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------E94CD02243E275889541BCF9 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Hello, 18.12.2019 6:25, Kyotaro Horiguchi wrote: > At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane 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 --------------E94CD02243E275889541BCF9 Content-Type: text/x-patch; name="fix- fsync_fname_ext.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="fix- fsync_fname_ext.patch" diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c index 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) { --------------E94CD02243E275889541BCF9--