On 22.04.2024 11:07, Anthonin Bonnefoy wrote:
On Sat, Apr 20, 2024 at 2:00 PM Alena Rybakina <lena.riback...@yandex.ru> wrote:Hi, thank you for your work with this subject. While I was reviewing your code, I noticed that your patch conflicts with another patch [0] that been committed. [0] https://www.postgresql.org/message-id/flat/CA%2BhUKGJkOiOCa%2Bmag4BF%2BzHo7qo%3Do9CFheB8%3Dg6uT5TUm2gkvA%40mail.gmail.com I've rebased the patch and also split the changes: 1: Use pgBufferUsage in Vacuum and Analyze block reporting2: Stop tracking buffer usage in the now unused Vacuum{Hit,Miss,Dirty} variables3: Remove declarations of Vacuum{Hit,Miss,Dirty}
Hi! Thank you for your work, and I have reviewed your corrections.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:
1. I added 1 million data to the table and deleted 10% of them. I ran vacuum verbose and didn't see any differences.
buffer usage: 12585 hits, 0 misses, 4 dirtied2. I opened another connection with a repeatable read transaction through the dblink extension and launched a query updating the records in the table under test. Later, I ran vacuum verbose again and also didn't see any differences.
buffer usage: 19424 hits, 0 misses, 6 dirtied3. I commited transaction and ran vacuum verbose again. Everything is fine in the logs.
buffer usage: 22960 hits, 0 misses, 11456 dirtied4. I deleted all the data from the table and later started vacuum verbose again. The number of pages in the buffer matched with your patch too. 5.I inserted 1 million data into the table and updated it, and I found the difference between the original master version and the version with your patch:
with your patch: buffer usage: 32315 hits, 606 misses, 1547 dirtied original version: buffer usage: 32348 hits, 573 misses, 1456 dirtied I suppose, something wasn't calculated.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 dirtiedI have attached a test file (vacuum_check_logs.sql) and four log files: two with the vacuum verbose command (vacuum_log and vacuum_log_with_patch files) and two others with the vacuum verbose analyze command (vacuum_analyze_test_with_patch and vacuum_analyze_test files). Both test approaches show logs with and without your changes.
I agree with that. I think we can leave these changes to the analysis command for master, but I also doubt the need to backport his changes to back versions.1: Use pgBufferUsage in Vacuum and Analyze block reportingI think that if the anayze command doesn't have the same issue, we don't need to change it. Making the vacuum and the analyze consistent is a good point but I'd like to avoid doing unnecessary changes in back branches. I think the patch set would contain: (a) make lazy vacuum use BufferUsage instead of VacuumPage{Hit,Miss,Dirty}. (backpatched down to pg13). (b) make analyze use BufferUsage and remove VacuumPage{Hit,Miss,Dirty} variables for consistency and simplicity (only for HEAD, if we agree). BTW I realized that VACUUM VERBOSE running on a temp table always shows the number of dirtied buffers being 0, which seems to be a bug. The patch (a) will resolve it as well.
-- Regards, Alena Rybakina Postgres Professional:http://www.postgrespro.com The Russian Postgres Company
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 psql:/home/alena/vacuum_check_logs.sql:15: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:15: 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: 741, which was 0 XIDs old when operation ended new relfrozenxid: 741, which is 2 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.100 ms, write: 0.000 ms avg read rate: 29.260 MB/s, avg write rate: 0.000 MB/s buffer usage: 13 hits, 1 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:24: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:24: INFO: table "vestat": truncated 3922 to 3530 pages psql:/home/alena/vacuum_check_logs.sql:24: 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: 743, 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 I/O timings: read: 0.000 ms, write: 0.029 ms avg read rate: 0.000 MB/s, avg write rate: 0.062 MB/s buffer usage: 12585 hits, 0 misses, 4 dirtied WAL usage: 5369 records, 1 full page images, 928676 bytes system usage: CPU: user: 0.37 s, system: 0.00 s, elapsed: 0.50 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:/home/alena/vacuum_check_logs.sql:37: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:37: 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: 744, 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.058 ms avg read rate: 0.000 MB/s, avg write rate: 0.066 MB/s buffer usage: 19424 hits, 0 misses, 6 dirtied WAL usage: 2 records, 1 full page images, 1529 bytes system usage: CPU: user: 0.50 s, system: 0.00 s, elapsed: 0.71 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- COMMIT (1 row) psql:/home/alena/vacuum_check_logs.sql:44: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:44: 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: 745, which was 0 XIDs old when operation ended new relfrozenxid: 744, which is 3 XIDs ahead of previous value frozen: 1 pages from table (0.01% of total) had 133 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 18.227 MB/s buffer usage: 22960 hits, 0 misses, 11456 dirtied WAL usage: 18513 records, 7471 full page images, 21157546 bytes system usage: CPU: user: 2.28 s, system: 0.00 s, elapsed: 4.91 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT DELETE 900000 psql:/home/alena/vacuum_check_logs.sql:51: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:51: INFO: table "vestat": truncated 7512 to 0 pages psql:/home/alena/vacuum_check_logs.sql:51: 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: 746, which was 1 XIDs old when operation ended new relfrozenxid: 746, 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 16.897 MB/s buffer usage: 51482 hits, 0 misses, 3958 dirtied WAL usage: 23781 records, 3954 full page images, 14444904 bytes system usage: CPU: user: 0.53 s, system: 0.01 s, elapsed: 1.83 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT INSERT 0 1000000 UPDATE 1000000 psql:/home/alena/vacuum_check_logs.sql:60: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:60: 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: 749, which was 0 XIDs old when operation ended new relfrozenxid: 748, 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 I/O timings: read: 3.803 ms, write: 1.315 ms avg read rate: 1.365 MB/s, avg write rate: 3.484 MB/s buffer usage: 32315 hits, 606 misses, 1547 dirtied WAL usage: 20571 records, 2 full page images, 9938566 bytes system usage: CPU: user: 2.78 s, system: 0.01 s, elapsed: 3.46 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT
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 psql:/home/alena/vacuum_check_logs.sql:15: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:15: 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: 741, which was 0 XIDs old when operation ended new relfrozenxid: 741, which is 2 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.092 ms, write: 0.000 ms avg read rate: 32.964 MB/s, avg write rate: 0.000 MB/s buffer usage: 13 hits, 1 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:24: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:24: INFO: table "vestat": truncated 3922 to 3530 pages psql:/home/alena/vacuum_check_logs.sql:24: 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: 743, 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 I/O timings: read: 0.000 ms, write: 0.033 ms avg read rate: 0.000 MB/s, avg write rate: 0.057 MB/s buffer usage: 12585 hits, 0 misses, 4 dirtied WAL usage: 5369 records, 1 full page images, 928676 bytes system usage: CPU: user: 0.42 s, system: 0.00 s, elapsed: 0.54 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:/home/alena/vacuum_check_logs.sql:37: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:37: 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: 744, 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.043 ms avg read rate: 0.000 MB/s, avg write rate: 0.062 MB/s buffer usage: 19424 hits, 0 misses, 6 dirtied WAL usage: 2 records, 1 full page images, 1529 bytes system usage: CPU: user: 0.55 s, system: 0.00 s, elapsed: 0.75 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- COMMIT (1 row) psql:/home/alena/vacuum_check_logs.sql:44: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:44: 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: 745, which was 0 XIDs old when operation ended new relfrozenxid: 744, which is 3 XIDs ahead of previous value frozen: 1 pages from table (0.01% of total) had 133 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 18.654 MB/s buffer usage: 22960 hits, 0 misses, 11456 dirtied WAL usage: 18513 records, 7471 full page images, 21157546 bytes system usage: CPU: user: 2.19 s, system: 0.00 s, elapsed: 4.79 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT DELETE 900000 psql:/home/alena/vacuum_check_logs.sql:51: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:51: INFO: table "vestat": truncated 7512 to 0 pages psql:/home/alena/vacuum_check_logs.sql:51: 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: 746, which was 1 XIDs old when operation ended new relfrozenxid: 746, 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 16.985 MB/s buffer usage: 51482 hits, 0 misses, 3958 dirtied WAL usage: 23781 records, 3954 full page images, 14444904 bytes system usage: CPU: user: 0.52 s, system: 0.01 s, elapsed: 1.82 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT INSERT 0 1000000 UPDATE 1000000 psql:/home/alena/vacuum_check_logs.sql:60: INFO: vacuuming "postgres.public.vestat" psql:/home/alena/vacuum_check_logs.sql:60: 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: 749, which was 0 XIDs old when operation ended new relfrozenxid: 748, 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 I/O timings: read: 3.922 ms, write: 1.230 ms avg read rate: 1.336 MB/s, avg write rate: 3.396 MB/s buffer usage: 32348 hits, 573 misses, 1456 dirtied WAL usage: 20571 records, 2 full page images, 9938566 bytes system usage: CPU: user: 2.69 s, system: 0.01 s, elapsed: 3.34 s VACUUM pg_sleep ---------- (1 row) CHECKPOINT
postgres=# \i vacuum_test_analyze.sql psql:vacuum_test_analyze.sql:2: ERROR: extension "dblink" does not exist CREATE EXTENSION dblink_connect ---------------- OK (1 row) psql:vacuum_test_analyze.sql:5: ERROR: table "vestat" does not exist SET SET CREATE TABLE CREATE INDEX psql:vacuum_test_analyze.sql:15: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:15: 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: 741, which was 0 XIDs old when operation ended new relfrozenxid: 741, which is 2 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.111 ms, write: 0.000 ms avg read rate: 28.617 MB/s, avg write rate: 0.000 MB/s buffer usage: 13 hits, 1 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 psql:vacuum_test_analyze.sql:15: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:15: INFO: "vestat": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 DELETE 100000 psql:vacuum_test_analyze.sql:24: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:24: INFO: table "vestat": truncated 3922 to 3530 pages psql:vacuum_test_analyze.sql:24: 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: 743, 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 I/O timings: read: 0.000 ms, write: 0.029 ms avg read rate: 0.000 MB/s, avg write rate: 0.060 MB/s buffer usage: 12583 hits, 0 misses, 4 dirtied WAL usage: 5369 records, 1 full page images, 928676 bytes system usage: CPU: user: 0.39 s, system: 0.00 s, elapsed: 0.52 s psql:vacuum_test_analyze.sql:24: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:24: INFO: "vestat": scanned 3530 of 3530 pages, containing 900000 live rows and 0 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:vacuum_test_analyze.sql:37: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:37: 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.055 ms avg read rate: 0.000 MB/s, avg write rate: 0.063 MB/s buffer usage: 19424 hits, 0 misses, 6 dirtied WAL usage: 2 records, 1 full page images, 1529 bytes system usage: CPU: user: 0.53 s, system: 0.00 s, elapsed: 0.73 s psql:vacuum_test_analyze.sql:37: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:37: INFO: "vestat": scanned 7512 of 7512 pages, containing 900000 live rows and 900000 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- COMMIT (1 row) psql:vacuum_test_analyze.sql:44: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:44: 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: 747, which was 0 XIDs old when operation ended new relfrozenxid: 745, which is 4 XIDs ahead of previous value frozen: 1 pages from table (0.01% of total) had 133 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 18.429 MB/s buffer usage: 22962 hits, 0 misses, 11456 dirtied WAL usage: 18512 records, 7471 full page images, 21157309 bytes system usage: CPU: user: 2.24 s, system: 0.00 s, elapsed: 4.85 s psql:vacuum_test_analyze.sql:44: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:44: INFO: "vestat": scanned 7512 of 7512 pages, containing 900000 live rows and 0 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT DELETE 900000 psql:vacuum_test_analyze.sql:51: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:51: INFO: table "vestat": truncated 7512 to 0 pages psql:vacuum_test_analyze.sql:51: 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: 749, which was 1 XIDs old when operation ended new relfrozenxid: 749, which is 4 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 17.193 MB/s buffer usage: 51480 hits, 0 misses, 3958 dirtied WAL usage: 23781 records, 3954 full page images, 14444904 bytes system usage: CPU: user: 0.51 s, system: 0.01 s, elapsed: 1.79 s psql:vacuum_test_analyze.sql:51: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:51: INFO: "vestat": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT INSERT 0 1000000 UPDATE 1000000 psql:vacuum_test_analyze.sql:60: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:60: 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: 752, which was 0 XIDs old when operation ended new relfrozenxid: 751, 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 I/O timings: read: 5.693 ms, write: 1.319 ms avg read rate: 1.421 MB/s, avg write rate: 3.666 MB/s buffer usage: 32312 hits, 607 misses, 1566 dirtied WAL usage: 20571 records, 2 full page images, 9938566 bytes system usage: CPU: user: 2.65 s, system: 0.00 s, elapsed: 3.33 s psql:vacuum_test_analyze.sql:60: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:60: INFO: "vestat": scanned 8347 of 8347 pages, containing 1000000 live rows and 0 dead rows; 30000 rows in sample, 1000000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT
postgres=# \i vacuum_test_analyze.sql psql:vacuum_test_analyze.sql:2: ERROR: extension "dblink" does not exist CREATE EXTENSION dblink_connect ---------------- OK (1 row) psql:vacuum_test_analyze.sql:5: ERROR: table "vestat" does not exist SET SET CREATE TABLE CREATE INDEX psql:vacuum_test_analyze.sql:15: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:15: 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: 741, which was 0 XIDs old when operation ended new relfrozenxid: 741, which is 2 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.107 ms, write: 0.000 ms avg read rate: 28.617 MB/s, avg write rate: 0.000 MB/s buffer usage: 13 hits, 1 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 psql:vacuum_test_analyze.sql:15: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:15: INFO: "vestat": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows VACUUM pg_sleep ---------- (1 row) INSERT 0 1000000 DELETE 100000 psql:vacuum_test_analyze.sql:24: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:24: INFO: table "vestat": truncated 3922 to 3530 pages psql:vacuum_test_analyze.sql:24: 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: 743, 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 I/O timings: read: 0.000 ms, write: 0.058 ms avg read rate: 0.000 MB/s, avg write rate: 0.054 MB/s buffer usage: 12583 hits, 0 misses, 4 dirtied WAL usage: 5369 records, 1 full page images, 928676 bytes system usage: CPU: user: 0.44 s, system: 0.00 s, elapsed: 0.57 s psql:vacuum_test_analyze.sql:24: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:24: INFO: "vestat": scanned 3530 of 3530 pages, containing 900000 live rows and 0 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- BEGIN (1 row) a --- (1 row) UPDATE 900000 psql:vacuum_test_analyze.sql:37: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:37: 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.053 ms avg read rate: 0.000 MB/s, avg write rate: 0.062 MB/s buffer usage: 19424 hits, 0 misses, 6 dirtied WAL usage: 2 records, 1 full page images, 1529 bytes system usage: CPU: user: 0.54 s, system: 0.00 s, elapsed: 0.75 s psql:vacuum_test_analyze.sql:37: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:37: INFO: "vestat": scanned 7512 of 7512 pages, containing 900000 live rows and 900000 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT dblink_exec ------------- COMMIT (1 row) psql:vacuum_test_analyze.sql:44: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:44: 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: 747, which was 0 XIDs old when operation ended new relfrozenxid: 745, which is 4 XIDs ahead of previous value frozen: 1 pages from table (0.01% of total) had 133 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 18.508 MB/s buffer usage: 22962 hits, 0 misses, 11456 dirtied WAL usage: 18512 records, 7471 full page images, 21157309 bytes system usage: CPU: user: 2.24 s, system: 0.00 s, elapsed: 4.83 s psql:vacuum_test_analyze.sql:44: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:44: INFO: "vestat": scanned 7512 of 7512 pages, containing 900000 live rows and 0 dead rows; 30000 rows in sample, 900000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT DELETE 900000 psql:vacuum_test_analyze.sql:51: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:51: INFO: table "vestat": truncated 7512 to 0 pages psql:vacuum_test_analyze.sql:51: 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: 749, which was 1 XIDs old when operation ended new relfrozenxid: 749, which is 4 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 I/O timings: read: 0.000 ms, write: 0.000 ms avg read rate: 0.000 MB/s, avg write rate: 16.836 MB/s buffer usage: 51480 hits, 0 misses, 3958 dirtied WAL usage: 23781 records, 3954 full page images, 14444904 bytes system usage: CPU: user: 0.55 s, system: 0.00 s, elapsed: 1.83 s psql:vacuum_test_analyze.sql:51: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:51: INFO: "vestat": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT INSERT 0 1000000 UPDATE 1000000 psql:vacuum_test_analyze.sql:60: INFO: vacuuming "postgres.public.vestat" psql:vacuum_test_analyze.sql:60: 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: 752, which was 0 XIDs old when operation ended new relfrozenxid: 751, 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 I/O timings: read: 3.803 ms, write: 1.236 ms avg read rate: 1.351 MB/s, avg write rate: 3.208 MB/s buffer usage: 32346 hits, 573 misses, 1360 dirtied WAL usage: 20571 records, 2 full page images, 9938566 bytes system usage: CPU: user: 2.67 s, system: 0.01 s, elapsed: 3.31 s psql:vacuum_test_analyze.sql:60: INFO: analyzing "public.vestat" psql:vacuum_test_analyze.sql:60: INFO: "vestat": scanned 8347 of 8347 pages, containing 1000000 live rows and 0 dead rows; 30000 rows in sample, 1000000 estimated total rows VACUUM pg_sleep ---------- (1 row) CHECKPOINT
vacuum_check_logs.sql
Description: application/sql
