public inbox for [email protected]
help / color / mirror / Atom feedFrom: Alena Rybakina <[email protected]>
To: Anthonin Bonnefoy <[email protected]>
Cc: Masahiko Sawada <[email protected]>
Cc: PostgreSQL Hackers <[email protected]>
Subject: Re: Fix parallel vacuum buffer usage reporting
Date: Fri, 26 Apr 2024 15:12:45 +0300
Message-ID: <[email protected]> (raw)
In-Reply-To: <CAO6_XqpCxQ0VkdkV_Ah_v=W1v3wt=pfGQssXGeuHrbMsUG=Bzg@mail.gmail.com>
References: <CAO6_XqrQk+QZQcYs_C6nk0cMfHuUWk85vT9CrcA1NffFbAVE2A@mail.gmail.com>
<CAD21AoBOkX+QBUqotOS-Cob+9t0pO49+rrpiMcgZfdEsVLA0uw@mail.gmail.com>
<CAO6_Xqpt9t4Oyn9TBS9HeOupfuaH1B4xU9SYbs7k86cVK6m92w@mail.gmail.com>
<[email protected]>
<CAO6_XqrJeHrPtE9z0dt3O9xqq3097-LWO9xNYbnjh_iMmurzgw@mail.gmail.com>
<CAD21AoAK=f_mEm3-FPJT75dm=nESUgknixEq0WHWkn7+-S6-Kg@mail.gmail.com>
<[email protected]>
<CAO6_XqpCxQ0VkdkV_Ah_v=W1v3wt=pfGQssXGeuHrbMsUG=Bzg@mail.gmail.com>
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 dirtied
>
> Isn'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/acces...
>
> Looking 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 dirtied
with 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
> <[email protected]> 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, 1777dirtied
with 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
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)
Attachments:
[application/sql] vacuum_check_logs.sql (1.8K, ../[email protected]/3-vacuum_check_logs.sql)
download
[text/plain] vacuum_test_v4 (7.4K, ../[email protected]/4-vacuum_test_v4)
download | inline:
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)
[text/plain] vacuum_test (7.4K, ../[email protected]/5-vacuum_test)
download | inline:
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)
view thread (21+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected]
Subject: Re: Fix parallel vacuum buffer usage reporting
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox