Re: strange slow query - lost lot of time somewhere

On Mon, 2 May 2022 at 16:09, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> wrote:
>
>
>
> po 2. 5. 2022 v 16:02 odesílatel Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> napsal:
>> there is just shared buffers changed to 32GB and work_mem to 70MB. Unfortunately - it is in production environment with customer 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