[BUGS] BUG #14530: Logical Decoding Slowness

The following bug has been logged on the website:

Bug reference:      14530
Logged by:          Huan Ruan
Email address:      leohuanruan@gmail.com
PostgreSQL version: 9.5.5
Operating system:   CentOS 7.2.1511 x86_64
Description:

This occurs in both 9.5.5 and 9.6.1.

Logically decoding a transaction with lots of subtransactions runs CPU at
100% for a long time (compared to no subtransaction).

To reproduce,

ROWS=100000

function test() {
  SQL=$1
  echo $SQL
  createdb test
  psql test -qc "CREATE TABLE t(x) AS SELECT generate_series(1,$ROWS);
CREATE INDEX ON t(x);"
  psql test -c "SELECT pg_create_logical_replication_slot('test_slot',
'test_decoding')" > /dev/null
  echo "BEGIN; $(seq -f "$SQL" $ROWS) COMMIT;" | psql test -q
  time $(psql test -c "SELECT COUNT(*) FROM
pg_logical_slot_get_changes('test_slot', NULL, NULL)" > /dev/null)
  echo
  psql test -c "SELECT pg_drop_replication_slot('test_slot')" > /dev/null
  dropdb test
}

UPDATE="UPDATE t SET x=x-1 WHERE x=%0.f"

test "$UPDATE;"
test "SAVEPOINT s; $UPDATE; RELEASE SAVEPOINT s;"

Sample results of running the above script for different input sizes look
like this (times are in seconds),

Records    NO_SAVEPOINT    SAVEPOINT
 10,000     0.051    0.08
 20,000     0.104    1.635
 30,000     0.118    5.518
 40,000     0.15    11.788
 50,000     0.182    20.368
 60,000     0.216    31.919
 70,000     0.248    48.622
 80,000     0.278    73.614
 90,000     0.328    105.849
 100,000     0.36    145.467
 110,000     0.416    199.62
 120,000     0.426    274.782
 130,000     0.457    411.933
 140,000     0.501    545.472
 150,000     0.525    592.541
 160,000     0.566    737.855
 170,000     0.58    832.151
 180,000     0.632    1159.2
 190,000     0.687    1257.374
 200,000     0.692    1438.609

The backend running the pg_logical_slot_get_changes() query runs at 100% CPU
during this time, and does not respond to pg_cancel_backend() or
pg_terminate_backend().

We've also observed similar symptoms when there are lots of CREATE [TEMP]
TABLE statements in one transaction. 

To reproduce,

CREATE_TABLES=`seq -f "CREATE TABLE t_%.0f (id int);" 10000`

# Create tables in separate transactions; pg_logical_slot_get_changes()
takes 0.3s
createdb test1
psql test1 -c "SELECT pg_create_logical_replication_slot('test_slot_1',
'test_decoding')"
time echo $CREATE_TABLES | psql test1 -q
time psql test1 -c "SELECT COUNT(*) FROM
pg_logical_slot_get_changes('test_slot_1', NULL, NULL)"

# Create tables in one transaction; pg_logical_slot_get_changes() takes
210s
createdb test2
psql test2 -c "SELECT pg_create_logical_replication_slot('test_slot_2',
'test_decoding')"
time echo "BEGIN; $CREATE_TABLES COMMIT;" | psql test2 -q
time psql test2 -c "SELECT COUNT(*) FROM
pg_logical_slot_get_changes('test_slot_2', NULL, NULL)"

# Clean up
psql test1 -c "select pg_drop_replication_slot('test_slot_1');"
dropdb test1
psql test2 -c "select pg_drop_replication_slot('test_slot_2');"
dropdb test2



--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs