BUG #14530: Logical Decoding Slowness

The following bug has been logged on the website:

Bug reference: 14530
Logged by: Huan Ruan
Email address: leohuanruan(at)gmail(dot)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