Date: Fri, 19 Mar 2021 06:56:39 +0900
From: Michael Paquier <michael@paquier.xyz>
To: =?utf-8?B?0K/RgNC+0YHQu9Cw0LIg0J/QsNGI0LjQvdGB0LrQuNC5?=
 <yarik97.6@gmail.com>
Cc: Postgres bugs <pgsql-bugs@lists.postgresql.org>
Subject: Re: BUG #16927: Postgres can`t access WAL files
Message-ID: <YFPMl3TUPXbN127E@paquier.xyz>
References: <YFExaMohbb8tqM3k@paquier.xyz>
 <YFFFkWzunPO9M6kV@paquier.xyz>
 <CADLmToLRCck9P7k=iOzLZRU7FiUmFTTTTggxF3gc0a1RasYrhQ@mail.gmail.com>
 <YFKB0ccg5zN+nS0Z@paquier.xyz>
 <CADLmToKd=eFW9E+p7i0sxHOZZKshShvJSedD3ek=+PqhiXt4jg@mail.gmail.com>
 <YFMTgN8KY9MQsiIk@paquier.xyz>
 <CADLmTo+FaWQEi9Lt=f4kc9wL-XT+RiaEddW2kfuCZ=XiXycwNQ@mail.gmail.com>
 <CADLmTo+AOq2UE3Gr22omfcxhZajqkeGYgWFowKNScOZA1fWVFA@mail.gmail.com>
 <YFM2MRbHZGQ4DsG/@paquier.xyz>
 <CADLmToJJykdGUdKiPkut4mq8oZJ8z4+8d5aSUU9zCtey7yu_9g@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="ZDDLj0KGzSOker6E"
Content-Disposition: inline
In-Reply-To: 
 <CADLmToJJykdGUdKiPkut4mq8oZJ8z4+8d5aSUU9zCtey7yu_9g@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/YFPMl3TUPXbN127E%40paquier.xyz>
Precedence: bulk


