Re: strange slow query - lost lot of time somewhere - Mailing list pgsql-hackers
| From | Matthias van de Meent |
|---|---|
| Subject | Re: strange slow query - lost lot of time somewhere |
| Date | |
| Msg-id | CAEze2WhRovW3DVXzRkRL5fr2XtEisH8Nk0Kff_D2q+SbKtapJA@mail.gmail.com Whole thread Raw |
| In response to | Re: strange slow query - lost lot of time somewhere (Pavel Stehule <pavel.stehule@gmail.com>) |
| Responses |
Re: strange slow query - lost lot of time somewhere
|
| List | pgsql-hackers |
On Mon, 2 May 2022 at 16:09, Pavel Stehule <pavel.stehule@gmail.com> wrote: > > > > po 2. 5. 2022 v 16:02 odesílatel Pavel Stehule <pavel.stehule@gmail.com> napsal: >> there is just shared buffers changed to 32GB and work_mem to 70MB. Unfortunately - it is in production environment withcustomer data, so I cannot to play too much >> >> This is perf of slow >> >> 25,94% postmaster [kernel.kallsyms] [k] clear_page_erms >> 11,06% postmaster [kernel.kallsyms] [k] page_fault >> 5,51% postmaster [kernel.kallsyms] [k] prepare_exit_to_usermode >> 5,18% postmaster [kernel.kallsyms] [k] __list_del_entry_valid >> 5,15% postmaster libc-2.28.so [.] __memset_avx2_erms >> 3,99% postmaster [kernel.kallsyms] [k] unmap_page_range >> 3,07% postmaster postgres [.] hash_search_with_hash_value >> 2,73% postmaster [kernel.kallsyms] [k] cgroup_throttle_swaprate >> 2,49% postmaster postgres [.] heap_page_prune_opt >> 1,92% postmaster [kernel.kallsyms] [k] try_charge >> 1,85% postmaster [kernel.kallsyms] [k] swapgs_restore_regs_and_return_to_usermode >> 1,82% postmaster [kernel.kallsyms] [k] error_entry >> 1,73% postmaster postgres [.] _bt_checkkeys >> 1,48% postmaster [kernel.kallsyms] [k] free_pcppages_bulk >> 1,35% postmaster [kernel.kallsyms] [k] get_page_from_freelist >> 1,20% postmaster [kernel.kallsyms] [k] __pagevec_lru_add_fn >> 1,08% postmaster [kernel.kallsyms] [k] percpu_ref_put_many.constprop.84 >> 1,08% postmaster postgres [.] 0x00000000003c1be6 >> 1,06% postmaster [kernel.kallsyms] [k] get_mem_cgroup_from_mm.part.49 >> 0,86% postmaster [kernel.kallsyms] [k] __handle_mm_fault >> 0,79% postmaster [kernel.kallsyms] [k] mem_cgroup_charge >> 0,70% postmaster [kernel.kallsyms] [k] release_pages >> 0,61% postmaster postgres [.] _bt_checkpage >> 0,61% postmaster [kernel.kallsyms] [k] free_pages_and_swap_cache >> 0,60% postmaster [kernel.kallsyms] [k] handle_mm_fault >> 0,57% postmaster postgres [.] tbm_iterate >> 0,56% postmaster [kernel.kallsyms] [k] __count_memcg_events.part.70 >> 0,55% postmaster [kernel.kallsyms] [k] __mod_memcg_lruvec_state >> 0,52% postmaster postgres [.] 0x000000000015f6e5 >> 0,50% postmaster [kernel.kallsyms] [k] prep_new_page >> 0,49% postmaster [kernel.kallsyms] [k] __do_page_fault >> 0,46% postmaster [kernel.kallsyms] [k] _raw_spin_lock >> 0,44% postmaster [kernel.kallsyms] [k] do_anonymous_page >> >> This is fast >> >> 21,13% postmaster postgres [.] hash_search_with_hash_value >> 15,33% postmaster postgres [.] heap_page_prune_opt >> 10,22% postmaster libc-2.28.so [.] __memset_avx2_erms >> 10,00% postmaster postgres [.] _bt_checkkeys >> 6,23% postmaster postgres [.] 0x00000000003c1be6 >> 4,94% postmaster postgres [.] _bt_checkpage >> 2,85% postmaster postgres [.] tbm_iterate >> 2,31% postmaster postgres [.] nocache_index_getattr >> 2,13% postmaster postgres [.] pg_qsort >> 1,58% postmaster postgres [.] heap_hot_search_buffer >> 1,58% postmaster postgres [.] FunctionCall2Coll >> 1,58% postmaster postgres [.] 0x000000000015f6e5 >> 1,17% postmaster postgres [.] LWLockRelease >> 0,85% postmaster libc-2.28.so [.] __memcmp_avx2_movbe >> 0,64% postmaster postgres [.] 0x00000000003e4233 >> 0,54% postmaster postgres [.] hash_bytes >> 0,53% postmaster postgres [.] 0x0000000000306fbb >> 0,53% postmaster postgres [.] LWLockAcquire >> 0,42% postmaster postgres [.] 0x00000000003c1c6f >> 0,42% postmaster postgres [.] _bt_compare >> > > It looks so memoization allocate lot of memory - maybe there are some temporal memory leak Memoization doesn't leak memory any more than hash tables do; so I doubt that that is the issue. > Performance counter stats for process id '4004464': > > 84,26 msec task-clock # 0,012 CPUs utilized > 3 context-switches # 0,036 K/sec > 0 cpu-migrations # 0,000 K/sec > 19 page-faults # 0,225 K/sec > 0 cycles # 0,000 GHz > 106 873 995 instructions > 20 225 431 branches # 240,026 M/sec > 348 834 branch-misses # 1,72% of all branches > > 7,106142051 seconds time elapsed > Assuming the above was for the fast query > Performance counter stats for process id '4004464': > > 1 116,97 msec task-clock # 0,214 CPUs utilized > 4 context-switches # 0,004 K/sec > 0 cpu-migrations # 0,000 K/sec > 99 349 page-faults # 0,089 M/sec > 0 cycles # 0,000 GHz > 478 842 411 instructions > 89 495 015 branches # 80,123 M/sec > 1 014 763 branch-misses # 1,13% of all branches > > 5,221116331 seconds time elapsed ... and this for the slow one: It seems like this system is actively swapping memory; which has a negative impact on your system. This seems to be indicated by the high amount of page faults and the high amount of time spent in the kernel (as per the perf report one mail earlier). Maybe too much (work)memory was assigned and the machine you're running on doesn't have that amount of memory left? Either way, seeing that so much time is spent in the kernel I don't think that PostgreSQL is the main/only source of the slow query here, so I don't think pgsql-hackers is the right place to continue with this conversation. Regards, Matthias PS. Maybe next time start off in https://www.postgresql.org/list/pgsql-performance/ if you have performance issues with unknown origin. The wiki also has some nice tips to debug performance issues: https://wiki.postgresql.org/wiki/Slow_Query_Questions
pgsql-hackers by date: