Hi Dilip, Amit, > > 5. Can you please once repeat the performance test done by Keisuke-San > > to see if you have similar observations? Additionally, see if you are > > also seeing the inconsistency related to the Truncate message reported > > by him and if so why? > > > > Okay, I will set up and do this test early next week. Keisuke-San, > can you send me your complete test script?
Yes, I've attached a test script(test_pg_recvlogical.sh)
Sorry, the issue with TRUNCATE not outputting was due to a build miss
on my part.
Even before the patch, TRUNCATE decodes and outputting correctly.
So, please check the performance only.
I have tested it again and will share the results with you.
Also, the argument of palloc was still MemoryContextAlloc,
which prevented me from applying the patch, so I've only fixed that part.
# test script
Please set PGHOME and CLUSTER_PUB before run.
sh test_pg_recvlogical.sh
# perf command
perf record --call-graph dwarf -p [walsender pid]
perf report -i perf.data --no-children
# before patch
decode + invalidation = 222s
2020-10-02 14:55:50 BEGIN 509
2020-10-02 14:59:42 table nsp_001.tbl_001, nsp_001.part_0001 ...
nsp_001.part_0999, nsp_001.part_1000: TRUNCATE: (no-flags)
2020-10-02 14:59:42 COMMIT 509 (at 2020-10-02 14:55:50.349219+09)
Samples: 229K of event 'cpu-clock:uhH', Event count (approx.): 57347250000
Overhead Command Shared Object Symbol
- 96.07% postgres postgres [.] hash_seq_search
hash_seq_search
- RelfilenodeMapInvalidateCallback
- LocalExecuteInvalidationMessage
ReorderBufferExecuteInvalidations
ReorderBufferProcessTXN
ReorderBufferCommit
DecodeCommit
DecodeXactOp
LogicalDecodingProcessRecord
XLogSendLogical
WalSndLoop
StartLogicalReplication
exec_replication_command
PostgresMain
BackendRun
BackendStartup
ServerLoop
PostmasterMain
main
__libc_start_main
_start
0.74% postgres postgres [.] LocalExecuteInvalidationMessage
0.47% postgres postgres [.] hash_bytes_uint32
0.46% postgres postgres [.] hash_search_with_hash_value
0.37% postgres postgres [.] RelfilenodeMapInvalidateCallback
0.31% postgres postgres [.] CatCacheInvalidate
0.22% postgres postgres [.] uint32_hash
0.21% postgres postgres [.] PlanCacheRelCallback
0.20% postgres postgres [.] hash_seq_init
0.17% postgres postgres [.] ReorderBufferExecuteInvalidations
# after patch
decode + invalidation = 1s or less
2020-10-02 15:20:08 BEGIN 509
2020-10-02 15:20:08 table nsp_001.tbl_001, nsp_001.part_0001 ...
nsp_001.part_0999, nsp_001.part_1000: TRUNCATE: (no-flags)
2020-10-02 15:20:08 COMMIT 509 (at 2020-10-02 15:20:08.704503+09)
Samples: 310 of event 'cpu-clock:uhH', Event count (approx.): 77500000
Overhead Command Shared Object Symbol
- 49.35% postgres postgres [.] hash_seq_search
hash_seq_search
RelfilenodeMapInvalidateCallback
LocalExecuteInvalidationMessage
ReorderBufferExecuteInvalidations
ReorderBufferProcessTXN
ReorderBufferCommit
DecodeCommit
DecodeXactOp
LogicalDecodingProcessRecord
XLogSendLogical
WalSndLoop
StartLogicalReplication
exec_replication_command
PostgresMain
BackendRun
BackendStartup
ServerLoop
PostmasterMain
main
__libc_start_main
_start
2.58% postgres libc-2.17.so [.] __memset_sse2
2.58% postgres libpthread-2.17.so [.] __libc_recv
1.61% postgres libc-2.17.so [.] __memcpy_ssse3_back
1.61% postgres libpthread-2.17.so [.] __errno_location
1.61% postgres postgres [.] AllocSetAlloc
1.61% postgres postgres [.] DecodeXLogRecord
1.29% postgres postgres [.] AllocSetFree
1.29% postgres postgres [.] hash_bytes_uint32
0.97% postgres [vdso] [.] __vdso_gettimeofday
0.97% postgres postgres [.] LocalExecuteInvalidationMessage
Best Regards,
--
Keisuke Kuroda
NTT Software Innovation Center
keisuke.kuroda.3...@gmail.com
#!/bin/bash
PGHOME="/home/postgres/pgsql/master_20201002_1"
CLUSTER_PUB="/home/postgres/pgsql/master_20201002_1/data_pub"
${PGHOME}/bin/pg_ctl -D ${CLUSTER_PUB} stop
rm -rf ${CLUSTER_PUB}
${PGHOME}/bin/initdb -D ${CLUSTER_PUB} --no-locale -E UTF8 -k
## Configuration
echo "shared_buffers = 1GB" >> ${CLUSTER_PUB}/postgresql.conf
echo "max_locks_per_transaction = 10000" >> ${CLUSTER_PUB}/postgresql.conf
echo "synchronous_commit = off" >> ${CLUSTER_PUB}/postgresql.conf
echo "archive_mode = off" >> ${CLUSTER_PUB}/postgresql.conf
echo "fsync = off" >> ${CLUSTER_PUB}/postgresql.conf
echo "full_page_writes = off" >> ${CLUSTER_PUB}/postgresql.conf
echo "autovacuum = off" >> ${CLUSTER_PUB}/postgresql.conf
echo "checkpoint_timeout = 120min" >> ${CLUSTER_PUB}/postgresql.conf
echo "max_wal_size = 20GB" >> ${CLUSTER_PUB}/postgresql.conf
echo "wal_level = logical" >> ${CLUSTER_PUB}/postgresql.conf
echo "max_wal_senders = 10" >> ${CLUSTER_PUB}/postgresql.conf
echo "wal_sender_timeout = 0" >> ${CLUSTER_PUB}/postgresql.conf
echo "wal_receiver_timeout = 0" >> ${CLUSTER_PUB}/postgresql.conf
echo "port = 5432" >> ${CLUSTER_PUB}/postgresql.conf
${PGHOME}/bin/pg_ctl -D ${CLUSTER_PUB} start
## create partition
${PGHOME}/bin/psql -p 5432 << "EOF"
DO $$
DECLARE
i INT;
j INT;
schema TEXT;
tablename TEXT;
partname TEXT;
BEGIN
FOR i IN 1 .. 2 LOOP
schema := 'nsp_' || to_char(i, 'FM000');
tablename := 'tbl_' || to_char(i, 'FM000');
EXECUTE 'CREATE SCHEMA ' || schema;
EXECUTE 'CREATE TABLE ' || schema || '.' || tablename || ' (
big01 BIGINT,
big02 BIGINT,
big03 BIGINT,
big04 BIGINT,
big05 BIGINT,
big06 BIGINT,
big07 BIGINT,
big08 BIGINT,
big09 BIGINT,
big10 BIGINT,
big11 BIGINT,
big12 BIGINT,
byt01 BYTEA,
byt02 BYTEA
) PARTITION BY RANGE (big02)';
FOR j IN 1 .. 1000 LOOP
partname := 'part_' || to_char(j, 'FM0000');
EXECUTE 'CREATE TABLE ' || schema || '.' || partname ||
' PARTITION OF ' || schema || '.' || tablename ||
' FOR VALUES FROM (' || (j-1)*10 || ') TO (' || (j)*10 || ')';
EXECUTE 'ALTER TABLE ' || schema || '.' || partname || ' ADD PRIMARY KEY (big01)';
END LOOP;
EXECUTE 'CREATE INDEX ON ' || schema || '.' || tablename || ' (big03)';
END LOOP;
END;
$$ LANGUAGE plpgsql;
EOF
${PGHOME}/bin/pg_recvlogical --no-loop --create-slot --start -f - --if-not-exists \
--plugin=test_decoding --slot=test1 --dbname=postgres --username=postgres \
--option=include-timestamp | gawk '{ print strftime("%Y-%m-%d %H:%M:%S"), $0; fflush(); }' > pg_recvlogical.log &
sleep 1
echo "---walsender process info---"
ps -aux | grep walsender | grep -v grep
# insert data(create relfilenodemaphash)
${PGHOME}/bin/psql -p 5432 << "EOF"
DO $$
DECLARE
i INT;
j INT;
schema TEXT;
tablename TEXT;
BEGIN
FOR i IN 1 .. 2 LOOP
schema := 'nsp_' || to_char(i, 'FM000');
tablename := 'tbl_' || to_char(i, 'FM000');
EXECUTE 'INSERT INTO ' || schema || '.' || tablename || '
SELECT i,i,i,0,0,0,0,0,0,0,0,0,''a''::bytea,''a''::bytea FROM generate_series(0,9999,1) AS i';
END LOOP;
END;
$$ LANGUAGE plpgsql;
EOF
echo "sleep 10 before truncate"
sleep 10
${PGHOME}/bin/psql -p 5432 << "EOF"
TRUNCATE TABLE nsp_001.tbl_001;
EOF
v4-0001-Collect-command-invalidation-in-form-of-changes.patch
Description: Binary data
