Re: [BUGS] BUG #14530: Logical Decoding Slowness - Mailing list pgsql-bugs
| From | Huan Ruan |
|---|---|
| Subject | Re: [BUGS] BUG #14530: Logical Decoding Slowness |
| Date | |
| Msg-id | CAGgcTZs6w87uTdkRHOOmDDP7KuZuHvQqq3N_M_Z6gqT34XBs2w@mail.gmail.com Whole thread Raw |
| In response to | Re: [BUGS] BUG #14530: Logical Decoding Slowness (Andres Freund <andres@anarazel.de>) |
| Responses |
Re: [BUGS] BUG #14530: Logical Decoding Slowness
(Andres Freund <andres@anarazel.de>)
|
| List | 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
pgsql-bugs by date: