Re: [PATCH] Reuse Workers and Replication Slots during Logical Replication

Hi Melih,

Here is a patch to help in getting the execution at various phases
like: a) replication slot creation time, b) Wal reading c) Number of
WAL records read d) subscription relation state change etc
Couple of observation while we tested with this patch:
1) We noticed that the patch takes more time for finding the decoding
start point.
2) Another observation was that the number of XLOG records read for
identify the consistent point was significantly high with the v26_0001
patch.

HEAD
postgres=# select avg(counttime)/1000 "avgtime(ms)",
median(counttime)/1000 "median(ms)", min(counttime)/1000
"mintime(ms)", max(counttime)/1000 "maxtime(ms)", logtype from test
group by logtype;
avgtime(ms) | median(ms) | mintime(ms) |
maxtime(ms) | logtype
------------------------+------------------------+-------------+-------------+--------------------------
0.00579245283018867920 | 0.00200000000000000000 | 0 |
1 | SNAPSHOT_BUILD
1.2246811320754717 | 0.98550000000000000000 | 0 |
37 | LOGICAL_SLOT_CREATION
171.0863283018867920 | 183.9120000000000000 | 0 |
408 | FIND_DECODING_STARTPOINT
2.0699433962264151 | 1.4380000000000000 | 1 |
49 | INIT_DECODING_CONTEXT
(4 rows)

HEAD + v26-0001 patch
postgres=# select avg(counttime)/1000 "avgtime(ms)",
median(counttime)/1000 "median(ms)", min(counttime)/1000
"mintime(ms)", max(counttime)/1000 "maxtime(ms)", logtype from test
group by logtype;
avgtime(ms) | median(ms) | mintime(ms) |
maxtime(ms) | logtype
------------------------+------------------------+-------------+-------------+--------------------------
0.00588113207547169810 | 0.00500000000000000000 | 0 |
0 | SNAPSHOT_BUILD
1.1270962264150943 | 1.1000000000000000 | 0 |
2 | LOGICAL_SLOT_CREATION
301.1745528301886790 | 410.4870000000000000 | 0 |
427 | FIND_DECODING_STARTPOINT
1.4814660377358491 | 1.4530000000000000 | 1 |
9 | INIT_DECODING_CONTEXT
(4 rows)

In the above FIND_DECODING_STARTPOINT is very much higher with V26-0001 patch.

HEAD
FIND_DECODING_XLOG_RECORD_COUNT
- average = 2762
- median = 3362

HEAD + reuse worker patch(v26_0001 patch)
Where FIND_DECODING_XLOG_RECORD_COUNT
- average = 4105
- median = 5345

Similarly Number of xlog records read is higher with v26_0001 patch.

Steps to calculate the timing:
-- first collect the necessary LOG from subscriber's log.
cat *.log | grep -E
'(LOGICAL_SLOT_CREATION|INIT_DECODING_CONTEXT|FIND_DECODING_STARTPOINT|SNAPSHOT_BUILD|FIND_DECODING_XLOG_RECORD_COUNT|LOGICAL_XLOG_READ|LOGICAL_DECODE_PROCESS_RECORD|LOGICAL_WAIT_TRANSACTION)'
> grep.dat

create table testv26(logtime varchar, pid varchar, level varchar,
space varchar, logtype varchar, counttime int);
-- then copy these datas into db table to count the avg number.
COPY testv26 FROM '/home/logs/grep.dat' DELIMITER ' ';

-- Finally, use the SQL to analyze the data:
select avg(counttime)/1000 "avgtime(ms)", logtype from testv26 group by logtype;

--- To get the number of xlog records read:
select avg(counttime) from testv26 where logtype
='FIND_DECODING_XLOG_RECORD_COUNT' and counttime != 1;

Thanks to Peter and Hou-san who helped in finding these out. We are
parallely analysing this, @Melih Mutlu posting this information so
that it might help you too in analysing this issue.

Regards,
Vignesh