Thread: PG17 optimizations to vacuum
Hello, While playing with optimizations to vacuum in v17 I can't understand how to measure this one: "Allow vacuum to more efficiently remove and freeze tuples". My test script and results: CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); CREATE INDEX t_id ON t(id); SET maintenance_work_mem = '1MB'; UPDATE t SET id = id + 1; VACUUM FREEZE VERBOSE t; v16.4 INFO: aggressively vacuuming "postgres.public.t" INFO: finished vacuuming "postgres.public.t": index scans: 21 pages: 0 removed, 30974 remain, 30974 scanned (100.00% of total) tuples: 3500000 removed, 3500000 remain, 0 are dead but not yet removable removable cutoff: 1675, which was 0 XIDs old when operation ended new relfrozenxid: 1675, which is 4 XIDs ahead of previous value frozen: 15488 pages from table (50.00% of total) had 3500000 tuples frozen index scan needed: 15487 pages from table (50.00% of total) had 3500000 dead item identifiers removed index "t_id": pages: 19196 in total, 0 newly deleted, 0 currently deleted, 0 reusable avg read rate: 473.207 MB/s, avg write rate: 92.511 MB/s buffer usage: 212718 hits, 267930 misses, 52380 dirtied WAL usage: 96585 records, 42819 full page images, 198029405 bytes system usage: CPU: user: 3.17 s, system: 0.48 s, elapsed: 4.42 s VACUUM master INFO: aggressively vacuuming "postgres.public.t" INFO: finished vacuuming "postgres.public.t": index scans: 1 pages: 0 removed, 30974 remain, 30974 scanned (100.00% of total) tuples: 3500000 removed, 3500000 remain, 0 are dead but not yet removable removable cutoff: 950, which was 0 XIDs old when operation ended new relfrozenxid: 950, which is 4 XIDs ahead of previous value frozen: 15488 pages from table (50.00% of total) had 3500000 tuples frozen index scan needed: 15487 pages from table (50.00% of total) had 3500000 dead item identifiers removed index "t_id": pages: 19196 in total, 0 newly deleted, 0 currently deleted, 0 reusable avg read rate: 101.121 MB/s, avg write rate: 120.530 MB/s buffer usage: 48900 hits, 47749 reads, 56914 dirtied WAL usage: 125391 records, 46626 full page images, 330547751 bytes system usage: CPU: user: 2.90 s, system: 0.27 s, elapsed: 3.68 s VACUUM I see a perfectly working TID-store optimization. With reduced maintenance_work_mem it used only one 'vacuuming indexes' phase instead of 21 in v16. But I also expected to see a reduction in the number of WAL records and the total size of the WAL. Instead, WAL numbers have significantly degraded. What am I doing wrong?
-- Pavel Luzanov Postgres Professional: https://postgrespro.com
On Sun, Sep 1, 2024 at 5:44 PM Pavel Luzanov <p.luzanov@postgrespro.ru> wrote: > I see a perfectly working TID-store optimization. > With reduced maintenance_work_mem it used only one 'vacuuming indexes' > phase instead of 21 in v16. > But I also expected to see a reduction in the number of WAL records > and the total size of the WAL. Instead, WAL numbers have significantly > degraded. > > What am I doing wrong? That does seem weird. CC'ing the authors of the relevant VACUUM enhancements. -- Peter Geoghegan
On Sun, Sep 1, 2024 at 6:00 PM Peter Geoghegan <pg@bowt.ie> wrote: > > On Sun, Sep 1, 2024 at 5:44 PM Pavel Luzanov <p.luzanov@postgrespro.ru> wrote: > > I see a perfectly working TID-store optimization. > > With reduced maintenance_work_mem it used only one 'vacuuming indexes' > > phase instead of 21 in v16. > > But I also expected to see a reduction in the number of WAL records > > and the total size of the WAL. Instead, WAL numbers have significantly > > degraded. > > > > What am I doing wrong? I'll investigate more tomorrow, but based on my initial investigation, there appears to be some interaction related to how much of the relation is in shared buffers after creating the table and updating it. If you set shared_buffers sufficiently high and prewarm the table after the update, master has fewer WAL records reported by vacuum verbose. - Melanie
On Mon, Sep 2, 2024 at 1:29 PM Melanie Plageman <melanieplageman@gmail.com> wrote: > I'll investigate more tomorrow, but based on my initial investigation, > there appears to be some interaction related to how much of the > relation is in shared buffers after creating the table and updating > it. If you set shared_buffers sufficiently high and prewarm the table > after the update, master has fewer WAL records reported by vacuum > verbose. Fewer of what specific kind of WAL record? All of the details about useful work done by VACUUM were identical across versions. It was only the details related to WAL, buffers, and CPU time that changed. Perhaps I'm not thinking of something obvious. Maybe it's extra VISIBILITY records? But I'd expect the number of VISIBILITY records to match the number of pages frozen, given these particulars. VACUUM VERBOSE at least shows that that hasn't changed. -- Peter Geoghegan
On Mon, Sep 2, 2024 at 1:47 PM Peter Geoghegan <pg@bowt.ie> wrote: > > On Mon, Sep 2, 2024 at 1:29 PM Melanie Plageman > <melanieplageman@gmail.com> wrote: > > I'll investigate more tomorrow, but based on my initial investigation, > > there appears to be some interaction related to how much of the > > relation is in shared buffers after creating the table and updating > > it. If you set shared_buffers sufficiently high and prewarm the table > > after the update, master has fewer WAL records reported by vacuum > > verbose. > > Fewer of what specific kind of WAL record? I would have expected to see no freeze records (since they no longer exist) and the same number of prune records. However, the overall number of records that I get for 16 and master is pretty similar. For some reason I stopped being able to reproduce Pavel's case. I'll work more on it tomorrow. This is roughly what I get for records by vacuum. Note that I prefixed VACUUM with BTREE on master to indicate those records are from index vacuuming. By default the headesc routine for records emitted by index vacuuming prints just VACUUM -- perhaps it would be better to prefix it. Note that these add up to almost the same thing. I don't know yet why the number PRUNE_VACUUM_SCAN is different than PRUNE on 16. PRUNE_VACUUM_SCAN and PRUNE + FREEZE_PAGE on 16 are similar. So, there must be pages that don't have items being pruned which are being frozen. I'll need to investigate further. master -- PRUNE_ON_ACCESS | 6 PRUNE_VACUUM_SCAN | 30974 PRUNE_VACUUM_CLEANUP | 14162 BTREE_VACUUM | 19127 16 -- PRUNE | 15504 FREEZE_PAGE | 13257 VACUUM | 34527 - Melanie
On Mon, Sep 2, 2024 at 3:23 PM Melanie Plageman <melanieplageman@gmail.com> wrote: > This is roughly what I get for records by vacuum. Note that I prefixed > VACUUM with BTREE on master to indicate those records are from index > vacuuming. By default the headesc routine for records emitted by index > vacuuming prints just VACUUM -- perhaps it would be better to prefix > it. > > Note that these add up to almost the same thing. I don't know yet why > the number PRUNE_VACUUM_SCAN is different than PRUNE on 16. That is indeed surprising, given that Pavel's VACUUM VERBOSE output indicates that the number of heap tuples deleted is identical across versions. The output also strongly suggests that the same heap pages are pruned on both versions, since the "index scan needed: " line is also identical across versions. Might it be that the extra PRUNE_VACUUM_SCAN records originated in pages that only contained existing LP_UNUSED items when scanned by VACUUM? -- Peter Geoghegan
On 02.09.2024 22:23, Melanie Plageman wrote:
For some reason I stopped being able to reproduce Pavel's case.
I repeated the test on another computer, but compared master with v15. The results are the same. The test can be simplified as follows: CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); CREATE INDEX t_id ON t(id); VACUUM FREEZE t; UPDATE t SET id = id + 1; VACUUM FREEZE VERBOSE t; My results (only line with WAL info from the last VACUUM command). master: WAL usage: 119583 records, 37231 full page images, 272631468 bytes v15: WAL usage: 96565 records, 47647 full page images, 217144602 bytes If it helps, without creating index on id column, the numbers will be much closer: master: WAL usage: 78502 records, 22090 full page images, 196215494 bytes v15: WAL usage: 77437 records, 30872 full page images, 152080268 bytes
-- Pavel Luzanov Postgres Professional: https://postgrespro.com
On 02/09/2024 23:35, Pavel Luzanov wrote: > On 02.09.2024 22:23, Melanie Plageman wrote: >> For some reason I stopped being able to reproduce Pavel's case. I also cannot reproduce this. > I repeated the test on another computer, but compared master with v15. > The results are the same. The test can be simplified as follows: > > CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); > INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); > CREATE INDEX t_id ON t(id); > VACUUM FREEZE t; > UPDATE t SET id = id + 1; > VACUUM FREEZE VERBOSE t; > > My results (only line with WAL info from the last VACUUM command). > > master: > WAL usage: 119583 records, 37231 full page images, 272631468 bytes > > v15: > WAL usage: 96565 records, 47647 full page images, 217144602 bytes Can you dump the stats with pg_waldump please. Something like: CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); CREATE INDEX t_id ON t(id); SET maintenance_work_mem = '1MB'; UPDATE t SET id = id + 1; select pg_current_wal_insert_lsn(); -- <<< PRINT WAL POS BEFORE VACUUM VACUUM FREEZE VERBOSE t; And then: pg_waldump -p data/pg_wal/ -s 1/F4474498 --stats=record where "1/F4474498" is the position printed by the "SELECT pg_current_wal_insert_lsn()" above. Do you have any non-default settings? "select name, current_setting(name), source from pg_settings where setting <> boot_val;" would show that. -- Heikki Linnakangas Neon (https://neon.tech)
On Mon, Sep 2, 2024 at 4:35 PM Pavel Luzanov <p.luzanov@postgrespro.ru> wrote: > If it helps, without creating index on id column, the numbers will be > much closer: Yes, avoiding all index vacuuming seems useful. It makes the test case cleaner, since we don't have to think about the variability from the TIDStore work (and from index vacuuming more generally). > master: > WAL usage: 78502 records, 22090 full page images, 196215494 bytes > > v15: > WAL usage: 77437 records, 30872 full page images, 152080268 bytes To be clear, I wouldn't be all that surprised if some issue with alignment padding and/or the new WAL format made master write more bytes of WAL total than on earlier versions. Small inefficiencies like that were always a possibility. That's not the problem that I'm principally concerned about right now. I'm most concerned about the simple fact that we're writing more individual WAL records than on previous versions, despite the fact that VACUUM does exactly the same amount of useful pruning and freezing work across versions. How could a patch that merged together the previous PRUNE and VACUUM WAL record types into a single record type actually cause an increase in the number of WAL records written? I'd have thought that that was simply impossible. -- Peter Geoghegan
On Mon, Sep 2, 2024 at 4:58 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote: > Do you have any non-default settings? "select name, > current_setting(name), source from pg_settings where setting <> > boot_val;" would show that. What about page checksums? One simple explanation is that we're writing extra FPIs to set hint bits. But that explanation only works if you assume that page-level checksums are in use (or that wal_log_hints is turned on). -- Peter Geoghegan
On 03/09/2024 00:01, Peter Geoghegan wrote: > On Mon, Sep 2, 2024 at 4:58 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote: >> Do you have any non-default settings? "select name, >> current_setting(name), source from pg_settings where setting <> >> boot_val;" would show that. > > What about page checksums? > > One simple explanation is that we're writing extra FPIs to set hint > bits. But that explanation only works if you assume that page-level > checksums are in use (or that wal_log_hints is turned on). Hmm, yeah, that might be it. With chceksums enabled, I see ~120k WAL records, vs ~90k without checksums. But there's no difference between v16 and master. Pavel, did you test v17 with checksums enabled and v16 with checksums disabled, by any chance? -- Heikki Linnakangas Neon (https://neon.tech)
On Mon, Sep 2, 2024 at 4:58 PM Peter Geoghegan <pg@bowt.ie> wrote: > On Mon, Sep 2, 2024 at 4:35 PM Pavel Luzanov <p.luzanov@postgrespro.ru> wrote: > > If it helps, without creating index on id column, the numbers will be > > much closer: > > Yes, avoiding all index vacuuming seems useful. It makes the test case > cleaner, since we don't have to think about the variability from the > TIDStore work (and from index vacuuming more generally). It just occurred to me that earlier versions don't have the HEAP_PAGE_PRUNE_MARK_UNUSED_NOW optimization added by commit c120550edb. Postgres 17 does have that optimization, though, so it should easily be able to write far fewer WAL records than earlier versions. And yet your revised no-indexes test case seems to show that Postgres 17 is doing slightly worse by that measure (and by others). -- Peter Geoghegan
On 03/09/2024 00:11, Heikki Linnakangas wrote: > On 03/09/2024 00:01, Peter Geoghegan wrote: >> On Mon, Sep 2, 2024 at 4:58 PM Heikki Linnakangas <hlinnaka@iki.fi> >> wrote: >>> Do you have any non-default settings? "select name, >>> current_setting(name), source from pg_settings where setting <> >>> boot_val;" would show that. >> >> What about page checksums? >> >> One simple explanation is that we're writing extra FPIs to set hint >> bits. But that explanation only works if you assume that page-level >> checksums are in use (or that wal_log_hints is turned on). > > Hmm, yeah, that might be it. With chceksums enabled, I see ~120k WAL > records, vs ~90k without checksums. But there's no difference between > v16 and master. Looking at the pg_waldump output from this test: > ... > rmgr: XLOG len (rec/tot): 49/ 8209, tx: 0, lsn: 0/FE052AA8, prev 0/FE0528A8, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/16396 blk 73 FPW > rmgr: Heap2 len (rec/tot): 507/ 507, tx: 0, lsn: 0/FE054AD8, prev 0/FE052AA8, desc: PRUNE snapshotConflictHorizon:754, nredirected: 0, ndead: 226, nunused: 0, redirected: [], dead: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10,11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40,41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70,71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100,101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124,125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144, 145, 146, 147, 148,149, 150, 151, 152, 153, 154, 155, 156, 157, 158, 159, 160, 161, 162, 163, 164, 165, 166, 167, 168, 169, 170, 171, 172,173, 174, 175, 176, 177, 178, 179, 180, 181, 182, 183, 184, 185, 186, 187, 188, 189, 190, 191, 192, 193, 194, 195, 196,197, 198, 199, 200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210, 211, 212, 213, 214, 215, 216, 217, 218, 219, 220,221, 222, 223, 224, 225, 226], unused: [], blkref #0: rel 1663/5/16396 blk 73 > rmgr: XLOG len (rec/tot): 49/ 8209, tx: 0, lsn: 0/FE054CD8, prev 0/FE054AD8, desc: FPI_FOR_HINT ,blkref #0: rel 1663/5/16396 blk 74 FPW > rmgr: Heap2 len (rec/tot): 507/ 507, tx: 0, lsn: 0/FE056D08, prev 0/FE054CD8, desc: PRUNE snapshotConflictHorizon:754, nredirected: 0, ndead: 226, nunused: 0, redirected: [], dead: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10,11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40,41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70,71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100,101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124,125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144, 145, 146, 147, 148,149, 150, 151, 152, 153, 154, 155, 156, 157, 158, 159, 160, 161, 162, 163, 164, 165, 166, 167, 168, 169, 170, 171, 172,173, 174, 175, 176, 177, 178, 179, 180, 181, 182, 183, 184, 185, 186, 187, 188, 189, 190, 191, 192, 193, 194, 195, 196,197, 198, 199, 200, 201, 202, 203, 204, 205, 206, 207, 208, 209, 210, 211, 212, 213, 214, 215, 216, 217, 218, 219, 220,221, 222, 223, 224, 225, 226], unused: [], blkref #0: rel 1663/5/16396 blk 74 > ... The pattern of WAL records with checksums enabled is silly: For each page, we first write an FPI record, an immediately after that a PRUNE record that removes all the tuples on it, leaving the page empty. This is the same with v16 and v17, but we certainly left money on the table by not folding that FPI into the VACUUM/PRUNE record. -- Heikki Linnakangas Neon (https://neon.tech)
On 03.09.2024 00:11, Heikki Linnakangas wrote:
Pavel, did you test v17 with checksums enabled and v16 with checksums disabled, by any chance?
Exactly, You are right! My v16 cluster comes from the default Ubuntu distribution. I forgot that checksums disabled by default. But when I initialize the master cluster, I automatically set -k option. More accurate results for the test: CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); VACUUM FREEZE t; UPDATE t SET id = id + 1; VACUUM FREEZE VERBOSE t; checksums disabled v16.4 WAL usage: 77437 records, 20832 full page images, 110654467 bytes master WAL usage: 61949 records, 20581 full page images, 92549229 bytes checksums enabled v16.4 WAL usage: 92848 records, 20985 full page images, 194863720 bytes master WAL usage: 76520 records, 20358 full page images, 181867154 bytes This a great optimization! Peter, Melanie, Heikki, Thank you very much for your help and time spent! Sorry for the noise before the release of PG17. ===== I don't think it's necessary anymore. But just in case. Non-default settings for v16 postgres@postgres(16.4)=# \dconfig List of non-default configuration parameters Parameter | Value ----------------------------+----------------------------------------- application_name | psql client_encoding | UTF8 cluster_name | 16/main config_file | /etc/postgresql/16/main/postgresql.conf data_directory | /var/lib/postgresql/16/main DateStyle | ISO, DMY default_text_search_config | pg_catalog.english external_pid_file | /var/run/postgresql/16-main.pid hba_file | /etc/postgresql/16/main/pg_hba.conf ident_file | /etc/postgresql/16/main/pg_ident.conf lc_messages | en_US.UTF-8 lc_monetary | ru_RU.UTF-8 lc_numeric | ru_RU.UTF-8 lc_time | ru_RU.UTF-8 log_line_prefix | %m [%p] %q%u@%d log_timezone | Europe/Moscow port | 5433 ssl | on ssl_cert_file | /etc/ssl/certs/ssl-cert-snakeoil.pem ssl_key_file | /etc/ssl/private/ssl-cert-snakeoil.key TimeZone | Europe/Moscow (21 rows) Building options and non-default settings for master: ./configure --silent --prefix=/home/pal/master --with-pgport=5401 --with-lz4 --with-icu --with-zstd --enable-nls --with-libxml --with-llvm make world --silent -j make --silent install-world initdb -k -U postgres postgres@postgres(18.0)=# \dconfig List of non-default configuration parameters Parameter | Value ----------------------------+--------------------------------------- application_name | psql client_encoding | UTF8 config_file | /home/pal/master/data/postgresql.conf data_directory | /home/pal/master/data DateStyle | ISO, DMY default_text_search_config | pg_catalog.english hba_file | /home/pal/master/data/pg_hba.conf ident_file | /home/pal/master/data/pg_ident.conf lc_messages | en_US.UTF-8 lc_monetary | ru_RU.UTF-8 lc_numeric | ru_RU.UTF-8 lc_time | ru_RU.UTF-8 log_timezone | Europe/Moscow TimeZone | Europe/Moscow (14 rows)
-- Pavel Luzanov Postgres Professional: https://postgrespro.com
On 03/09/2024 10:34, Pavel Luzanov wrote: > On 03.09.2024 00:11, Heikki Linnakangas wrote: >> Pavel, did you test v17 with checksums enabled and v16 with checksums >> disabled, by any chance? > > Exactly, You are right! > > My v16 cluster comes from the default Ubuntu distribution. > I forgot that checksums disabled by default. > But when I initialize the master cluster, I automatically set -k option. > > More accurate results for the test: > > CREATE TABLE t(id integer) WITH (autovacuum_enabled = off); > INSERT INTO t SELECT gen.id FROM generate_series(1,3_500_000) gen(id); > VACUUM FREEZE t; > UPDATE t SET id = id + 1; > VACUUM FREEZE VERBOSE t; > > checksums disabled > v16.4 WAL usage: 77437 records, 20832 full page images, 110654467 bytes > master WAL usage: 61949 records, 20581 full page images, 92549229 bytes > > checksums enabled > v16.4 WAL usage: 92848 records, 20985 full page images, 194863720 bytes > master WAL usage: 76520 records, 20358 full page images, 181867154 bytes That's more like it :-) > This a great optimization! > > Peter, Melanie, Heikki, > Thank you very much for your help and time spent! > Sorry for the noise before the release of PG17. Thanks for the testing! -- Heikki Linnakangas Neon (https://neon.tech)