MIME-Version: 1.0
From: Melanie Plageman <melanieplageman@gmail.com>
Date: Thu, 5 Dec 2024 11:07:52 -0500
Message-ID: <CAAKRu_ZvkxDRtMAhYRTK9N60jfMMVkiQgnEP5m_asYnuvgmQOg@mail.gmail.com>
Subject: Vacuum scans all-frozen pages with checksums enabled
To: Pg Hackers <pgsql-hackers@postgresql.org>
Cc: Andres Freund <andres@anarazel.de>
Content-Type: multipart/mixed; boundary="0000000000006df3670628881a84"
Archived-At: <https://www.postgresql.org/message-id/CAAKRu_ZvkxDRtMAhYRTK9N60jfMMVkiQgnEP5m_asYnuvgmQOg%40mail.gmail.com>
Precedence: bulk

--0000000000006df3670628881a84
Content-Type: text/plain; charset="UTF-8"

Hi,

I investigated what I thought was an issue with my patch to amortize
aggressive vacuum [1] and found some interesting behavior also present
on master. It seems vacuum will scan many all-frozen pages due to an
interaction between the opportunistic freeze heuristic and
SKIP_PAGES_THRESHOLD. This is not really an actionable finding (no
clear way to fix it) but I wanted to put a repro and analysis on the
mailing list in case anyone else ever notices this odd behavior.

Vacuum will opportunistically freeze a page if we just emitted an FPI
(or would emit one). This has a very peculiar interaction with several
other subsystems that can lead us to eventually scan huge numbers of
already frozen pages during vacuum.

In an insert-only workload, you would expect that because transaction
IDs mostly go from smaller to larger as block numbers become larger
that you would end up freezing contiguous ranges of pages once tuples'
xmins start being old enough.

However, we don't end up freezing contiguous ranges when checksums are enabled.

In an insert-only workload (like the one I provide at the bottom of
the email), the first time we vacuum a page is often when we set hint
bits. If checksums are enabled and this is the first time we are
dirtying the buffer since the last checkpoint, this will emit an FPI.
So, if bgwriter or checkpointer write out the page after the last
tuple is inserted to the page before the page is vacuumed, we will
likely emit an FPI when vacuuming it.

And because we opportunistically freeze pages if we emitted an FPI
setting their hint bits, we end up freezing a number of pages for this
reason.

What is interesting is that the ranges of contiguous frozen and
unfrozen pages are pretty small.

For example:

 start_block | end_block | nblocks | all_visible | all_frozen
-------------+-----------+---------+-------------+------------
     1396695 |   1396695 |       1 | t           | f
     1396696 |   1396710 |      14 | t           | t
     1396711 |   1396711 |       1 | t           | f
     1396712 |   1396730 |      18 | t           | t
     1396731 |   1396731 |       1 | t           | f
     1396732 |   1396758 |      26 | t           | t
     1396759 |   1396759 |       1 | t           | f
     1396760 |   1396767 |       7 | t           | t
     1396768 |   1396768 |       1 | t           | f

This fragmentation usually starts with the first vacuum after we have
dirtied enough buffers to provide work for bgwriter and at least one
checkpoint has happened. The most likely explanation is that because
bgwriter writes out buffers in the buffer clock order (not the order
the blocks are in the table), there are small random ranges of dirty
and clean buffers in the table. Combine that with checkpointer writing
out other buffers and the effect can be even more dramatic.

Here is some log output for the first vacuum after a checkpoint had
started (I patched master to print the number of hint bit fpis in
autovacuum log output):

automatic vacuum of table "melanieplageman.public.history":
pages: 0 removed, 605229 remain, 363538 scanned (60.07% of total)
frozen: 190990 pages from table (31.56% of total) had 10503305 tuples frozen
WAL usage: 745501 records, 205124 full page images, 190999 hint bit
fpis, 205494134 bytes

During an aggressive vacuum, all all-visible pages will be scanned
(because we must scan every unfrozen tuple to advance relfrozenxid).
All-frozen pages can be skipped. However, if the range of skippable
blocks is less than SKIP_PAGES_THRESHOLD (hard-coded to 32), then we
will scan these skippable blocks anyway -- on the assumption that
requesting small ranges from the kernel will mess with readahead.

The result of all of this is that aggressive vacuums may read large
numbers of frozen pages when checksums are enabled. Here is the
autovacuum logging output of one example (I've patched master to print
the pages scanned due to SKIP_PAGES_THRESHOLD and how many of those
are frozen):

automatic aggressive vacuum to prevent wraparound of table
"melanieplageman.public.history":
pages: 0 removed, 2454172 remain, 1437630 scanned (58.58% of total)
frozen skippable blocks scanned: 162335

As I said, I don't think we can do anything about this unless we find
a good alternative freeze heuristic (I've been trying and failing at
that for two years).

I attached a patch to log the frozen skippable blocks scanned by
vacuum and a repro.

- Melanie

--------
Repro:

The repro below includes a lot of GUCs that are required to get an
aggressive vacuum in a reasonable amount of time and see the effect.
It doesn't need to run for the full number of transactions to see the
effect -- just until the first aggressive vacuum of the history table.

psql -c "ALTER SYSTEM SET shared_buffers = '1GB';" \
      -c "ALTER SYSTEM SET log_checkpoints  = on;" \
      -c "ALTER SYSTEM SET max_wal_size = '150 GB';" \
      -c "ALTER SYSTEM SET min_wal_size = '150 GB';" \
      -c "ALTER SYSTEM SET autovacuum_naptime = 10;" \
      -c "ALTER SYSTEM SET log_autovacuum_min_duration = 0;" \
      -c "ALTER SYSTEM SET synchronous_commit = off;" \
      -c "ALTER SYSTEM SET checkpoint_timeout = '2min';" \
      -c "ALTER SYSTEM SET vacuum_cost_limit = 2000;" \
      -c "ALTER SYSTEM SET wal_compression = 'zstd';" \
      -c "ALTER SYSTEM SET wal_buffers = '2MB';" \
      -c "ALTER SYSTEM SET vacuum_freeze_min_age=10000000;" \
      -c "ALTER SYSTEM SET autovacuum_freeze_max_age=10000000;" \
      -c "ALTER SYSTEM SET vacuum_freeze_table_age=8000000;" \
      -c "ALTER SYSTEM SET autovacuum_vacuum_insert_scale_factor='0.01';" \
      -c "ALTER SYSTEM SET maintenance_work_mem = '1GB';" \
      -c "ALTER SYSTEM SET autovacuum_vacuum_insert_threshold=10000000;"

pg_ctl restart

psql -c "CREATE TABLE history( id BIGINT PRIMARY KEY GENERATED BY
DEFAULT AS IDENTITY, client_id INT NOT NULL, mtime TIMESTAMPTZ DEFAULT
NOW(), data TEXT);"

pgbench \
--random-seed=0 \
--no-vacuum \
-M prepared \
-c 8 \
-j 8 \
-t 11100000 \
-f- <<EOF
INSERT INTO history(client_id, data)
      VALUES
      (:client_id, repeat('a', 90)),
      (:client_id, repeat('b', 90)),
      (:client_id, repeat('c', 90)),
      (:client_id, repeat('d', 90)),
      (:client_id, repeat('e', 90)),
      (:client_id, repeat('f', 90)),
      (:client_id, repeat('g', 90)),
      (:client_id, repeat('h', 90)),
      (:client_id, repeat('i', 90)),
      (:client_id, repeat('j', 90));
EOF

[1] https://www.postgresql.org/message-id/flat/CAAKRu_ZF_KCzZuOrPrOqjGVe8iRVWEAJSpzMgRQs%3D5-v84cXUg%40mail.gmail.com

--0000000000006df3670628881a84
Content-Type: text/x-patch; charset="US-ASCII"; name="Track-skippable-blocks-scanned.patch"
Content-Disposition: attachment; 
	filename="Track-skippable-blocks-scanned.patch"
Content-Transfer-Encoding: base64
Content-ID: <f_m4bi625l0>
X-Attachment-Id: f_m4bi625l0

RnJvbSBjODYxZTc3ZDYyN2JlOGNjOGNmMmVkYTU0MGUxZjI2OGNlNDdlZDdiIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBNZWxhbmllIFBsYWdlbWFuIDxtZWxhbmllcGxhZ2VtYW5AZ21h
aWwuY29tPgpEYXRlOiBXZWQsIDQgRGVjIDIwMjQgMTY6NDA6MTYgLTA1MDAKU3ViamVjdDogW1BB
VENIXSBUcmFjayBza2lwcGFibGUgYmxvY2tzIHNjYW5uZWQKCkFkZCBjb3VudGVycyBhbmQgbG9n
Z2luZyB0byB2YWN1dW0gdG8gdHJhY2sgd2hhdCBza2lwcGFibGUgcGFnZXMgd2VyZQpzY2FubmVk
IGR1ZSB0byBTS0lQX1BBR0VTX1RIUkVTSE9MRCBhbmQgd2hpY2ggb2YgdGhvc2Ugd2VyZSBmcm96
ZW4uCi0tLQogc3JjL2JhY2tlbmQvYWNjZXNzL2hlYXAvdmFjdXVtbGF6eS5jIHwgMjMgKysrKysr
KysrKysrKysrKysrKysrKysKIDEgZmlsZSBjaGFuZ2VkLCAyMyBpbnNlcnRpb25zKCspCgpkaWZm
IC0tZ2l0IGEvc3JjL2JhY2tlbmQvYWNjZXNzL2hlYXAvdmFjdXVtbGF6eS5jIGIvc3JjL2JhY2tl
bmQvYWNjZXNzL2hlYXAvdmFjdXVtbGF6eS5jCmluZGV4IDZhMzU4OGNmODE3Li44YWY2NGUxYTcy
MCAxMDA2NDQKLS0tIGEvc3JjL2JhY2tlbmQvYWNjZXNzL2hlYXAvdmFjdXVtbGF6eS5jCisrKyBi
L3NyYy9iYWNrZW5kL2FjY2Vzcy9oZWFwL3ZhY3V1bWxhenkuYwpAQCAtMjE0LDYgKzIxNCw5IEBA
IHR5cGVkZWYgc3RydWN0IExWUmVsU3RhdGUKIAlCbG9ja051bWJlciBuZXh0X3Vuc2tpcHBhYmxl
X2Jsb2NrOyAvKiBuZXh0IHVuc2tpcHBhYmxlIGJsb2NrICovCiAJYm9vbAkJbmV4dF91bnNraXBw
YWJsZV9hbGx2aXM7CS8qIGl0cyB2aXNpYmlsaXR5IHN0YXR1cyAqLwogCUJ1ZmZlcgkJbmV4dF91
bnNraXBwYWJsZV92bWJ1ZmZlcjsJLyogYnVmZmVyIGNvbnRhaW5pbmcgaXRzIFZNIGJpdCAqLwor
CisJQmxvY2tOdW1iZXIgc2tpcHBhYmxlX2Jsb2Nrc19zY2FubmVkOworCUJsb2NrTnVtYmVyIGZy
b3plbl9za2lwcGFibGVfYmxvY2tzX3NjYW5uZWQ7CiB9IExWUmVsU3RhdGU7CiAKIC8qIFN0cnVj
dCBmb3Igc2F2aW5nIGFuZCByZXN0b3JpbmcgdmFjdXVtIGVycm9yIGluZm9ybWF0aW9uLiAqLwpA
QCAtNDI3LDYgKzQzMCw4IEBAIGhlYXBfdmFjdXVtX3JlbChSZWxhdGlvbiByZWwsIFZhY3V1bVBh
cmFtcyAqcGFyYW1zLAogCXZhY3JlbC0+bGl2ZV90dXBsZXMgPSAwOwogCXZhY3JlbC0+cmVjZW50
bHlfZGVhZF90dXBsZXMgPSAwOwogCXZhY3JlbC0+bWlzc2VkX2RlYWRfdHVwbGVzID0gMDsKKwl2
YWNyZWwtPnNraXBwYWJsZV9ibG9ja3Nfc2Nhbm5lZCA9IDA7CisJdmFjcmVsLT5mcm96ZW5fc2tp
cHBhYmxlX2Jsb2Nrc19zY2FubmVkID0gMDsKIAogCS8qCiAJICogR2V0IGN1dG9mZnMgdGhhdCBk
ZXRlcm1pbmUgd2hpY2ggZGVsZXRlZCB0dXBsZXMgYXJlIGNvbnNpZGVyZWQgREVBRCwKQEAgLTY2
NCw2ICs2NjksOSBAQCBoZWFwX3ZhY3V1bV9yZWwoUmVsYXRpb24gcmVsLCBWYWN1dW1QYXJhbXMg
KnBhcmFtcywKIAkJCQkJCQkgdmFjcmVsLT5zY2FubmVkX3BhZ2VzLAogCQkJCQkJCSBvcmlnX3Jl
bF9wYWdlcyA9PSAwID8gMTAwLjAgOgogCQkJCQkJCSAxMDAuMCAqIHZhY3JlbC0+c2Nhbm5lZF9w
YWdlcyAvIG9yaWdfcmVsX3BhZ2VzKTsKKwkJCWFwcGVuZFN0cmluZ0luZm8oJmJ1ZiwgXygic2tp
cHBhYmxlIGJsb2NrcyBzY2FubmVkOiAldS4gZnJvemVuIHNraXBwYWJsZSBibG9ja3Mgc2Nhbm5l
ZDogJXUuXG4iKSwKKwkJCQkJdmFjcmVsLT5za2lwcGFibGVfYmxvY2tzX3NjYW5uZWQsCisJCQkJ
CXZhY3JlbC0+ZnJvemVuX3NraXBwYWJsZV9ibG9ja3Nfc2Nhbm5lZCk7CiAJCQlhcHBlbmRTdHJp
bmdJbmZvKCZidWYsCiAJCQkJCQkJIF8oInR1cGxlczogJWxsZCByZW1vdmVkLCAlbGxkIHJlbWFp
biwgJWxsZCBhcmUgZGVhZCBidXQgbm90IHlldCByZW1vdmFibGVcbiIpLAogCQkJCQkJCSAobG9u
ZyBsb25nKSB2YWNyZWwtPnR1cGxlc19kZWxldGVkLApAQCAtMTE1MCwxMyArMTE1OCwyOCBAQCBo
ZWFwX3ZhY19zY2FuX25leHRfYmxvY2soTFZSZWxTdGF0ZSAqdmFjcmVsLCBCbG9ja051bWJlciAq
Ymxrbm8sCiAJLyogTm93IHdlIG11c3QgYmUgaW4gb25lIG9mIHRoZSB0d28gcmVtYWluaW5nIHN0
YXRlczogKi8KIAlpZiAobmV4dF9ibG9jayA8IHZhY3JlbC0+bmV4dF91bnNraXBwYWJsZV9ibG9j
aykKIAl7CisJCXVpbnQ4IHZtYml0cyA9IDA7CisJCUJ1ZmZlciB2bWJ1ZmZlciA9IEludmFsaWRC
dWZmZXI7CisKIAkJLyoKIAkJICogMi4gV2UgYXJlIHByb2Nlc3NpbmcgYSByYW5nZSBvZiBibG9j
a3MgdGhhdCB3ZSBjb3VsZCBoYXZlIHNraXBwZWQKIAkJICogYnV0IGNob3NlIG5vdCB0by4gIFdl
IGtub3cgdGhhdCB0aGV5IGFyZSBhbGwtdmlzaWJsZSBpbiB0aGUgVk0sCiAJCSAqIG90aGVyd2lz
ZSB0aGV5IHdvdWxkJ3ZlIGJlZW4gdW5za2lwcGFibGUuCiAJCSAqLworCQl2YWNyZWwtPnNraXBw
YWJsZV9ibG9ja3Nfc2Nhbm5lZCsrOworCiAJCSpibGtubyA9IHZhY3JlbC0+Y3VycmVudF9ibG9j
ayA9IG5leHRfYmxvY2s7CiAJCSphbGxfdmlzaWJsZV9hY2NvcmRpbmdfdG9fdm0gPSB0cnVlOwor
CisJCXZtYml0cyA9IHZpc2liaWxpdHltYXBfZ2V0X3N0YXR1cyh2YWNyZWwtPnJlbCwKKwkJCQl2
YWNyZWwtPmN1cnJlbnRfYmxvY2ssCisJCQkJJnZtYnVmZmVyKTsKKwkJaWYgKHZtYml0cyAmIFZJ
U0lCSUxJVFlNQVBfQUxMX0ZST1pFTikKKwkJCXZhY3JlbC0+ZnJvemVuX3NraXBwYWJsZV9ibG9j
a3Nfc2Nhbm5lZCsrOworCisJCWlmICh2bWJ1ZmZlciAhPSBJbnZhbGlkQnVmZmVyKQorCQkJUmVs
ZWFzZUJ1ZmZlcih2bWJ1ZmZlcik7CisKIAkJcmV0dXJuIHRydWU7CiAJfQogCWVsc2UKLS0gCjIu
MzQuMQoK
--0000000000006df3670628881a84--