Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1phbh9-00018I-2y for pgsql-bugs@arkaria.postgresql.org; Wed, 29 Mar 2023 19:42:56 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1phbh6-0000zu-0a for pgsql-bugs@arkaria.postgresql.org; Wed, 29 Mar 2023 19:42:52 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1phbh5-0000zj-JV for pgsql-bugs@lists.postgresql.org; Wed, 29 Mar 2023 19:42:51 +0000 Received: from smtp-fw-9103.amazon.com ([207.171.188.200]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1phbh2-00083m-7e for pgsql-bugs@lists.postgresql.org; Wed, 29 Mar 2023 19:42:51 +0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=amazon.com; i=@amazon.com; q=dns/txt; s=amazon201209; t=1680118968; x=1711654968; h=from:to:subject:date:message-id:mime-version; bh=auWjmfDjWIy9VQkgU/iO4uRUrHrmjTfGc7KC2c8IRYM=; b=KhpZeDUGhAuCTrxjJxLd48fbK5WdLdBM0/iPAwt4Puwj4qYgB+48SnA9 O4/cZE0zDZru35OJDvqQUzV2cIO+v0rkcNkNft3v+2RlUAZz4llHzULtO vIYTBHqFDO/JafHs/OPgWvJ9E7z+tHfnJedi3DVGgLebIwkLEJWBupQ2H I=; X-IronPort-AV: E=Sophos;i="5.98,301,1673913600"; d="scan'208,217";a="1117655962" Received: from pdx4-co-svc-p1-lb2-vlan3.amazon.com (HELO email-inbound-relay-pdx-2c-m6i4x-fad5e78e.us-west-2.amazon.com) ([10.25.36.214]) by smtp-border-fw-9103.sea19.amazon.com with ESMTP/TLS/ECDHE-RSA-AES256-GCM-SHA384; 29 Mar 2023 19:42:34 +0000 Received: from EX19D014EUA004.ant.amazon.com (pdx1-ws-svc-p6-lb9-vlan3.pdx.amazon.com [10.236.137.198]) by email-inbound-relay-pdx-2c-m6i4x-fad5e78e.us-west-2.amazon.com (Postfix) with ESMTPS id 65727A03C8 for ; Wed, 29 Mar 2023 19:42:33 +0000 (UTC) Received: from EX19D040EUC002.ant.amazon.com (10.252.61.192) by EX19D014EUA004.ant.amazon.com (10.252.50.41) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.2.1118.26; Wed, 29 Mar 2023 19:42:31 +0000 Received: from EX19D040EUC002.ant.amazon.com (10.252.61.192) by EX19D040EUC002.ant.amazon.com (10.252.61.192) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.2.1118.26; Wed, 29 Mar 2023 19:42:31 +0000 Received: from EX19D040EUC002.ant.amazon.com ([fe80::f5ad:6b9e:9eb3:808f]) by EX19D040EUC002.ant.amazon.com ([fe80::f5ad:6b9e:9eb3:808f%4]) with mapi id 15.02.1118.026; Wed, 29 Mar 2023 19:42:31 +0000 From: "Kumar, Sachin" To: "pgsql-bugs@lists.postgresql.org" Subject: .wal file gets modified after .ready file is created Thread-Topic: .wal file gets modified after .ready file is created Thread-Index: Adlidnl3jowChn8mQsGY44C6FK1cYg== Date: Wed, 29 Mar 2023 19:42:31 +0000 Message-ID: <6376e0ba308a4344a77727ab6d9d126d@amazon.com> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-originating-ip: [10.106.82.14] Content-Type: multipart/alternative; boundary="_000_6376e0ba308a4344a77727ab6d9d126damazoncom_" MIME-Version: 1.0 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --_000_6376e0ba308a4344a77727ab6d9d126damazoncom_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Hi Everyone, We are seeing that .wal modification time is after .ready file is created. [xyz/db/pg_wal]$ stat -c %Y archive_status/000000010000027100000018.ready 1678538736 [xyz/db/pg_wal]$ stat -c %Y 000000010000027100000018 1678538737 (postgresql binary does include this commit [1] https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3Dcommit;h=3Dff= 9f111bce24fd9bbca7a20315586de877d74923) This only happens when there is shutdown/fast shutdown (I have attached postgres logs (with some path information changed)) 12:42:49 UTC::@:[372]:LOG: starting PostgreSQL 14.5 on aarch64-unknown-lin= ux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red ), 64-bit 12:42:49 UTC::@:[372]:LOG: listening on IPv4 address "0.0.0.0", port 5432 12:42:49 UTC::@:[372]:LOG: listening on IPv6 address "::", port 5432 12:42:49 UTC::@:[372]:LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 12:42:49 UTC::@:[374]:LOG: database system was shut down at 12:33:33 UTC 12:42:49 UTC::@:[372]:LOG: database system is ready to accept connections 12:44:12 UTC::@:[372]:LOG: received SIGHUP, reloading configuration files 12:44:12 UTC::@:[372]:LOG: skipping missing configuration file "changed_pa= th/recovery.conf" 12:44:12 UTC::@:[380]:LOG: skipping missing configuration file "changed_pa= th/recovery.conf" 12:45:37 UTC::@:[372]:LOG: received fast shutdown request 12:45:37 UTC::@:[372]:LOG: aborting any active transactions 12:45:37 UTC::@:[372]:LOG: background worker "logical replication launcher= " (PID 381) exited with exit code 1 12:45:37 UTC::@:[375]:LOG: shutting down 12:45:36 UTC::@:[375]:LOG: checkpoint starting: shutdown immediate 12:45:36 UTC::@:[379]:LOG: archive command failed with exit code 1 12:45:36 UTC::@:[379]:DETAIL: The failed archive command was: changed_path= /rds_wal_archive pg_wal/0027100000018 12:45:36 UTC::@:[375]:LOG: checkpoint complete: wrote 7 buffers (0.0%); 0 = WAL file(s) added, 0 removed, 1 recycled; write=3D0.=3D0.011 s, total=3D0.0= 35 s; sync files=3D6, longest=3D0.007 s, average=3D0.002 s; distance=3D6553= 6 kB, estimate=3D65536 kB 12:45:36 UTC::@:[379]:LOG: archive command failed with exit code 1 12:45:36 UTC::@:[379]:DETAIL: The failed archive command was: changed_path= /rds_wal_archive pg_wal/0027100000018 12:45:37 UTC::@:[379]:LOG: archive command failed with exit code 1 12:45:37 UTC::@:[379]:DETAIL: The failed archive command was: changed_path= /rds_wal_archive pg_wal/0027100000018 12:45:37 UTC::@:[379]:WARNING: archiving write-ahead log file "00000001000= 0027100000018" failed too many times, will try 12:45:40 UTC::@:[372]:LOG: database system is shut down 12:45:44 UTC::@:[372]:LOG: listening on IPv4 address "0.0.0.0", port 5432 12:45:44 UTC::@:[372]:LOG: listening on IPv6 address "::", port 5432 12:45:44 UTC::@:[372]:LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 12:45:44 UTC::@:[374]:LOG: database system was shut down at 12:45:36 UTC 12:45:44 UTC::@:[372]:LOG: database system is ready to accept connections 12:45:44 UTC::@:[379]:LOG: archive command failed with exit code 1 12:45:44 UTC::@:[379]:DETAIL: The failed archive command was: changed_path= /rds_wal_archive pg_wal/000000010000027100000018 12:45:45 UTC::@:[379]:LOG: archive command failed with exit code 1 12:45:45 UTC::@:[379]:DETAIL: The failed archive command was: changed_path= /rds_wal_archive pg_wal/000000010000027100000018 12:45:46 UTC::@:[379]:LOG: archive command failed with exit code 1 pg_waldump of failing and next wal log failing wal_log pg_waldump 000000010000027100000018 | tail rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 271/60= 000B00, prev 271/60000AA8, desc: RUNNING_XACTS nextXid 80725 latestComplete= dXid 80724 oldestRunningXid 80725 rmgr: XLOG len (rec/tot): 24/ 24, tx: 0, lsn: 271/60= 000B38, prev 271/60000B00, desc: SWITCH next wal_log pg_waldump 000000010000027100000019 | head rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 271/64= 000028, prev 271/60000B38, desc: CHECKPOINT_SHUTDOWN redo 271/64000028; tli= 1; prev tli 1; fpw true; xid 0:80725; oid 172060; multi 1; offset 0; oldes= t xid 549 in DB 16406; oldest multi 1 in DB 16406; oldest/newest commit tim= estamp xid: 0/0; oldest running xid 0; shutdown rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 271/64= 0000A0, prev 271/64000028, desc: RUNNING_XACTS nextXid 80725 latestComplete= dXid 80724 oldestRunningXid 80725 rmgr: Heap len (rec/tot): 67/ 1352, tx: 80726, lsn: 271/64= 0000D8, prev 271/640000A0, desc: HOT_UPDATE off 28 xmax 80726 flags 0x00 ; = new off 32 xmax 0, blkref #0: rel 1664/0/1260 blk 0 FPW wal_dump of failing and next wal log looks normal to me. I dont think there is any contrecord involved because if it was we would ha= ve seen a corrosponding log entry. So maybe we are hitting a corner case of commit = [1] ?. [1] https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3Dcommit;h=3Dff= 9f111bce24fd9bbca7a20315586de877d74923 Regards Sachin Amazon Web Services --_000_6376e0ba308a4344a77727ab6d9d126damazoncom_ Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

