vacuum_analyze_test_with_patch

text/plain

Filename: vacuum_analyze_test_with_patch
Type: text/plain
Part: 2
Message: Re: Fix parallel vacuum buffer usage reporting
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