Thread: [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
Apologies for the re-post. I noted scripts in the original post had their line feeds messed up. Below are the fixed ones,
Script 1,
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;"
Script 2,
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
Hi, On 2017-02-09 03:15:26 +0000, Huan Ruan wrote: > Apologies for the re-post. I noted scripts in the original post had their > line feeds messed up. Below are the fixed ones, I have a suspicion what's causing this, but would it be possible for you to run a profile (with perf or such) and report the result? Regards, Andres -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Hi Andres
Thanks for your reply.
On Thu, 9 Feb 2017 at 14:29 Andres Freund <andres@anarazel.de> wrote:
Hi,
I have a suspicion what's causing this, but would it be possible for you
to run a profile (with perf or such) and report the result?
Attached
- perf.data.subtran100k.gz is 'perf record -a -g -s -- ' output for the pg_logical_slot_get_changes() query in script 1 for 100,000 subtransactions.
- perf.data.createtable5k.gz is 'perf record -a -g -s -- ' output for the pg_logical_slot_get_changes() query in script 2 for 5,000 create tables in one transaction.
Regards
Huan
Attachment
On 2017-02-09 04:52:41 +0000, Huan Ruan wrote: > Hi Andres > > Thanks for your reply. > > On Thu, 9 Feb 2017 at 14:29 Andres Freund <andres@anarazel.de> wrote: > > > Hi, > > > > I have a suspicion what's causing this, but would it be possible for you > > to run a profile (with perf or such) and report the result? > > > > Attached > > - perf.data.subtran100k.gz is 'perf record -a -g -s -- ' output for the > pg_logical_slot_get_changes() query in script 1 for 100,000 subtransactions. > - perf.data.createtable5k.gz is 'perf record -a -g -s -- ' output for > the pg_logical_slot_get_changes() query in script 2 for 5,000 create tables > in one transaction. Unfortunately perf files can't be interpreted on other systems unless you added all the referenced object files to it using perf archive. Could you perhaps just send the first few lines of the report? Greetings, Andres Freund -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Hi Andres
Unfortunately perf files can't be interpreted on other systems unless
you added all the referenced object files to it using perf archive.
Sorry this was my first time using perf for profiling so didn't know that. Also, the profile was collected without Postgres debuginfo installed. If you need that or something else please let me know.
Could you perhaps just send the first few lines of the report?
The first screen of 'perf report -n' for subtransaction case is,
Samples: 247K of event 'cycles', Event count (approx.): 155149593065
Children Self Samples Command Shared Object Symbol
+ 51.26% 0.00% 0 postgres [unknown] [.] 0x0000000003236e68
+ 48.66% 48.54% 117427 postgres postgres [.] CatalogCacheIdInvalidate
+ 38.44% 38.35% 92748 postgres postgres [.] hash_seq_search
+ 5.67% 5.66% 13683 postgres postgres [.] CallSyscacheCallbacks
+ 3.00% 2.99% 7234 postgres postgres [.] LocalExecuteInvalidationMessage
+ 1.00% 0.99% 2397 postgres postgres [.] ReorderBufferCommit
+ 0.97% 0.00% 0 postgres [unknown] [.] 0x00000000017bb688
+ 0.95% 0.00% 0 postgres [unknown] [.] 0x00000000017bb368
+ 0.42% 0.00% 24 swapper [kernel.kallsyms] [k] cpu_startup_entry
+ 0.40% 0.40% 986 postgres postgres [.] hash_search_with_hash_value
+ 0.40% 0.00% 0 swapper [kernel.kallsyms] [k] start_secondary
+ 0.37% 0.00% 0 swapper [kernel.kallsyms] [k] arch_cpu_idle
+ 0.37% 0.00% 22 swapper [kernel.kallsyms] [k] cpuidle_idle_call
+ 0.35% 0.35% 847 postgres postgres [.] InvalidateCatalogSnapshot
+ 0.34% 0.00% 0 postgres [unknown] [.] 0x00000000017c99d8
+ 0.33% 0.33% 787 postgres postgres [.] RelfilenodeMapInvalidateCallback
+ 0.28% 0.00% 0 postgres [unknown] [.] 0x00000000017c9798
+ 0.24% 0.02% 51 postgres [kernel.kallsyms] [k] apic_timer_interrupt
+ 0.24% 0.00% 24 swapper [kernel.kallsyms] [k] cpuidle_enter_state
+ 0.23% 0.23% 2234 swapper [kernel.kallsyms] [k] intel_idle
+ 0.22% 0.00% 1 postgres [kernel.kallsyms] [k] smp_apic_timer_interrupt
+ 0.20% 0.00% 1 postgres [kernel.kallsyms] [k] system_call_fastpath
+ 0.19% 0.00% 0 postgres [unknown] [.] 0x00785c5300007f5c
+ 0.18% 0.00% 3 postgres [kernel.kallsyms] [k] local_apic_timer_interrupt
+ 0.18% 0.00% 0 postgres [kernel.kallsyms] [k] hrtimer_interrupt
+ 0.15% 0.00% 7 postgres libc-2.17.so [.] __GI___libc_write
+ 0.15% 0.00% 11 postgres [kernel.kallsyms] [k] __hrtimer_run_queues
+ 0.15% 0.00% 0 postgres [unknown] [.] 0x000000000184e8b0
+ 0.14% 0.14% 345 postgres postgres [.] deregister_seq_scan
+ 0.14% 0.00% 0 postgres [unknown] [.] 0x00000000017c54d8
+ 0.14% 0.00% 0 postgres [unknown] [.] 0x00000000017c5278
+ 0.14% 0.00% 6 postgres [kernel.kallsyms] [k] sys_write
+ 0.13% 0.00% 2 postgres [kernel.kallsyms] [k] tick_sched_timer
+ 0.13% 0.00% 12 postgres [kernel.kallsyms] [k] vfs_write
+ 0.13% 0.13% 308 postgres postgres [.] hash_uint32
+ 0.10% 0.00% 12 postgres [kernel.kallsyms] [k] do_sync_write
+ 0.10% 0.00% 11 postgres [kernel.kallsyms] [k] xfs_file_aio_write
+ 0.10% 0.09% 228 postgres postgres [.] hash_seq_init
+ 0.09% 0.00% 0 postgres [kernel.kallsyms] [k] tick_sched_handle.isra.14
+ 0.09% 0.00% 13 postgres [kernel.kallsyms] [k] xfs_file_buffered_aio_write
+ 0.09% 0.00% 0 postgres [kernel.kallsyms] [k] update_process_times
+ 0.09% 0.00% 7 postgres libc-2.17.so [.] __GI___libc_read
+ 0.08% 0.00% 28 swapper [kernel.kallsyms] [k] apic_timer_interrupt
+ 0.07% 0.00% 14 swapper [kernel.kallsyms] [k] irq_exit
+ 0.07% 0.00% 3 swapper [kernel.kallsyms] [k] smp_apic_timer_interrupt
+ 0.07% 0.07% 295 unpigz libz.so.1.2.7 [.] crc32
+ 0.07% 0.07% 170 postgres postgres [.] hash_search
+ 0.07% 0.00% 0 unpigz [kernel.kallsyms] [k] system_call_fastpath
+ 0.07% 0.00% 8 swapper [kernel.kallsyms] [k] call_softirq
+ 0.07% 0.00% 3 swapper [kernel.kallsyms] [k] do_softirq
+ 0.06% 0.00% 21 swapper [kernel.kallsyms] [k] __do_softirq
+ 0.06% 0.00% 12 postgres [kernel.kallsyms] [k] generic_file_buffered_write
+ 0.06% 0.00% 11 postgres [kernel.kallsyms] [k] scheduler_tick
+ 0.06% 0.00% 9 postgres [kernel.kallsyms] [k] sys_read
for create tables is,
Samples: 342K of event 'cycles', Event count (approx.): 216348097599
Children Self Samples Command Shared Object Symbol
+ 52.09% 0.00% 0 postgres [unknown] [.] 0x000000009754f3a8
+ 49.09% 48.98% 164831 postgres postgres [.] CatalogCacheIdInvalidate
+ 38.75% 38.67% 130091 postgres postgres [.] hash_seq_search
+ 4.92% 4.90% 16494 postgres postgres [.] CallSyscacheCallbacks
+ 3.20% 3.19% 10736 postgres postgres [.] LocalExecuteInvalidationMessage
+ 1.14% 1.14% 3828 postgres postgres [.] ReorderBufferCommit
+ 1.02% 0.00% 0 postgres [unknown] [.] 0x0000000001500aa8
+ 0.97% 0.00% 0 postgres [unknown] [.] 0x0000000001500788
+ 0.42% 0.42% 1408 postgres postgres [.] hash_search_with_hash_value
+ 0.34% 0.34% 1132 postgres postgres [.] InvalidateCatalogSnapshot
+ 0.34% 0.00% 31 swapper [kernel.kallsyms] [k] cpu_startup_entry
+ 0.32% 0.00% 0 swapper [kernel.kallsyms] [k] start_secondary
+ 0.30% 0.30% 1012 postgres postgres [.] RelfilenodeMapInvalidateCallback
+ 0.30% 0.00% 3 swapper [kernel.kallsyms] [k] arch_cpu_idle
+ 0.30% 0.00% 36 swapper [kernel.kallsyms] [k] cpuidle_idle_call
+ 0.24% 0.00% 0 postgres [unknown] [.] 0x000000000150edf8
+ 0.22% 0.02% 69 postgres [kernel.kallsyms] [k] apic_timer_interrupt
+ 0.21% 0.00% 0 postgres [unknown] [.] 0x000000000150ebb8
+ 0.20% 0.00% 0 postgres [unknown] [.] 0x00785c5300007f71
+ 0.20% 0.00% 2 postgres [kernel.kallsyms] [k] smp_apic_timer_interrupt
+ 0.20% 0.00% 25 swapper [kernel.kallsyms] [k] cpuidle_enter_state
+ 0.18% 0.18% 2389 swapper [kernel.kallsyms] [k] intel_idle
+ 0.17% 0.00% 0 postgres [kernel.kallsyms] [k] system_call_fastpath
+ 0.16% 0.00% 4 postgres [kernel.kallsyms] [k] local_apic_timer_interrupt
+ 0.16% 0.00% 2 postgres [kernel.kallsyms] [k] hrtimer_interrupt
+ 0.15% 0.15% 514 postgres postgres [.] deregister_seq_scan
+ 0.15% 0.00% 0 postgres [unknown] [.] 0x000000000150a8f8
+ 0.15% 0.01% 18 postgres [kernel.kallsyms] [k] __hrtimer_run_queues
+ 0.14% 0.00% 0 postgres [unknown] [.] 0x000000000150a698
+ 0.13% 0.13% 436 postgres postgres [.] hash_uint32
+ 0.13% 0.00% 2 postgres [kernel.kallsyms] [k] tick_sched_timer
+ 0.11% 0.00% 9 postgres libc-2.17.so [.] __GI___libc_write
+ 0.11% 0.00% 0 postgres [unknown] [.] 0x00000000015944d0
+ 0.10% 0.00% 1 postgres [kernel.kallsyms] [k] tick_sched_handle.isra.14
+ 0.09% 0.00% 2 postgres [kernel.kallsyms] [k] update_process_times
+ 0.09% 0.00% 10 postgres [kernel.kallsyms] [k] sys_write
+ 0.09% 0.09% 303 postgres postgres [.] hash_seq_init
+ 0.09% 0.00% 8 postgres [kernel.kallsyms] [k] vfs_write
+ 0.08% 0.08% 432 postgres postgres [.] compare_scalars
+ 0.08% 0.00% 13 postgres libc-2.17.so [.] __GI___libc_read
+ 0.08% 0.08% 258 postgres postgres [.] hash_search
+ 0.07% 0.00% 13 postgres [kernel.kallsyms] [k] do_sync_write
+ 0.07% 0.00% 12 postgres [kernel.kallsyms] [k] xfs_file_aio_write
+ 0.06% 0.00% 28 swapper [kernel.kallsyms] [k] apic_timer_interrupt
+ 0.06% 0.00% 6 swapper [kernel.kallsyms] [k] smp_apic_timer_interrupt
+ 0.06% 0.00% 10 postgres [kernel.kallsyms] [k] scheduler_tick
+ 0.06% 0.00% 4 postgres [kernel.kallsyms] [k] xfs_file_buffered_aio_write
+ 0.06% 0.00% 17 postgres [kernel.kallsyms] [k] sys_read
+ 0.05% 0.00% 11 swapper [kernel.kallsyms] [k] irq_exit
+ 0.05% 0.05% 171 postgres postgres [.] RelationCacheInvalidateEntry
+ 0.05% 0.00% 10 postgres [kernel.kallsyms] [k] vfs_read
+ 0.05% 0.00% 8 swapper [kernel.kallsyms] [k] do_softirq
+ 0.05% 0.00% 5 swapper [kernel.kallsyms] [k] call_softirq
+ 0.05% 0.00% 23 swapper [kernel.kallsyms] [k] __do_softirq
Regards
Huan
On 2017-02-09 06:55:00 +0000, Huan Ruan wrote: > Hi Andres > > > > Unfortunately perf files can't be interpreted on other systems unless > > you added all the referenced object files to it using perf archive. > > > > Sorry this was my first time using perf for profiling so didn't know that. > Also, the profile was collected without Postgres debuginfo installed. If > you need that or something else please let me know. > > > > Could you perhaps just send the first few lines of the report? > > > > The first screen of 'perf report -n' for subtransaction case is, > > Samples: 247K of event 'cycles', Event count (approx.): 155149593065 > Children Self Samples Command Shared Object > Symbol > + 51.26% 0.00% 0 postgres [unknown] > [.] 0x0000000003236e68 > + 48.66% 48.54% 117427 postgres postgres > [.] CatalogCacheIdInvalidate > + 38.44% 38.35% 92748 postgres postgres > [.] hash_seq_search > + 5.67% 5.66% 13683 postgres postgres > [.] CallSyscacheCallbacks > + 3.00% 2.99% 7234 postgres postgres > [.] LocalExecuteInvalidationMessage > + 1.00% 0.99% 2397 postgres postgres Yea, that was what I was thinking - we're replaying more invalidations than we'd need to, and we do so very frequently. That's quite expensive. Hmmm. > for create tables is, > > Samples: 342K of event 'cycles', Event count (approx.): 216348097599 > Children Self Samples Command Shared Object > Symbol > + 52.09% 0.00% 0 postgres [unknown] > [.] 0x000000009754f3a8 > + 49.09% 48.98% 164831 postgres postgres > [.] CatalogCacheIdInvalidate > + 38.75% 38.67% 130091 postgres postgres > [.] hash_seq_search > + 4.92% 4.90% 16494 postgres postgres > [.] CallSyscacheCallbacks > + 3.20% 3.19% 10736 postgres postgres > [.] LocalExecuteInvalidationMessage Same here. Let me ponder this for a bit. Thanks, Andres -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Hi Andres
I might have given you the create table perf data for the subtran case.
We profiled again with debug info on today, and the results are
Subtran:
DDL:
Children Self Command Shared Object Symbol
+ 94.84% 0.00% postgres postgres [.] ExecMakeTableFunctionResult
+ 94.84% 0.00% postgres postgres [.] pg_logical_slot_get_changes_guts
+ 94.80% 0.00% postgres postgres [.] LogicalDecodingProcessRecord
+ 94.45% 0.03% postgres postgres [.] ReorderBufferCommit
+ 94.19% 0.01% postgres postgres [.] ReorderBufferCleanupTXN
+ 94.11% 0.01% postgres postgres [.] ReorderBufferReturnChange
+ 94.08% 93.40% postgres postgres [.] AllocSetFree
DDL:
+ 93.88% 0.00% postgres postgres [.] ExecMakeTableFunctionResult
+ 93.88% 0.00% postgres postgres [.] pg_logical_slot_get_changes_guts
+ 93.83% 0.01% postgres postgres [.] LogicalDecodingProcessRecord
+ 93.78% 1.10% postgres postgres [.] ReorderBufferCommit
+ 87.69% 3.12% postgres postgres [.] LocalExecuteInvalidationMessage
+ 46.32% 46.21% postgres postgres [.] CatalogCacheIdInvalidate
+ 37.17% 0.37% postgres postgres [.] RelfilenodeMapInvalidateCallback
+ 36.71% 36.46% postgres postgres [.] hash_seq_search
+ 4.92% 4.91% postgres postgres [.] CallSyscacheCallbacks
Regards
Huan
Hi, On 2017-02-10 05:33:17 +0000, Huan Ruan wrote: > I might have given you the create table perf data for the subtran case. > > We profiled again with debug info on today, and the results are > > Subtran: > > Children Self Command Shared Object Symbol > + 94.84% 0.00% postgres postgres [.] > ExecMakeTableFunctionResult > + 94.84% 0.00% postgres postgres [.] > pg_logical_slot_get_changes_guts > + 94.80% 0.00% postgres postgres [.] > LogicalDecodingProcessRecord > + 94.45% 0.03% postgres postgres [.] > ReorderBufferCommit > + 94.19% 0.01% postgres postgres [.] > ReorderBufferCleanupTXN > + 94.11% 0.01% postgres postgres [.] > ReorderBufferReturnChange > + 94.08% 93.40% postgres postgres [.] > AllocSetFree Could you give a bit more detail abou thtis one - it indeed looks like different profile, but it's hard to nail down without more lines... Andres -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
Could you give a bit more detail abou thtis one - it indeed looks like
different profile, but it's hard to nail down without more lines...
First screen of unexpanded output:
…
+ 94.84% 0.00% postgres postgres [.] ExecMakeTableFunctionResult
+ 94.84% 0.00% postgres postgres [.] pg_logical_slot_get_changes_guts
+ 94.80% 0.00% postgres postgres [.] LogicalDecodingProcessRecord
+ 94.45% 0.03% postgres postgres [.] ReorderBufferCommit
+ 94.19% 0.01% postgres postgres [.] ReorderBufferCleanupTXN
+ 94.11% 0.01% postgres postgres [.] ReorderBufferReturnChange
+ 94.08% 93.40% postgres postgres [.] AllocSetFree
+ 2.33% 0.00% perf [kernel.kallsyms] [k] system_call_fastpath
+ 2.19% 0.00% perf libpthread-2.17.so [.] __write_nocancel
+ 2.17% 0.00% perf [kernel.kallsyms] [k] sys_write
+ 2.16% 0.00% perf [kernel.kallsyms] [k] vfs_write
+ 2.13% 0.00% perf [kernel.kallsyms] [k] do_sync_write
+ 2.13% 0.01% perf [kernel.kallsyms] [k] xfs_file_aio_write
+ 2.12% 0.00% perf [kernel.kallsyms] [k] xfs_file_buffered_aio_write
+ 2.01% 0.01% perf [kernel.kallsyms] [k] generic_file_buffered_write
+ 1.97% 0.00% postgres postgres [.] ServerLoop
+ 1.92% 0.00% postgres postgres [.] PostgresMain
+ 1.92% 0.00% postgres postgres [.] PostmasterMain
+ 1.92% 0.00% postgres postgres [.] main
+ 1.92% 0.00% postgres postgres [.] PortalRun
+ 1.92% 0.00% postgres postgres [.] PortalRunSelect
+ 1.92% 0.00% postgres postgres [.] standard_ExecutorRun
+ 1.92% 0.00% postgres postgres [.] ExecAgg
+ 1.92% 0.00% postgres postgres [.] ExecProcNode
+ 1.92% 0.00% postgres libc-2.17.so [.] __libc_start_main
+ 1.92% 0.00% postgres postgres [.] _start
+ 1.91% 0.00% postgres postgres [.] fetch_input_tuple
+ 1.91% 0.00% postgres postgres [.] ExecScan
+ 1.91% 0.00% postgres postgres [.] FunctionNext
+ 1.14% 0.01% swapper [kernel.kallsyms] [k] cpu_startup_entry
+ 1.12% 0.00% swapper [kernel.kallsyms] [k] start_secondary
+ 1.00% 0.00% swapper [kernel.kallsyms] [k] arch_cpu_idle
+ 1.00% 0.01% swapper [kernel.kallsyms] [k] cpuidle_idle_call
+ 0.92% 0.01% perf [kernel.kallsyms] [k] xfs_vm_write_begin
+ 0.71% 0.01% swapper [kernel.kallsyms] [k] cpuidle_enter_state
+ 0.69% 0.69% swapper [kernel.kallsyms] [k] intel_idle
+ 0.67% 0.67% perf [kernel.kallsyms] [k] copy_user_enhanced_fast_string
+ 0.58% 0.01% perf [kernel.kallsyms] [k] grab_cache_page_write_begin
+ 0.57% 0.19% postgres [kernel.kallsyms] [k] page_fault
+ 0.38% 0.00% postgres [kernel.kallsyms] [k] do_page_fault
+ 0.38% 0.01% postgres [kernel.kallsyms] [k] __do_page_fault
+ 0.34% 0.02% postgres [kernel.kallsyms] [k] handle_mm_fault
+ 0.33% 0.05% perf perf [.] cmd_record
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] ret_from_fork
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] kthread
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] worker_thread
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] process_one_work
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] bdi_writeback_workfn
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] wb_writeback
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] __writeback_inodes_wb
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] writeback_sb_inodes
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] __writeback_single_inode
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] do_writepages
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] xfs_vm_writepages
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] generic_writepages
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] write_cache_pages
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] __writepage
+ 0.32% 0.00% kworker/u50:1 [kernel.kallsyms] [k] xfs_vm_writepage
+ 0.32% 0.02% perf [kernel.kallsyms] [k] __block_write_begin
+ 0.32% 0.03% postgres [kernel.kallsyms] [k] apic_timer_interrupt
+ 0.32% 0.01% perf [kernel.kallsyms] [k] alloc_pages_current
+ 0.30% 0.00% perf [kernel.kallsyms] [k] __page_cache_alloc
+ 0.30% 0.03% perf [kernel.kallsyms] [k] __alloc_pages_nodemask
+ 0.29% 0.01% postgres [kernel.kallsyms] [k] smp_apic_timer_interrupt
+ 0.25% 0.01% postgres postgres [.] AllocSetAlloc
+ 0.25% 0.00% kswapd1 [kernel.kallsyms] [k] ret_from_fork
+ 0.25% 0.00% kswapd1 [kernel.kallsyms] [k] kthread
+ 0.25% 0.00% kswapd1 [kernel.kallsyms] [k] kswapd
+ 0.25% 0.01% perf [kernel.kallsyms] [k] add_to_page_cache_lru
+ 0.25% 0.00% kswapd1 [kernel.kallsyms] [k] balance_pgdat
+ 0.24% 0.00% kswapd0 [kernel.kallsyms] [k] ret_from_fork
+ 0.24% 0.00% kswapd0 [kernel.kallsyms] [k] kthread
+ 0.24% 0.00% kswapd0 [kernel.kallsyms] [k] kswapd
+ 0.24% 0.00% kswapd0 [kernel.kallsyms] [k] balance_pgdat
+ 0.24% 0.00% postgres postgres [.] MemoryContextAlloc
+ 0.24% 0.01% postgres [kernel.kallsyms] [k] local_apic_timer_interrupt
+ 0.24% 0.00% postgres postgres [.] ReorderBufferGetTupleBuf
+ 0.24% 0.09% perf [kernel.kallsyms] [k] get_page_from_freelist
+ 0.23% 0.00% postgres [kernel.kallsyms] [k] hrtimer_interrupt
+ 0.23% 0.00% perf [kernel.kallsyms] [k] xfs_vm_write_end
+ 0.23% 0.00% postgres libc-2.17.so [.] malloc
+ 0.23% 0.02% postgres libc-2.17.so [.] _int_malloc
+ 0.23% 0.01% perf [kernel.kallsyms] [k] generic_write_end
+ 0.23% 0.00% kworker/u50:1 [kernel.kallsyms] [k] xfs_cluster_write
+ 0.21% 0.00% kswapd1 [kernel.kallsyms] [k] shrink_zone
+ 0.21% 0.00% kswapd1 [kernel.kallsyms] [k] shrink_lruvec
+ 0.21% 0.00% kswapd1 [kernel.kallsyms] [k] shrink_inactive_list
+ 0.21% 0.01% postgres [kernel.kallsyms] [k] __hrtimer_run_queues
+ 0.20% 0.00% kswapd0 [kernel.kallsyms] [k] shrink_zone
+ 0.20% 0.00% kswapd0 [kernel.kallsyms] [k] shrink_lruvec
+ 0.20% 0.00% kswapd0 [kernel.kallsyms] [k] shrink_inactive_list
+ 0.20% 0.04% kworker/u50:1 [kernel.kallsyms] [k] xfs_convert_page.isra.11
+ 0.19% 0.00% postgres [kernel.kallsyms] [k] tick_sched_timer
+ 0.19% 0.00% postgres postgres [.] change_cb_wrapper
+ 0.17% 0.02% kswapd1 [kernel.kallsyms] [k] shrink_page_list
Expanded output for the expensive stuff at the top:
- 94.84% 0.00% postgres postgres [.] ExecMakeTableFunctionResult
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
- ServerLoop
- PostmasterMain
- main
- __libc_start_main
_start
- 94.84% 0.00% postgres postgres [.] pg_logical_slot_get_changes_guts
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
- ServerLoop
- PostmasterMain
- main
- __libc_start_main
_start
- 94.80% 0.00% postgres postgres [.] LogicalDecodingProcessRecord
LogicalDecodingProcessRecord
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
- ServerLoop
- PostmasterMain
- main
- __libc_start_main
_start
- 94.45% 0.03% postgres postgres [.] ReorderBufferCommit
ReorderBufferCommit
LogicalDecodingProcessRecord
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
- ServerLoop
- PostmasterMain
- main
- __libc_start_main
_start
- 94.19% 0.01% postgres postgres [.] ReorderBufferCleanupTXN
- ReorderBufferCleanupTXN
- ReorderBufferCleanupTXN
ReorderBufferCommit
LogicalDecodingProcessRecord
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
ServerLoop
PostmasterMain
main
__libc_start_main
_start
- 94.11% 0.01% postgres postgres [.] ReorderBufferReturnChange
ReorderBufferReturnChange
ReorderBufferCleanupTXN
ReorderBufferCleanupTXN
ReorderBufferCommit
LogicalDecodingProcessRecord
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
ServerLoop
PostmasterMain
main
__libc_start_main
_start
- 94.08% 93.40% postgres postgres [.] AllocSetFree
- AllocSetFree
- ReorderBufferReturnChange
ReorderBufferCleanupTXN
ReorderBufferCleanupTXN
ReorderBufferCommit
LogicalDecodingProcessRecord
pg_logical_slot_get_changes_guts
- ExecMakeTableFunctionResult
- FunctionNext
ExecScan
ExecProcNode
fetch_input_tuple
ExecAgg
ExecProcNode
standard_ExecutorRun
PortalRunSelect
PortalRun
PostgresMain
ServerLoop
PostmasterMain
main
__libc_start_main
_start
On 2017-02-10 06:33:30 +0000, Huan Ruan wrote: > > > > > > Could you give a bit more detail abou thtis one - it indeed looks like > > different profile, but it's hard to nail down without more lines... > > > > > First screen of unexpanded output: > > … > > + 94.84% 0.00% postgres postgres > [.] ExecMakeTableFunctionResult > + 94.84% 0.00% postgres postgres > [.] pg_logical_slot_get_changes_guts > + 94.80% 0.00% postgres postgres > [.] LogicalDecodingProcessRecord > + 94.45% 0.03% postgres postgres > [.] ReorderBufferCommit > + 94.19% 0.01% postgres postgres > [.] ReorderBufferCleanupTXN > + 94.11% 0.01% postgres postgres > [.] ReorderBufferReturnChange > + 94.08% 93.40% postgres postgres > [.] AllocSetFree > > + 2.33% 0.00% perf [kernel.kallsyms] > [k] system_call_fastpath Ok, so this is likely a known issue. If you're in the position to try, there's a set of patches to address this: http://archives.postgresql.org/message-id/20ca0c69-e8c3-cb50-4456-f03908c672ec%402ndquadrant.com Andres -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
On Fri, Feb 10, 2017 at 6:20 PM, Andres Freund <andres@anarazel.de> wrote:
On 2017-02-10 06:33:30 +0000, Huan Ruan wrote:
> >
> >
> > Could you give a bit more detail abou thtis one - it indeed looks like
> > different profile, but it's hard to nail down without more lines...
> >
> >
> First screen of unexpanded output:
>
> …
>
> + 94.84% 0.00% postgres postgres
> [.] ExecMakeTableFunctionResult
> + 94.84% 0.00% postgres postgres
> [.] pg_logical_slot_get_changes_guts
> + 94.80% 0.00% postgres postgres
> [.] LogicalDecodingProcessRecord
> + 94.45% 0.03% postgres postgres
> [.] ReorderBufferCommit
> + 94.19% 0.01% postgres postgres
> [.] ReorderBufferCleanupTXN
> + 94.11% 0.01% postgres postgres
> [.] ReorderBufferReturnChange
> + 94.08% 93.40% postgres postgres
> [.] AllocSetFree
>
> + 2.33% 0.00% perf [kernel.kallsyms]
> [k] system_call_fastpath
Ok, so this is likely a known issue. If you're in the position to try,
there's a set of patches to address this:
http://archives.postgresql.org/message-id/20ca0c69-e8c3- cb50-4456-f03908c672ec% 402ndquadrant.com
Andres
Hi Andres,
I've been working with Huan on this. I tried those patches, and can confirm that they resolve the subtransaction issue.Thanks,
Nick
Hi, On 2017-02-10 19:01:55 +1100, Nick Barnes wrote: > I've been working with Huan on this. I tried those patches, and can confirm > that they resolve the subtransaction issue. That issue should be fixed in the set of release from Thursday. The other issue has partially been addressed *after* that release, sorry for that. Greetings, Andres Freund -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs