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 | CAGgcTZsbij-N17fV_AaJ84U6iURo7rktOaUP3sqY6rt+bqkwMw@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 |
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
pgsql-bugs by date: