Re: BUG #14530: Logical Decoding Slowness

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