Hi!
The same script was run, but using vacuum verbose analyze, and I saw the difference again in the fifth step: with your patch: buffer usage: 32312 hits, 607 misses, 1566 dirtied master: buffer usage: 32346 hits, 573 misses, 1360 dirtiedIsn't there a chance for the checkpointer to run during this time? That could make the conditions between the two runs slightly different and explain the change in buffer report.[0] https://github.com/postgres/postgres/blob/8a1b31e6e59631807a08a4e9465134c343bbdf5e/src/backend/access/heap/vacuumlazy.c#L2826-L2831Looking at the script, you won't trigger the problem.
Thank you for the link I accounted it in my next experiments.I repeated the test without processing checkpoints with a single index, and the number of pages in the buffer used almost matched:
master branch: buffer usage: 32315 hits, 606 misses, 4486 dirtiedwith applied patch v4 version: buffer usage: 32315 hits, 606 misses, 4489 dirtied
I think you are right - the problem was interfering with the checkpoint process, by the way I checked the first version patch. To cut a long story short, everything is fine now with one index.
Just in case, I'll explain: I considered this case because your patch could have impact influenced it too.
On 25.04.2024 10:17, Anthonin Bonnefoy wrote:
On Wed, Apr 24, 2024 at 4:01 PM Alena Rybakina <lena.riback...@yandex.ru> wrote:I tested the main postgres branch with and without your fix using a script that was written by me. It consists of five scenarios and I made a comparison in the logs between the original version of the master branch and the master branch with your patch: Hi! Thanks for the tests. I have attached a test file (vacuum_check_logs.sql)The reporting issue will only happen if there's a parallel index vacuum and it will only happen if there's at least 2 indexes [0]. You will need to create an additional index.
Speaking of the problem, I added another index and repeated the test and found a significant difference:
* I found it when I commited the transaction (3): master: 2964hits, 0misses, 0dirtied with applied patch v4 version: buffer usage: 33013hits, 0misses, 3dirtied * When I deleted all the data from the table and later started vacuum verbose again (4): master: buffer usage: 51486hits, 0misses, 0dirtied with applied patch v4 version:buffer usage: 77924hits, 0misses, 0dirtied * when I inserted 1 million data into the table and updated it (5): master:buffer usage: 27904hits, 5021misses, 1777dirtiedwith applied patch v4 version:buffer usage: 41051hits, 9973misses, 2564dirtied
As I see, the number of pages is significantly more than it was in the master branch and ,frankly, I couldn't fully figure out if it was a mistake or not.
I attached a test script (vacuum_checks_logs.sql) with two indexes and no checkpoints, I also attached log files: the first one (vacuum_test) is the result of testing on the master branch, the second file with your applied patch (vacuum_test_v4).
-- Regards, Alena Rybakina Postgres Professional:http://www.postgrespro.com The Russian Postgres Company
vacuum_check_logs.sql
Description: application/sql
postgres=# \i ~/vacuum_check_logs.sql psql:/home/alena/vacuum_check_logs.sql:2: ERROR: extension "dblink" does not exist CREATE EXTENSION dblink_connect ---------------- OK (1 row) psql:/home/alena/vacuum_check_logs.sql:5: ERROR: table "vestat" does not exist SET SET CREATE TABLE CREATE INDEX CREATE INDEX psql:/home/alena/vacuum_check_logs.sql:16: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:16: INFO: finished vacuuming "postgres.public.vestat": index scans: 0 pages: 0 removed, 0 remain, 0 scanned (100.00% of total) tuples: 0 removed, 0 remain, 0 are dead but not yet removable removable cutoff: 742, which was 0 XIDs old when operation ended new relfrozenxid: 742, which is 3 XIDs ahead of previous value frozen: 0 pages from table (100.00% of total) had 0 tuples frozen index scan not needed: 0 pages from table (100.00% of total) had 0 dead item identifiers removed I/O timings: read: 0.049 ms, write: 0.000 ms avg read rate: 40.584 MB/s, avg write rate: 0.000 MB/s buffer usage: 23 hits, 2 misses, 0 dirtied WAL usage: 1 records, 0 full page images, 237 bytes system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 DELETE 100000 psql:/home/alena/vacuum_check_logs.sql:25: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:25: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:25: INFO: table "vestat": truncated 3922 to 3530 pages psql:/home/alena/vacuum_check_logs.sql:25: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 392 removed, 3530 remain, 3922 scanned (100.00% of total) tuples: 100000 removed, 900000 remain, 0 are dead but not yet removable removable cutoff: 744, which was 1 XIDs old when operation ended frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 393 pages from table (10.02% of total) had 100000 dead item identifiers removed index "vestat_idx": pages: 2197 in total, 218 newly deleted, 218 currently deleted, 0 reusable index "vestat_idx1": pages: 785 in total, 77 newly deleted, 77 currently deleted, 0 reusable I/O timings: read: 0.000 ms, write: 0.046 ms avg read rate: 0.000 MB/s, avg write rate: 0.054 MB/s buffer usage: 13990 hits, 0 misses, 4 dirtied WAL usage: 5604 records, 1 full page images, 946934 bytes system usage: CPU: user: 0.44 s, system: 0.00 s, elapsed: 0.57 s VACUUM pg_sleep ---------- (1 row) dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:/home/alena/vacuum_check_logs.sql:38: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:38: INFO: launched 1 parallel vacuum worker for index cleanup (planned: 1) psql:/home/alena/vacuum_check_logs.sql:38: INFO: finished vacuuming "postgres.public.vestat": index scans: 0 pages: 0 removed, 7512 remain, 7512 scanned (100.00% of total) tuples: 0 removed, 1800000 remain, 900000 are dead but not yet removable removable cutoff: 745, which was 1 XIDs old when operation ended frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 0 newly deleted, 218 currently deleted, 218 reusable I/O timings: read: 0.000 ms, write: 0.056 ms avg read rate: 0.000 MB/s, avg write rate: 0.041 MB/s buffer usage: 19425 hits, 0 misses, 4 dirtied WAL usage: 2 records, 0 full page images, 309 bytes system usage: CPU: user: 0.55 s, system: 0.00 s, elapsed: 0.76 s VACUUM pg_sleep ---------- (1 row) dblink_exec ------------- COMMIT (1 row) psql:/home/alena/vacuum_check_logs.sql:45: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:45: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:45: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 0 removed, 7512 remain, 7512 scanned (100.00% of total) tuples: 900000 removed, 900000 remain, 0 are dead but not yet removable removable cutoff: 746, which was 0 XIDs old when operation ended new relfrozenxid: 745, which is 3 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3530 pages from table (46.99% of total) had 900000 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 0 newly deleted, 218 currently deleted, 218 reusable index "vestat_idx1": pages: 4342 in total, 703 newly deleted, 780 currently deleted, 77 reusable I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 0.010 MB/s buffer usage: 33013 hits, 0 misses, 3 dirtied WAL usage: 20621 records, 0 full page images, 9097649 bytes system usage: CPU: user: 2.19 s, system: 0.00 s, elapsed: 2.43 s VACUUM pg_sleep ---------- (1 row) DELETE 900000 psql:/home/alena/vacuum_check_logs.sql:52: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:52: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:52: INFO: table "vestat": truncated 7512 to 0 pages psql:/home/alena/vacuum_check_logs.sql:52: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 7512 removed, 0 remain, 3983 scanned (53.02% of total) tuples: 900000 removed, 422804 remain, 0 are dead but not yet removable removable cutoff: 747, which was 1 XIDs old when operation ended new relfrozenxid: 747, which is 2 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3983 pages from table (53.02% of total) had 900000 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 3949 newly deleted, 4167 currently deleted, 218 reusable index "vestat_idx1": pages: 4342 in total, 3558 newly deleted, 4338 currently deleted, 780 reusable I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s buffer usage: 77924 hits, 0 misses, 0 dirtied WAL usage: 34428 records, 0 full page images, 9439566 bytes system usage: CPU: user: 0.56 s, system: 0.00 s, elapsed: 1.05 s VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 UPDATE 1000000 psql:/home/alena/vacuum_check_logs.sql:61: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:61: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:61: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 0 removed, 8347 remain, 8347 scanned (100.00% of total) tuples: 1000000 removed, 1000000 remain, 0 are dead but not yet removable removable cutoff: 750, which was 0 XIDs old when operation ended new relfrozenxid: 749, which is 2 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3922 pages from table (46.99% of total) had 1000000 dead item identifiers removed index "vestat_idx": pages: 8341 in total, 0 newly deleted, 3949 currently deleted, 3949 reusable index "vestat_idx1": pages: 8295 in total, 780 newly deleted, 4338 currently deleted, 3558 reusable I/O timings: read: 39.594 ms, write: 8.168 ms avg read rate: 22.641 MB/s, avg write rate: 5.821 MB/s buffer usage: 41051 hits, 9973 misses, 2564 dirtied WAL usage: 22911 records, 157 full page images, 11330823 bytes system usage: CPU: user: 2.63 s, system: 0.03 s, elapsed: 3.44 s VACUUM pg_sleep ---------- (1 row)
postgres=# \i ~/vacuum_check_logs.sql psql:/home/alena/vacuum_check_logs.sql:2: ERROR: extension "dblink" does not exist CREATE EXTENSION dblink_connect ---------------- OK (1 row) psql:/home/alena/vacuum_check_logs.sql:5: ERROR: table "vestat" does not exist SET SET CREATE TABLE CREATE INDEX CREATE INDEX psql:/home/alena/vacuum_check_logs.sql:16: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:16: INFO: finished vacuuming "postgres.public.vestat": index scans: 0 pages: 0 removed, 0 remain, 0 scanned (100.00% of total) tuples: 0 removed, 0 remain, 0 are dead but not yet removable removable cutoff: 742, which was 0 XIDs old when operation ended new relfrozenxid: 742, which is 3 XIDs ahead of previous value frozen: 0 pages from table (100.00% of total) had 0 tuples frozen index scan not needed: 0 pages from table (100.00% of total) had 0 dead item identifiers removed I/O timings: read: 0.039 ms, write: 0.000 ms avg read rate: 40.271 MB/s, avg write rate: 0.000 MB/s buffer usage: 23 hits, 2 misses, 0 dirtied WAL usage: 1 records, 0 full page images, 237 bytes system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 DELETE 100000 psql:/home/alena/vacuum_check_logs.sql:25: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:25: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:25: INFO: table "vestat": truncated 3922 to 3530 pages psql:/home/alena/vacuum_check_logs.sql:25: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 392 removed, 3530 remain, 3922 scanned (100.00% of total) tuples: 100000 removed, 900000 remain, 0 are dead but not yet removable removable cutoff: 744, which was 1 XIDs old when operation ended frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 393 pages from table (10.02% of total) had 100000 dead item identifiers removed index "vestat_idx": pages: 2197 in total, 218 newly deleted, 218 currently deleted, 0 reusable index "vestat_idx1": pages: 785 in total, 77 newly deleted, 77 currently deleted, 0 reusable I/O timings: read: 0.000 ms, write: 0.041 ms avg read rate: 0.000 MB/s, avg write rate: 0.053 MB/s buffer usage: 12589 hits, 0 misses, 4 dirtied WAL usage: 5604 records, 1 full page images, 946934 bytes system usage: CPU: user: 0.45 s, system: 0.00 s, elapsed: 0.58 s VACUUM pg_sleep ---------- (1 row) dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:/home/alena/vacuum_check_logs.sql:38: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:38: INFO: launched 1 parallel vacuum worker for index cleanup (planned: 1) psql:/home/alena/vacuum_check_logs.sql:38: INFO: finished vacuuming "postgres.public.vestat": index scans: 0 pages: 0 removed, 7512 remain, 7512 scanned (100.00% of total) tuples: 0 removed, 1800000 remain, 900000 are dead but not yet removable removable cutoff: 745, which was 1 XIDs old when operation ended frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 0 newly deleted, 218 currently deleted, 218 reusable I/O timings: read: 0.000 ms, write: 0.056 ms avg read rate: 0.000 MB/s, avg write rate: 0.041 MB/s buffer usage: 19424 hits, 0 misses, 4 dirtied WAL usage: 2 records, 0 full page images, 309 bytes system usage: CPU: user: 0.55 s, system: 0.00 s, elapsed: 0.75 s VACUUM pg_sleep ---------- (1 row) dblink_exec ------------- COMMIT (1 row) psql:/home/alena/vacuum_check_logs.sql:45: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:45: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:45: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 0 removed, 7512 remain, 7512 scanned (100.00% of total) tuples: 900000 removed, 900000 remain, 0 are dead but not yet removable removable cutoff: 746, which was 0 XIDs old when operation ended new relfrozenxid: 745, which is 3 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3530 pages from table (46.99% of total) had 900000 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 0 newly deleted, 218 currently deleted, 218 reusable index "vestat_idx1": pages: 4342 in total, 703 newly deleted, 780 currently deleted, 77 reusable I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s buffer usage: 22964 hits, 0 misses, 0 dirtied WAL usage: 20621 records, 0 full page images, 9097649 bytes system usage: CPU: user: 2.35 s, system: 0.00 s, elapsed: 2.59 s VACUUM pg_sleep ---------- (1 row) DELETE 900000 psql:/home/alena/vacuum_check_logs.sql:52: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:52: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:52: INFO: table "vestat": truncated 7512 to 0 pages psql:/home/alena/vacuum_check_logs.sql:52: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 7512 removed, 0 remain, 3983 scanned (53.02% of total) tuples: 900000 removed, 422804 remain, 0 are dead but not yet removable removable cutoff: 747, which was 1 XIDs old when operation ended new relfrozenxid: 747, which is 2 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3983 pages from table (53.02% of total) had 900000 dead item identifiers removed index "vestat_idx": pages: 4171 in total, 3949 newly deleted, 4167 currently deleted, 218 reusable index "vestat_idx1": pages: 4342 in total, 3558 newly deleted, 4338 currently deleted, 780 reusable I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s buffer usage: 51486 hits, 0 misses, 0 dirtied WAL usage: 34428 records, 0 full page images, 9439566 bytes system usage: CPU: user: 0.55 s, system: 0.01 s, elapsed: 1.04 s VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 UPDATE 1000000 psql:/home/alena/vacuum_check_logs.sql:61: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:61: INFO: launched 1 parallel vacuum worker for index vacuuming (planned: 1) psql:/home/alena/vacuum_check_logs.sql:61: INFO: finished vacuuming "postgres.public.vestat": index scans: 1 pages: 0 removed, 8347 remain, 8347 scanned (100.00% of total) tuples: 1000000 removed, 1000000 remain, 0 are dead but not yet removable removable cutoff: 750, which was 0 XIDs old when operation ended new relfrozenxid: 749, which is 2 XIDs ahead of previous value frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3922 pages from table (46.99% of total) had 1000000 dead item identifiers removed index "vestat_idx": pages: 8341 in total, 0 newly deleted, 3949 currently deleted, 3949 reusable index "vestat_idx1": pages: 8295 in total, 780 newly deleted, 4338 currently deleted, 3558 reusable I/O timings: read: 29.939 ms, write: 8.233 ms avg read rate: 10.658 MB/s, avg write rate: 3.772 MB/s buffer usage: 27904 hits, 5021 misses, 1777 dirtied WAL usage: 22911 records, 151 full page images, 11283585 bytes system usage: CPU: user: 2.88 s, system: 0.02 s, elapsed: 3.68 s VACUUM pg_sleep ---------- (1 row)
