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 1oTYSd-0004ic-Il for pgsql-hackers@arkaria.postgresql.org; Thu, 01 Sep 2022 00:53:35 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1oTYSc-0006df-Dt for pgsql-hackers@arkaria.postgresql.org; Thu, 01 Sep 2022 00:53:34 +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 1oTYSc-0006bv-34 for pgsql-hackers@lists.postgresql.org; Thu, 01 Sep 2022 00:53:34 +0000 Received: from mail-il1-x12d.google.com ([2607:f8b0:4864:20::12d]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1oTYSZ-0001jx-Nb for pgsql-hackers@postgresql.org; Thu, 01 Sep 2022 00:53:33 +0000 Received: by mail-il1-x12d.google.com with SMTP id l16so8548300ilj.2 for ; Wed, 31 Aug 2022 17:53:31 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telsasoft-com.20210112.gappssmtp.com; s=20210112; h=user-agent:in-reply-to:content-disposition:mime-version:references :message-id:subject:cc:to:from:date:from:to:cc:subject:date; bh=j9uX8LY7lt+EmgmjMtSC/FdbDQnOyGGArwlTo52xmJE=; b=zkSW5kIWt/K3Fgk5D75yB9vlKLSadtyAnkLfwkH5AzpxZIeyVuSpRgG/4zbYwlgYbu t5YicVWc7CtiX5U0NAQTYxacsYvShMHILWBOqlSAUDEtO0gEIeE6yJddTvhRkJ/Gt1VU 4gTm3O/Hpv68pnVX0CZJrX0caJILs7WTan0GCbVrrn73ZPW41pAybGNUk2v/OcE9pK8v on/hU5WaJ7d7W4f1T8LaZHBwFJqDjDboZHmLYTrrMGEvEMCUbjLaAh425w6rjr8a7c1T BYCMWi1mVvPmGSScQwKcMYbl4GAxdDJoj3xy9VYUlce3reHa8W/Aa7jHa7vLeEnhyZ/a kSoA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=user-agent:in-reply-to:content-disposition:mime-version:references :message-id:subject:cc:to:from:date:x-gm-message-state:from:to:cc :subject:date; bh=j9uX8LY7lt+EmgmjMtSC/FdbDQnOyGGArwlTo52xmJE=; b=2oOXRFGYgBVas0nmaoYn6fVq9mTbTgKyiTMhNdCr2y0RAwgpoikIIqc2e1sv/72hPZ TjEQsnnEhJK7xcg/LK6RoQUXbeWKpFKGdAk8vOOH3W02BCVb1OgfthfnYU20CwUbC1YJ UJzTshFNsT2vCFhL84aVDjYhxHG9d9xp0uVONVUqZwCck2OvlxuD6UH1uYiy6jeQIaZO /1OPD/CFVGhpUfkqPd6LX9zyaga3jTUoVvPXgWuDkrzSoRUxtOyERXNDiSReAQ8yoXc6 HX8emxK4g0d7XtQXHhDgfaoHyP2ZmlpIoYjnIxs5r6nME2tPNg9ToQ2AE3XQ+5sQd4XF aEqg== X-Gm-Message-State: ACgBeo11mpJ297k7ZSp2gDvqEgjidjHuBEs1eTUsHG4NqmW05Vq8Fpju HC9ihbfHHiTlddJijoKAjYwKcw== X-Google-Smtp-Source: AA6agR7b94c55+5PcGQ4mvwKr29KdrQrmnMtYa3FW55aLKR5Sek4VoYW7Qzr0ON2EmiIYzQoabStaQ== X-Received: by 2002:a92:c005:0:b0:2eb:253c:c0bf with SMTP id q5-20020a92c005000000b002eb253cc0bfmr7080835ild.277.1661993609688; Wed, 31 Aug 2022 17:53:29 -0700 (PDT) Received: from pryzbyj.telsasoft (charmander.telsasoft.com. [50.244.222.1]) by smtp.gmail.com with ESMTPSA id x2-20020a056602160200b0067b7a057ee8sm8284229iow.25.2022.08.31.17.52.44 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Wed, 31 Aug 2022 17:52:54 -0700 (PDT) Received: by pryzbyj.telsasoft (Postfix, from userid 1000) id B6D8D800EB6; Wed, 31 Aug 2022 19:52:39 -0500 (CDT) Date: Wed, 31 Aug 2022 19:52:39 -0500 From: Justin Pryzby To: Thomas Munro Cc: "Shinoda, Noriyoshi (PN Japan FSIP)" , Tomas Vondra , Stephen Frost , Andres Freund , Jakub Wartak , Alvaro Herrera , Tomas Vondra , Dmitry Dolgov <9erthalion6@gmail.com>, David Steele , pgsql-hackers Subject: Re: pg15b3: recovery fails with wal prefetch enabled Message-ID: <20220901005239.GC31833@telsasoft.com> References: <20220831140128.GS31833@telsasoft.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.9.4 (2018-02-28) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On Thu, Sep 01, 2022 at 12:05:36PM +1200, Thomas Munro wrote: > On Thu, Sep 1, 2022 at 2:01 AM Justin Pryzby wrote: > > < 2022-08-31 08:44:10.495 CDT >LOG: checkpoint starting: end-of-recovery immediate wait > > < 2022-08-31 08:44:10.609 CDT >LOG: request to flush past end of generated WAL; request 1201/1CAF84F0, current position 1201/1CADB730 > > < 2022-08-31 08:44:10.609 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm > > < 2022-08-31 08:44:10.609 CDT >ERROR: xlog flush request 1201/1CAF84F0 is not satisfied --- flushed only to 1201/1CADB730 > > < 2022-08-31 08:44:10.609 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm > > < 2022-08-31 08:44:10.609 CDT >FATAL: checkpoint request failed > > > > I was able to start it with -c recovery_prefetch=no, so it seems like > > prefetch tried to do too much. The VM runs centos7 under qemu. > > I'm making a copy of the data dir in cases it's needed. > > Hmm, a page with an LSN set 118208 bytes past the end of WAL. It's a > vm fork page (which recovery prefetch should ignore completely). Did > you happen to get a copy before the successful recovery? After the > successful recovery, what LSN does that page have, and can you find > the references to it in the WAL with eg pg_waldump -R 1663/16681/2840 > -F vm? Have you turned FPW off (perhaps this is on ZFS?)? Yes, I have a copy that reproduces the issue: #1 0x00000000009a0df4 in errfinish (filename=, filename@entry=0xa15535 "xlog.c", lineno=lineno@entry=2671, funcname=funcname@entry=0xa1da27 <__func__.22763> "XLogFlush") at elog.c:588 #2 0x000000000055f1cf in XLogFlush (record=19795985532144) at xlog.c:2668 #3 0x0000000000813b24 in FlushBuffer (buf=0x7fffdf1f8900, reln=) at bufmgr.c:2889 #4 0x0000000000817a5b in SyncOneBuffer (buf_id=buf_id@entry=7796, skip_recently_used=skip_recently_used@entry=false, wb_context=wb_context@entry=0x7fffffffcdf0) at bufmgr.c:2576 #5 0x00000000008181c2 in BufferSync (flags=flags@entry=358) at bufmgr.c:2164 #6 0x00000000008182f5 in CheckPointBuffers (flags=flags@entry=358) at bufmgr.c:2743 #7 0x00000000005587b2 in CheckPointGuts (checkPointRedo=19795985413936, flags=flags@entry=358) at xlog.c:6855 #8 0x000000000055feb3 in CreateCheckPoint (flags=flags@entry=358) at xlog.c:6534 #9 0x00000000007aceaa in CheckpointerMain () at checkpointer.c:455 #10 0x00000000007aac52 in AuxiliaryProcessMain (auxtype=auxtype@entry=CheckpointerProcess) at auxprocess.c:153 #11 0x00000000007b0bd8 in StartChildProcess (type=) at postmaster.c:5430 #12 0x00000000007b388f in PostmasterMain (argc=argc@entry=7, argv=argv@entry=0xf139e0) at postmaster.c:1463 #13 0x00000000004986a6 in main (argc=7, argv=0xf139e0) at main.c:202 It's not on zfs, and FPW have never been turned off. I should add that this instance has been pg_upgraded since v10. BTW, base/16881 is the postgres DB )which has 43GB of logfiles imported from CSV, plus 2GB of snapshots of pg_control_checkpoint, pg_settings, pg_stat_bgwriter, pg_stat_database, pg_stat_wal). postgres=# SELECT * FROM page_header(get_raw_page('pg_toast.pg_toast_2619', 'main', 0)); lsn | checksum | flags | lower | upper | special | pagesize | version | prune_xid ---------------+----------+-------+-------+-------+---------+----------+---------+------------ 1201/1CDD1F98 | -6200 | 1 | 44 | 424 | 8192 | 8192 | 4 | 3681043287 (1 fila) postgres=# SELECT * FROM page_header(get_raw_page('pg_toast.pg_toast_2619', 'vm', 0)); lsn | checksum | flags | lower | upper | special | pagesize | version | prune_xid ---------------+----------+-------+-------+-------+---------+----------+---------+----------- 1201/1CAF84F0 | -6010 | 0 | 24 | 8192 | 8192 | 8192 | 4 | 0 I found this in waldump (note that you had a typoe - it's 16881). [pryzbyj@template0 ~]$ sudo /usr/pgsql-15/bin/pg_waldump -R 1663/16881/2840 -F vm -p /mnt/tmp/15/data/pg_wal 00000001000012010000001C rmgr: Heap2 len (rec/tot): 64/ 122, tx: 0, lsn: 1201/1CAF2658, prev 1201/1CAF2618, desc: VISIBLE cutoff xid 3681024856 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0 FPW, blkref #1: rel 1663/16881/2840 blk 54 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF3AF8, prev 1201/1CAF2788, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 0 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF3B70, prev 1201/1CAF3B38, desc: VISIBLE cutoff xid 3671427998 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 2 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF4DC8, prev 1201/1CAF3BB0, desc: VISIBLE cutoff xid 3672889900 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 4 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF5FB0, prev 1201/1CAF4E08, desc: VISIBLE cutoff xid 3679743844 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 5 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7320, prev 1201/1CAF5FF0, desc: VISIBLE cutoff xid 3679743844 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 6 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7398, prev 1201/1CAF7360, desc: VISIBLE cutoff xid 3679751919 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 11 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7410, prev 1201/1CAF73D8, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 17 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7488, prev 1201/1CAF7450, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 19 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7500, prev 1201/1CAF74C8, desc: VISIBLE cutoff xid 3645406844 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 23 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7578, prev 1201/1CAF7540, desc: VISIBLE cutoff xid 3669978567 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 24 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF75F0, prev 1201/1CAF75B8, desc: VISIBLE cutoff xid 0 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 25 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7668, prev 1201/1CAF7630, desc: VISIBLE cutoff xid 3681024856 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 26 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF76E0, prev 1201/1CAF76A8, desc: VISIBLE cutoff xid 3671911724 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 27 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7758, prev 1201/1CAF7720, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 34 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF77D0, prev 1201/1CAF7798, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 35 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7EF8, prev 1201/1CAF7810, desc: VISIBLE cutoff xid 3672408544 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 37 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7F70, prev 1201/1CAF7F38, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 38 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF7FE8, prev 1201/1CAF7FB0, desc: VISIBLE cutoff xid 2 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 39 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF8078, prev 1201/1CAF8040, desc: VISIBLE cutoff xid 3678237783 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 41 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF80F0, prev 1201/1CAF80B8, desc: VISIBLE cutoff xid 3672408544 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 42 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF8168, prev 1201/1CAF8130, desc: VISIBLE cutoff xid 3680789266 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 43 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF81E0, prev 1201/1CAF81A8, desc: VISIBLE cutoff xid 3667994218 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 44 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF8258, prev 1201/1CAF8220, desc: VISIBLE cutoff xid 3680789266 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 45 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF82D0, prev 1201/1CAF8298, desc: VISIBLE cutoff xid 3673830395 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 48 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF8348, prev 1201/1CAF8310, desc: VISIBLE cutoff xid 0 flags 0x03, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 50 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF83C0, prev 1201/1CAF8388, desc: VISIBLE cutoff xid 3681024856 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 51 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF8438, prev 1201/1CAF8400, desc: VISIBLE cutoff xid 3681024856 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 52 rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 1201/1CAF84B0, prev 1201/1CAF8478, desc: VISIBLE cutoff xid 3678741092 flags 0x01, blkref #0: rel 1663/16881/2840 fork vm blk 0, blkref #1: rel 1663/16881/2840 blk 53 pg_waldump: error: error en registro de WAL en 1201/1CD90E48: invalid record length at 1201/1CD91010: wanted 24, got 0 I could send our WAL to you if that's desirable .. -- Justin