Subject: Re: More time spending with "delete pending"
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Justin Pryzby <pryzby@telsasoft.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>
References: <c3427edf-d7c0-ff57-90f6-b5de3bb62709@gmail.com>
 <20201115011112.GW30691@telsasoft.com>
 <979f4ee6-9960-e37f-f3ee-f458e87777b0@gmail.com>
 <995713.1605725597@sss.pgh.pa.us> <1001775.1605731995@sss.pgh.pa.us>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <3366bfde-183f-60be-62ab-8ae81b946bac@gmail.com>
Date: Thu, 19 Nov 2020 00:00:00 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.10.0
MIME-Version: 1.0
In-Reply-To: <1001775.1605731995@sss.pgh.pa.us>
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Content-Language: en-US
Precedence: bulk

Hello Tom,
18.11.2020 23:39, Tom Lane wrote:
> BTW ... scraping the buildfarm logs for "could not open ... Permission
> denied" failures suggests that pgwin32_open() isn't the pinnacle of
> perfection either.  In the last three months I found these instances:
>
>  dory      | REL_11_STABLE | 2020-08-21 22:15:14 | Check              | pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/REL_11_STABLE/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>  fairywren | REL_11_STABLE | 2020-09-01 01:04:55 | Check              | pg_ctl: could not open PID file "C:/tools/msys64/home/pgrunner/bf/root/REL_11_STABLE/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>  dory      | HEAD          | 2020-09-16 02:40:17 | Check              | pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>  walleye   | HEAD          | 2020-09-29 18:35:46 | pg_upgradeCheck    | 2020-09-29 15:20:04.298 EDT [896:31] pg_regress/gist WARNING:  could not open statistics file "pg_stat_tmp/global.stat": Permission denied
>  frogmouth | REL_10_STABLE | 2020-10-01 00:30:15 | StopDb-C:5         | waiting for server to shut down....pg_ctl: could not open PID file "data-C/postmaster.pid": Permission denied\r
>  dory      | REL_11_STABLE | 2020-10-05 02:15:06 | pg_upgradeCheck    | waiting for server to shut down..............pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/REL_11_STABLE/pgsql.build/src/bin/pg_upgrade/tmp_check/data.old/postmaster.pid": Permission denied\r
>  bowerbird | REL_10_STABLE | 2020-10-21 23:19:22 | scriptsCheck       | waiting for server to shut down....pg_ctl: could not open PID file "H:/prog/bf/root/REL_10_STABLE/pgsql.build/src/bin/scripts/tmp_check/data_main_cH68/pgdata/postmaster.pid": Permission denied\r
>  jacana    | REL_10_STABLE | 2020-10-22 12:42:51 | pg_upgradeCheck    | Oct 22 09:08:20 waiting for server to shut down....pg_ctl: could not open PID file "c:/mingw/msys/1.0/home/pgrunner/bf/root/REL_10_STABLE/pgsql.build/src/bin/pg_upgrade/tmp_check/data.old/postmaster.pid": Permission denied\r
>  dory      | HEAD          | 2020-10-22 23:30:16 | Check              | pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>  dory      | REL_11_STABLE | 2020-10-27 18:15:08 | StopDb-C:2         | waiting for server to shut down....pg_ctl: could not open PID file "data-C/postmaster.pid": Permission denied\r
>  fairywren | REL_11_STABLE | 2020-10-28 04:01:17 | recoveryCheck      | waiting for server to shut down....pg_ctl: could not open PID file "C:/tools/msys64/home/pgrunner/bf/root/REL_11_STABLE/pgsql.build/src/test/recovery/tmp_check/t_004_timeline_switch_standby_2_data/pgdata/postmaster.pid": Permission denied\r
>  hamerkop  | REL_11_STABLE | 2020-11-01 11:31:54 | pg_upgradeCheck    | waiting for server to shut down....pg_ctl: could not open PID file "c:/build-farm-local/buildroot/REL_11_STABLE/pgsql.build/src/bin/pg_upgrade/tmp_check/data/postmaster.pid": Permission denied\r
>  dory      | HEAD          | 2020-11-04 05:50:17 | Check              | pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>  walleye   | HEAD          | 2020-11-09 09:45:41 | Check              | 2020-11-09 05:06:19.672 EST [4408:31] pg_regress/gist WARNING:  could not open statistics file "pg_stat_tmp/global.stat": Permission denied
>  dory      | HEAD          | 2020-11-10 23:35:18 | Check              | pg_ctl: could not open PID file "C:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid": Permission denied\r
>
> Now, the ones on the 10 and 11 branches are all from pg_ctl, which
> does not use pgwin32_open() in those branches, only native open().
> So those aren't fair to count against it.  But we have nearly as
> many similar failures in HEAD, which surely is going through
> pgwin32_open().  So either we don't really have adequate protection
> against delete-pending files, or there is some other effect we haven't
> explained yet.
Can you confirm that there are no such failures on REL_12_STABLE and
REL_13_STABLE for last three (or maybe six) months? Maybe something
changed in HEAD then?
> A simple theory about that is that the 1-second wait is not always
> enough on heavily loaded buildfarm machines.  Is it sensible to
> increase the timeout?
I'm going to explore the issue this weekend, and probably comparing
duration of the tests before failures can say something about load of
the machines...
It's very doubtful that that state could last for so 1 second...

Best regards,
Alexander