Hi Everyone,

 

We are seeing that .wal modification time is after .ready file= is created.

[xyz/db/pg_wal]$ stat -c %Y archive_status/0000000100000271000= 00018.ready

1678538736

[xyz/db/pg_wal]$  stat -c %Y 000000010000027100000018

1678538737

 

(postgresql binary does include this commit

[1] https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3D= commit;h=3Dff9f111bce24fd9bbca7a20315586de877d74923)

 

This only happens when there is shutdown/fas= t shutdown

(I have attached postgres logs (with some path information cha= nged))

12:42:49 UTC::@:[372]:LOG:  starting PostgreSQL 14.5 on a= arch64-unknown-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red ), 64-bit

12:42:49 UTC::@:[372]:LOG:  listening on IPv4 address "0.0.0.0", po= rt 5432

12:42:49 UTC::@:[372]:LOG:  listening on IPv6 address "::", port 54= 32

12:42:49 UTC::@:[372]:LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"

12:42:49 UTC::@:[374]:LOG:  database system was shut down= at 12:33:33 UTC

12:42:49 UTC::@:[372]:LOG:  database system is ready to a= ccept connections

12:44:12 UTC::@:[372]:LOG:  received SIGHUP, reloading co= nfiguration files

12:44:12 UTC::@:[372]:LOG:  skipping missing configuratio= n file "changed_path/recovery.conf"

12:44:12 UTC::@:[380]:LOG:  skipping missing configuratio= n file "changed_path/recovery.conf"

12:45:37 UTC::@:[372]:LOG:  received fast shutdown reques= t

12:45:37 UTC::@:[372]:LOG:  aborting any active transacti= ons

12:45:37 UTC::@:[372]:LOG:  background worker "logical replication launcher"<= span style=3D"font-size:10.5pt;font-family:Consolas;color:black;mso-fareast= -language:EN-GB"> (PID 381) exited with exit code 1

12:45:37 UTC::@:[375]:LOG:  shutting down

12:45:36 UTC::@:[375]:LOG:  checkpoint starting: shutdown= immediate

12:45:36 UTC::@:[379]:LOG:  archive command failed with exit code 1

12:45:36 UTC::@:[379]:DETAIL:  The failed archive command= was: changed_path/rds_wal_archive pg_wal/0027100000018

12:45:36 UTC::@:[375]:LOG:  checkpoint complete: wrote 7 = buffers (0.0%); 0 WAL file(ss= , total=3D0.035 s; sync files=3D6, longest= =3D0.007 s, average=3D0.002 s; distance=3D65536 kB, es= timate=3D65536 kB

12:45:36 UTC::@:[379]:LOG:  archive command failed with exit code 1

12:45:36 UTC::@:[379]:DETAIL:  The failed archive command= was: changed_path/rds_wal_archive pg_wal/0027100000018

12:45:37 UTC::@:[379]:LOG:  archive command failed with exit code 1

12:45:37 UTC::@:[379]:DETAIL:  The failed archive command= was: changed_path/rds_wal_archive pg_wal/0027100000018

12:45:37 UTC::@:[379]:WARNING:  archiving write-ahead log= file "000000010000027100000018" failed too many times, will try

12:45:40 UTC::@:[372]:LOG:  database system is shut down<= o:p>

12:45:44 UTC::@:[372]:LOG:  listening on IPv4 address "0.0.0.0", po= rt 5432

12:45:44 UTC::@:[372]:LOG:  listening on IPv6 address "::", port 54= 32

12:45:44 UTC::@:[372]:LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"

12:45:44 UTC::@:[374]:LOG:  database system was shut down= at 12:45:36 UTC

12:45:44 UTC::@:[372]:LOG:  database system is ready to a= ccept connections

12:45:44 UTC::@:[379]:LOG:  archive command failed with exit code 1

12:45:44 UTC::@:[379]:DETAIL:  The failed archive command= was: changed_path/rds_wal_archive pg_wal/000000010000027100000018

12:45:45 UTC::@:[379]:LOG:  archive command failed with exit code 1

12:45:45 UTC::@:[379]:DETAIL:  The failed archive command= was: changed_path/rds_wal_archive pg_wal/000000010000027100000018

12:45:46 UTC::@:[379]:LOG:  archive command failed with exit code 1

 

pg_waldump of failing and next wal log

 

failing wal_log

pg_waldump 000000010000027100000018 | tail

rmgr: Standby     len (rec/tot):     50/ &= nbsp;  50, tx:          0, lsn: 271/60000B00,= prev 271/60000AA8, desc: RUNNING_XACTS nextXid 80725 latestCompletedXid 80724 oldestRunningXi= d 80725

rmgr: XLOG        len (rec/tot):   &n= bsp; 24/    24, tx:          0, lsn: 271= /60000B38, prev 271/60000B00, desc: SWITCH

 

next wal_log

pg_waldump 000000010000027100000019 | head

rmgr: XLOG        len (rec/tot):   &n= bsp;114/   114, tx:          0, lsn: 271/6400= 0028, prev 271/60000B38, desc: CHECKPOINT_SHUTDOWN redo 271/64000028; tli 1; prev tli 1; fpw true; xid 0:80725; oid 172060; multi 1; offset 0; oldest xid 549 in= DB 16406; oldest multi 1 in DB 16406; oldest/newest commit timestamp xid: = 0/0; oldest running xid 0; shutdown

rmgr: Standby     len (rec/tot):     50/ &= nbsp;  50, tx:          0, lsn: 271/640000A0,= prev 271/64000028, desc: RUNNING_XACTS nextXid 80725 latestCompletedXid 80724 oldestRunningXi= d 80725

rmgr: Heap        len (rec/tot):   &n= bsp; 67/  1352, tx:      80726, lsn: 271/640000D8, prev= 271/640000A0, desc: HOT_UPDATE off 28 xmax 80726 flags 0x00 ; new off 32 xmax 0, blkref = #0: rel 1664/0/1260 blk 0 FPW

 

wal_dump of failing and next wal log looks normal = to me.

I dont think there is any contrecord involved because if it was we would have se= en

a corrosponding log entry. So maybe we are hitting a corner case of commit [1] ?.=

 

[1] https://git.postgresql.org/gitweb/?p=3Dpostgresql.git;a=3D= commit;h=3Dff9f111bce24fd9bbca7a20315586de877d74923

 

Regards

Sachin

Amazon Web Services

 

 

--_000_6376e0ba308a4344a77727ab6d9d126damazoncom_--