--ZDDLj0KGzSOker6E
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Thu, Mar 18, 2021 at 02:16:21PM +0200, =D0=AF=D1=80=D0=BE=D1=81=D0=BB=D0=
=B0=D0=B2 =D0=9F=D0=B0=D1=88=D0=B8=D0=BD=D1=81=D0=BA=D0=B8=D0=B9 wrote:
> =D1=87=D1=82, 18 =D0=BC=D0=B0=D1=80. 2021 =D0=B3. =D0=B2 13:15, Michael P=
aquier <michael@paquier.xyz>:
>> On Thu, Mar 18, 2021 at 12:44:29PM +0200, =D0=AF=D1=80=D0=BE=D1=81=D0=BB=
=D0=B0=D0=B2 =D0=9F=D0=B0=D1=88=D0=B8=D0=BD=D1=81=D0=BA=D0=B8=D0=B9 wrote:
>>> So, I started test on my Windows server that we using for replica on
>>> instance, which I copied from master. The binarys was unpatched, that
>>> you sent me here. The system is: windows server 2016, os build 14393.42=
83.
>>> To emulate load I used pgbench with such parameters -t 10000 -c 50 -j 2=
0.
>>> After couple of running test in log file I found almost same errors:
>>> "2021-03-18 11:27:14.322 EET [3748] LOG:  could not rename temporary
>>> statistics file "pg_stat_tmp/global.tmp" to "pg_stat_tmp/global.stat":
>>> Permission denied
>>> 2021-03-18 11:27:18.928 EET [692] LOG:  using stale statistics instead =
of
>>> current ones because stats collector is not responding"
>>> ...and
>>> "2021-03-18 11:48:49.630 EET [6476] LOG:  could not rename file
>>> "pg_wal/00000001000000650000008F": Permission denied"
>>> So I decided to switch to patched binaries and sometimes get only this
>>> one error:
>>> "2021-03-18 12:27:14.571 EET [4840] LOG:  could not rename temporary
>>> statistics file "pg_stat_tmp/global.tmp" to "pg_stat_tmp/global.stat":
>>> Permission denied
>>> 2021-03-18 12:27:19.178 EET [7556] LOG:  using stale statistics instead
>> of current ones because stats collector is not responding"
>>> Which is not very critical, so it`s ok.
>>
>> Okay, so it looks like a very good news to me.  With the patched
>> binaries you are not seeing the renaming problem with the WAL files
>> anymore.
>>
>>> On other hand, on developer server (Windows Server 2016 (version 1607, =
OS
>>> build 14393.4225))  with real load and unpatched binaries now I got no
>>> errors about about pg_wal and gets only twice this error:
>>> "2021-03-18 12:07:26.153 EET [2956] LOG:  could not rename temporary
>>> statistics file "pg_stat_tmp/global.tmp" to "pg_stat_tmp/global.stat":
>>> Permission denied"
>>>
>>> So, keep testing. That's strange for now. I am thinking about changing
>>> binaries on prod server, but it will be possible on Saturday.
>>
>> Yes, I think that it would be good to do more tests, as it may be
>> possible that what you are seeing does not repeat.  What you are
>> reporting is encouraging though.  Thanks!
>>
>> By the way, it is very important to report that to the community
>> mailing lists.  Could you add pgsql-bugs when replying please?
>
> The strange thing is why one server works fine on unpatched binaries while
> the second one requires a patched version to get rid of pg_wal access
> error.
>
> UPD: just right now on developer server I got an error: "2021-03-18
> 14:11:39.444 EET [892] LOG:  could not rename file
> "pg_wal/00000001000009130000006F": Permission denied"
> Will switch to patched binaries and tell you later.

The issue seems to depend on timing and the load your cluster is
facing, so that is not surprising to hear that this does not show up
100% of the time.  I am actually glad to hear that you have not seen
the issue anymore with the patched builds, while the unpatched builds
have shown the problem at least once.  It would be a problem if the
patched builds begin to complain about the renaming of the WAL
segments though as we would have to consider a different theory.

> P.S: Sorry, that I didn't include in reply psql-bugs, is it ok right now?

That's fine.  Thanks :)

I have added to this email the last things we discussed, for
transparency.
--
Michael

--ZDDLj0KGzSOker6E
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmBTzJcACgkQnvQgOdby
QH285Q//bnUsh6iigaLwi+M+ISWzvwCG29iMARJW9XBOdEKYv696jAr1erDhtgni
Ia/Kj/kz34oPRu7DpR9EWEJMDwDTZWgzoFj/fqLkXHIA8xM76WvzSm+4rK6QCs/P
gfefp53L13l+5bAdCF6JSQB27LDUQe0MrbE+427TlPCZUb7G58HzcBJavE66ZKML
oZdltDLm8hCj60z8zcg+55pwWQeh9zFKTyp2Qs1Z0FToJKXmXicTM7QNu5ojm5Au
tl4aoEc2HyfRJo3AB+OoiG1xj6UgiKamk5kR+lL4fbOTbC2IBkkpw+4GXY0FO+6E
+2KbNT/PuRxEeUv3YMxJr8Bco0ZrIRv7qUixS1W6tv/Pugzgamb5I+Q879uBkvH1
4gAO8LSiA7yppSTL/O9gRJ1EGl/GxfdMf4R8/pILjme0kvNvrhc6E7eFh1V7gOfp
O93m3D2ItK6nzA+iX7VWSVC9STXwEyMOznv55FxDiHQ0s/kSGJLK7brfn6GkXXwa
0gjDZ21M5uhWYxnG8VzsLBs86KUHoq5wDR1s6f49wMLmGlwT7HLuEAHQzNBGJQN+
0NXP16NW8kSlaGrDjvYCxY5+2JZCd1A/oabX8pGtlXFwxhfjCA2H8V6ejrUqF/rw
09baxejCJsDklAK1ZkLeeWi5w9z3Bo3Z/THVvCOdhJVD1VkoHGE=
=5N0k
-----END PGP SIGNATURE-----

--ZDDLj0KGzSOker6E--