On Thu, Apr 2, 2020 at 6:41 PM Amit Kapila <[email protected]> wrote:
>
> On Thu, Apr 2, 2020 at 6:18 PM Julien Rouhaud <[email protected]> wrote:
> >
> > =# select query, calls, wal_bytes, wal_records, wal_num_fpw from
> > pg_stat_statements where query ilike '%create index%';
> > query | calls | wal_bytes |
> > wal_records | wal_num_fpw
> > ----------------------------------------------+-------+-----------+-------------+-------------
> > create index t1_idx_parallel_0 ON t1(id) | 1 | 20389743 |
> > 2762 | 2758
> > create index t1_idx_parallel_0_bis ON t1(id) | 1 | 20394391 |
> > 2762 | 2758
> > create index t1_idx_parallel_0_ter ON t1(id) | 1 | 20395155 |
> > 2762 | 2758
> > create index t1_idx_parallel_1 ON t1(id) | 1 | 20388335 |
> > 2762 | 2758
> > create index t1_idx_parallel_2 ON t1(id) | 1 | 20389091 |
> > 2762 | 2758
> > create index t1_idx_parallel_3 ON t1(id) | 1 | 20389847 |
> > 2762 | 2758
> > create index t1_idx_parallel_4 ON t1(id) | 1 | 20390603 |
> > 2762 | 2758
> > create index t1_idx_parallel_5 ON t1(id) | 1 | 20391359 |
> > 2762 | 2758
> > create index t1_idx_parallel_6 ON t1(id) | 1 | 20392115 |
> > 2762 | 2758
> > create index t1_idx_parallel_7 ON t1(id) | 1 | 20392871 |
> > 2762 | 2758
> > create index t1_idx_parallel_8 ON t1(id) | 1 | 20393627 |
> > 2762 | 2758
> > (11 rows)
> >
> > =# select relname, pg_relation_size(oid) from pg_class where relname like
> > '%t1_id%';
> > relname | pg_relation_size
> > -----------------------+------------------
> > t1_idx_parallel_0 | 22487040
> > t1_idx_parallel_0_bis | 22487040
> > t1_idx_parallel_0_ter | 22487040
> > t1_idx_parallel_2 | 22487040
> > t1_idx_parallel_1 | 22487040
> > t1_idx_parallel_4 | 22487040
> > t1_idx_parallel_3 | 22487040
> > t1_idx_parallel_5 | 22487040
> > t1_idx_parallel_6 | 22487040
> > t1_idx_parallel_7 | 22487040
> > t1_idx_parallel_8 | 22487040
> > (9 rows)
> >
> >
> > So while the number of WAL records and full page images stay constant, we
> > can
> > see some small fluctuations in the total amount of generated WAL data, even
> > for
> > multiple execution of the sequential create index. I'm wondering if the
> > fluctuations are due to some other internal details or if the WalUsage
> > support
> > is just completely broken (although I don't see any obvious issue ATM).
> >
>
> I think we need to know the reason for this. Can you try with small
> size indexes and see if the problem is reproducible? If it is, then it
> will be easier to debug the same.
I have done some testing to see where these extra WAL size is coming
from. First I tried to create new db before every run then the size
is consistent. But, then on the same server, I tired as Julien showed
in his experiment then I am getting few extra wal bytes from next
create index onwards. And, the waldump(attached in the mail) shows
that is pg_class insert wal. I still have to check that why we need
to write an extra wal size.
create extension pg_stat_statements;
drop table t1;
create table t1(id integer);
insert into t1 select * from generate_series(1, 10);
alter table t1 set (parallel_workers = 0);
vacuum;checkpoint;
select * from pg_stat_statements_reset() ;
create index t1_idx_parallel_0 ON t1(id);
select query, calls, wal_bytes, wal_records, wal_num_fpw from
pg_stat_statements where query ilike '%create index%';;
query
| calls | wal_bytes | wal_records | wal_num_fpw
----------------------------------------------------------------------------------+-------+-----------+-------------+-------------
create index t1_idx_parallel_0 ON t1(id)
| 1 | 49320 | 23 | 15
drop table t1;
create table t1(id integer);
insert into t1 select * from generate_series(1, 10);
--select * from pg_stat_statements_reset() ;
alter table t1 set (parallel_workers = 0);
vacuum;checkpoint;
create index t1_idx_parallel_1 ON t1(id);
select query, calls, wal_bytes, wal_records, wal_num_fpw from
pg_stat_statements where query ilike '%create index%';;
postgres[110383]=# select query, calls, wal_bytes, wal_records,
wal_num_fpw from pg_stat_statements;
query
| calls | wal_bytes | wal_records | wal_num_fpw
----------------------------------------------------------------------------------+-------+-----------+-------------+-------------
create index t1_idx_parallel_1 ON t1(id)
| 1 | 50040 | 23 | 15
wal_bytes diff = 50040-49320 = 720
Below, WAL record is causing the 720 bytes difference, all other WALs
are of the same size.
t1_idx_parallel_0:
rmgr: Heap len (rec/tot): 54/ 7498, tx: 489, lsn:
0/0167B9B0, prev 0/0167B970, desc: INSERT off 30 flags 0x01, blkref
#0: rel 1663/13580/1249
t1_idx_parallel_1:
rmgr: Heap len (rec/tot): 54/ 8218, tx: 494, lsn:
0/016B84F8, prev 0/016B84B8, desc: INSERT off 30 flags 0x01, blkref
#0: rel 1663/13580/1249
wal diff: 8218 - 7498 = 720
--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn:
0/016B6288, prev 0/016B6210, desc: RUNNING_XACTS nextXid 494 latestCompletedXid
493 oldestRunningXid 494
rmgr: Storage len (rec/tot): 42/ 42, tx: 0, lsn:
0/016B62C0, prev 0/016B6288, desc: CREATE base/13580/16405
rmgr: Standby len (rec/tot): 42/ 42, tx: 494, lsn:
0/016B62F0, prev 0/016B62C0, desc: LOCK xid 494 db 13580 rel 16405
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 494, lsn:
0/016B6320, prev 0/016B62F0, desc: NEW_CID rel 1663/13580/1259; tid 0/2; cmin:
0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 1322, tx: 494, lsn:
0/016B6360, prev 0/016B6320, desc: INSERT off 2 flags 0x01, blkref #0: rel
1663/13580/1259 blk 0 FPW
rmgr: Btree len (rec/tot): 53/ 2253, tx: 494, lsn:
0/016B6890, prev 0/016B6360, desc: INSERT_LEAF off 108, blkref #0: rel
1663/13580/2662 blk 2 FPW
rmgr: Btree len (rec/tot): 53/ 3881, tx: 494, lsn:
0/016B7160, prev 0/016B6890, desc: INSERT_LEAF off 88, blkref #0: rel
1663/13580/2663 blk 2 FPW
rmgr: Btree len (rec/tot): 53/ 1033, tx: 494, lsn:
0/016B80A8, prev 0/016B7160, desc: INSERT_LEAF off 47, blkref #0: rel
1663/13580/3455 blk 4 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 494, lsn:
0/016B84B8, prev 0/016B80A8, desc: NEW_CID rel 1663/13580/1249; tid 16/30;
cmin: 0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 8218, tx: 494, lsn:
0/016B84F8, prev 0/016B84B8, desc: INSERT off 30 flags 0x01, blkref #0: rel
1663/13580/1249 blk 16 FPW
rmgr: Btree len (rec/tot): 53/ 1373, tx: 494, lsn:
0/016BA530, prev 0/016B84F8, desc: INSERT_LEAF off 40, blkref #0: rel
1663/13580/2658 blk 14 FPW
rmgr: Btree len (rec/tot): 53/ 6753, tx: 494, lsn:
0/016BAA90, prev 0/016BA530, desc: INSERT_LEAF off 333, blkref #0: rel
1663/13580/2659 blk 9 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 494, lsn:
0/016BC510, prev 0/016BAA90, desc: NEW_CID rel 1663/13580/2610; tid 3/20; cmin:
0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 3582, tx: 494, lsn:
0/016BC550, prev 0/016BC510, desc: INSERT off 20 flags 0x01, blkref #0: rel
1663/13580/2610 blk 3 FPW
rmgr: Btree len (rec/tot): 53/ 3193, tx: 494, lsn:
0/016BD350, prev 0/016BC550, desc: INSERT_LEAF off 155, blkref #0: rel
1663/13580/2678 blk 1 FPW
rmgr: Btree len (rec/tot): 53/ 3193, tx: 494, lsn:
0/016BDFD0, prev 0/016BD350, desc: INSERT_LEAF off 155, blkref #0: rel
1663/13580/2679 blk 1 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 494, lsn:
0/016BEC68, prev 0/016BDFD0, desc: NEW_CID rel 1663/13580/2608; tid 56/64;
cmin: 0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 4798, tx: 494, lsn:
0/016BECA8, prev 0/016BEC68, desc: INSERT off 64 flags 0x01, blkref #0: rel
1663/13580/2608 blk 56 FPW
rmgr: Btree len (rec/tot): 53/ 1149, tx: 494, lsn:
0/016BFF68, prev 0/016BECA8, desc: INSERT_LEAF off 32, blkref #0: rel
1663/13580/2673 blk 32 FPW
rmgr: Btree len (rec/tot): 53/ 8121, tx: 494, lsn:
0/016C0400, prev 0/016BFF68, desc: INSERT_LEAF off 287, blkref #0: rel
1663/13580/2674 blk 39 FPW
rmgr: XLOG len (rec/tot): 49/ 289, tx: 494, lsn:
0/016C23D8, prev 0/016C0400, desc: FPI , blkref #0: rel 1663/13580/16405 blk 1
FPW
rmgr: XLOG len (rec/tot): 49/ 137, tx: 494, lsn:
0/016C2500, prev 0/016C23D8, desc: FPI , blkref #0: rel 1663/13580/16405 blk 0
FPW
rmgr: Heap len (rec/tot): 233/ 233, tx: 494, lsn:
0/016C2590, prev 0/016C2500, desc: INPLACE off 4, blkref #0: rel
1663/13580/1259 blk 0
rmgr: Heap len (rec/tot): 188/ 188, tx: 494, lsn:
0/016C2680, prev 0/016C2590, desc: INPLACE off 2, blkref #0: rel
1663/13580/1259 blk 0
rmgr: Transaction len (rec/tot): 274/ 274, tx: 494, lsn:
0/016C2740, prev 0/016C2680, desc: COMMIT 2020-04-02 20:41:00.529118 IST; inval
msgs: catcache 50 catcache 49 catcache 50 catcache 49 catcache 50 catcache 49
catcache 7 catcache 6 catcache 32 relcache 16402 relcache 16405 relcache 16405
relcache 16402 snapshot 2608
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn:
0/01679740, prev 0/016796C8, desc: RUNNING_XACTS nextXid 489 latestCompletedXid
488 oldestRunningXid 489
rmgr: Storage len (rec/tot): 42/ 42, tx: 0, lsn:
0/01679778, prev 0/01679740, desc: CREATE base/13580/16401
rmgr: Standby len (rec/tot): 42/ 42, tx: 489, lsn:
0/016797A8, prev 0/01679778, desc: LOCK xid 489 db 13580 rel 16401
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 489, lsn:
0/016797D8, prev 0/016797A8, desc: NEW_CID rel 1663/13580/1259; tid 0/2; cmin:
0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 1322, tx: 489, lsn:
0/01679818, prev 0/016797D8, desc: INSERT off 2 flags 0x01, blkref #0: rel
1663/13580/1259 blk 0 FPW
rmgr: Btree len (rec/tot): 53/ 2253, tx: 489, lsn:
0/01679D48, prev 0/01679818, desc: INSERT_LEAF off 108, blkref #0: rel
1663/13580/2662 blk 2 FPW
rmgr: Btree len (rec/tot): 53/ 3881, tx: 489, lsn:
0/0167A630, prev 0/01679D48, desc: INSERT_LEAF off 88, blkref #0: rel
1663/13580/2663 blk 2 FPW
rmgr: Btree len (rec/tot): 53/ 1033, tx: 489, lsn:
0/0167B560, prev 0/0167A630, desc: INSERT_LEAF off 47, blkref #0: rel
1663/13580/3455 blk 4 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 489, lsn:
0/0167B970, prev 0/0167B560, desc: NEW_CID rel 1663/13580/1249; tid 16/30;
cmin: 0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 7498, tx: 489, lsn:
0/0167B9B0, prev 0/0167B970, desc: INSERT off 30 flags 0x01, blkref #0: rel
1663/13580/1249 blk 16 FPW
rmgr: Btree len (rec/tot): 53/ 1373, tx: 489, lsn:
0/0167D718, prev 0/0167B9B0, desc: INSERT_LEAF off 40, blkref #0: rel
1663/13580/2658 blk 14 FPW
rmgr: Btree len (rec/tot): 53/ 6753, tx: 489, lsn:
0/0167DC78, prev 0/0167D718, desc: INSERT_LEAF off 333, blkref #0: rel
1663/13580/2659 blk 9 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 489, lsn:
0/0167F6F8, prev 0/0167DC78, desc: NEW_CID rel 1663/13580/2610; tid 3/20; cmin:
0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 3582, tx: 489, lsn:
0/0167F738, prev 0/0167F6F8, desc: INSERT off 20 flags 0x01, blkref #0: rel
1663/13580/2610 blk 3 FPW
rmgr: Btree len (rec/tot): 53/ 3193, tx: 489, lsn:
0/01680550, prev 0/0167F738, desc: INSERT_LEAF off 155, blkref #0: rel
1663/13580/2678 blk 1 FPW
rmgr: Btree len (rec/tot): 53/ 3193, tx: 489, lsn:
0/016811D0, prev 0/01680550, desc: INSERT_LEAF off 155, blkref #0: rel
1663/13580/2679 blk 1 FPW
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 489, lsn:
0/01681E50, prev 0/016811D0, desc: NEW_CID rel 1663/13580/2608; tid 56/64;
cmin: 0, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 54/ 4798, tx: 489, lsn:
0/01681E90, prev 0/01681E50, desc: INSERT off 64 flags 0x01, blkref #0: rel
1663/13580/2608 blk 56 FPW
rmgr: Btree len (rec/tot): 53/ 1149, tx: 489, lsn:
0/01683168, prev 0/01681E90, desc: INSERT_LEAF off 32, blkref #0: rel
1663/13580/2673 blk 32 FPW
rmgr: Btree len (rec/tot): 53/ 8121, tx: 489, lsn:
0/016835E8, prev 0/01683168, desc: INSERT_LEAF off 287, blkref #0: rel
1663/13580/2674 blk 39 FPW
rmgr: XLOG len (rec/tot): 49/ 289, tx: 489, lsn:
0/016855C0, prev 0/016835E8, desc: FPI , blkref #0: rel 1663/13580/16401 blk 1
FPW
rmgr: XLOG len (rec/tot): 49/ 137, tx: 489, lsn:
0/016856E8, prev 0/016855C0, desc: FPI , blkref #0: rel 1663/13580/16401 blk 0
FPW
rmgr: Heap len (rec/tot): 233/ 233, tx: 489, lsn:
0/01685778, prev 0/016856E8, desc: INPLACE off 9, blkref #0: rel
1663/13580/1259 blk 0
rmgr: Heap len (rec/tot): 188/ 188, tx: 489, lsn:
0/01685868, prev 0/01685778, desc: INPLACE off 2, blkref #0: rel
1663/13580/1259 blk 0
rmgr: Transaction len (rec/tot): 274/ 274, tx: 489, lsn:
0/01685928, prev 0/01685868, desc: COMMIT 2020-04-02 20:39:36.189621 IST; inval
msgs: catcache 50 catcache 49 catcache 50 catcache 49 catcache 50 catcache 49
catcache 7 catcache 6 catcache 32 relcache 16398 relcache 16401 relcache 16401
relcache 16398 snapshot 2608
