Re: BUG #14530: Logical Decoding Slowness

>
>
> 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