Subject: Re: base backup vs. concurrent truncation

From: Aleksander Alekseev <[email-masked]>
Date: Fri, 21 Apr 2023 17:50:34 +0300

Hi,

Just a quick observation:

> basebackup.c's theory about relation truncation is that it doesn't
> really matter because WAL replay will fix things up. But in this case,
> I don't think it will, because WAL replay relies on the above
> invariant holding.

Assuming this is the case perhaps we can reduce the scenario and
consider this simpler one:

1. The table is truncated
2. The DBMS is killed before making a checkpoint
3. We are in recovery and presumably see a pair of 0.5 Gb segments

Or can't we?

-- 
Best regards,
Aleksander Alekseev

---

From: Aleksander Alekseev <[email-masked]>
Date: Fri, 21 Apr 2023 17:56:46 +0300

Hi again,

> 3. We are in recovery and presumably see a pair of 0.5 Gb segments

Oh, I see. If the process will be killed this perhaps is not going to
happen. Whether this can happen if we pull the plug from the machine
is probably a design implementation of the particular filesystem and
whether it's journaled.

Hm...

-- 
Best regards,
Aleksander Alekseev

---

From: Robert Haas <[email-masked]>
Date: Fri, 21 Apr 2023 11:03:07 -0400

> is probably a design implementation of the particular filesystem and

Right. I mentioned that scenario in the original email:

"Furthermore, I think that the problem could arise without performing a
backup at all: say that the server crashes on the OS level in
mid-truncation, and the truncation of segment 0 reaches disk but the
removal of segment 1 does not."

-- 
Robert Haas
EDB: http://www.enterprisedb.com

---

From: Aleksander Alekseev <[email-masked]>
Date: Sat, 22 Apr 2023 00:19:36 +0300

Hi,

> removal of segment 1 does not."

Right. I didn't fully understand this scenario at first.

I tried to reproduce it to see what actually happens. Here is what I did.

```
create table truncateme(id integer, val varchar(1024));
alter table truncateme set (autovacuum_enabled = off);

-- takes ~30 seconds
insert into truncateme
  select id,
  (
    select string_agg(chr((33+random()*(126-33)) :: integer), '')
    from generate_series(1,1000)
  )
  from generate_series(1,2*1024*1024) as id;

checkpoint;

select relfilenode from pg_class where relname = 'truncateme';
 relfilenode
-------------
       32778
```

We got 3 segments (and no VM fork since I disabled VACUUM):

```
$ cd ~/pginstall/data-master/base/16384/
$ ls -lah 32778*
-rw-------  1 eax  staff   1.0G Apr 21 23:47 32778
-rw-------  1 eax  staff   1.0G Apr 21 23:48 32778.1
-rw-------  1 eax  staff   293M Apr 21 23:48 32778.2
-rw-------  1 eax  staff   608K Apr 21 23:48 32778_fsm
```

Let's backup the last segment:

```
$ cp 32778.2 ~/temp/32778.2_backup
```

Truncate the table:

```
delete from truncateme where id > 1024*1024;
vacuum truncateme;
```

And kill Postgres:

```
$ pkill -9 postgres
```

... before it finishes another checkpoint:

```
LOG:  checkpoints are occurring too frequently (4 seconds apart)
HINT:  Consider increasing the configuration parameter "max_wal_size".
LOG:  checkpoint starting: wal
[and there was no "checkpoint complete"]
```

Next:

```
$ ls -lah 32778*
-rw-------  1 eax  staff   1.0G Apr 21 23:50 32778
-rw-------  1 eax  staff   146M Apr 21 23:50 32778.1
-rw-------  1 eax  staff     0B Apr 21 23:50 32778.2
-rw-------  1 eax  staff   312K Apr 21 23:50 32778_fsm
-rw-------  1 eax  staff    40K Apr 21 23:50 32778_vm

$ cp ~/temp/32778.2_backup ./32778.2
```

I believe this simulates the case when pg_basebackup did a checkpoint,
copied 32778.2 before the rest of the segments, Postgres did a
truncate, and pg_basebackup received the rest of the data including
WAL. The WAL contains the record about the truncation, see
RelationTruncate(). Just as an observation: we keep zero sized
segments instead of deleting them.

So if I start Postgres now I expect it to return to a consistent
state, ideally the same state it had before the crash in terms of the
segments.

What I actually get is:

```
LOG:  database system was interrupted; last known up at 2023-04-21 23:50:08 MSK
LOG:  database system was not properly shut down; automatic recovery in progress
LOG:  redo starts at 9/C4035B18
LOG:  invalid record length at 9/E8FCBF10: expected at least 24, got 0
LOG:  redo done at 9/E8FCBEB0 system usage: CPU: user: 1.58 s, system:
0.96 s, elapsed: 2.61 s
LOG:  checkpoint starting: end-of-recovery immediate wait
LOG:  checkpoint complete: wrote 10 buffers (0.0%); 0 WAL file(s)
added, 0 removed, 36 recycled; write=0.005 s, sync=0.003 s,
total=0.016 s; sync files=9, longest=0.002 s, average=0.001 s;
distance=605784 kB, estimate=605784 kB; lsn=9/E8FCBF10, redo
lsn=9/E8FCBF10
LOG:  database system is ready to accept connections
```

... and:

```
-rw-------  1 eax  staff   1.0G Apr 21 23:50 32778
-rw-------  1 eax  staff   146M Apr 21 23:53 32778.1
-rw-------  1 eax  staff     0B Apr 21 23:53 32778.2
```

Naturally the database is consistent too. So it looks like the
recovery protocol worked as expected after all, at least in the
upcoming PG16 and this specific scenario.

Did I miss anything? If not, perhaps we should just update the comments a bit?

-- 
Best regards,
Aleksander Alekseev

---

From: Robert Haas <[email-masked]>
Date: Mon, 24 Apr 2023 11:37:16 -0400

> Did I miss anything? If not, perhaps we should just update the comments a bit?

I was confused about what was happening here but after trying to
reproduce I think I figured it out. In my test, I saw the .1 file grow
to a full 1GB and then the truncate happened afterward.
Unsurprisingly, that works. I believe that what's happening here is
that the DELETE statement triggers FPIs for all of the blocks it
touches. Therefore, when the DELETE records are replayed, those blocks
get written back to the relation, extending it. That gets it up to the
required 1GB size after which the .2 file is visible to the smgr
again, so the truncate works fine. I think that to reproduce the
scenario, you want the truncate to happen in its own checkpoint cycle.

I also found out from Andres that he's complained about pretty much
the same problem just a couple of months ago:

https://www.postgresql.org/message-id/[email-masked]