Thread: strange slow query - lost lot of time somewhere

On Mon, 2 May 2022 at 11:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> Hi
>
> I found a query that is significantly slower with more memory

Which PostgreSQL version did you use? Did you enable assert checking?
Do you have an example database setup to work with?

> plan 2
>  QUERY PLAN
> ----------------
>  Nested Loop Anti Join  (cost=46.53..2914.58 rows=1 width=16) (actual time=18.306..23.065 rows=32 loops=1)
> ...
>  Execution Time: 451.161 ms

Truly strange; especially the 418ms difference between execution time
and the root node's "actual time". I haven't really seen such
differences happen, except when concurrent locks were held at the
table / index level.

> plan 1 - fast https://explain.depesz.com/s/XM1f
>
> plan 2 - slow https://explain.depesz.com/s/2rBw
>
> Strange - the time of last row is +/- same, but execution time is 10x worse

The only difference between the two plans that I see is that plan 1
doesn't use memoization, whereas plan 2 does use 2 memoize plan nodes
(one of 66 misses; one of 342 misses). The only "expensive" operation
that I see in memoize nodes is the check for memory size in
assert-enabled builds; and that should have very low overhead
considering that the size of the memoized data is only 8kB and 25kB
respectively.

po 2. 5. 2022 v 15:28 odesílatel Matthias van de Meent <boekewurm+postgres@gmail.com> napsal:

On Mon, 2 May 2022 at 11:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> Hi
>
> I found a query that is significantly slower with more memory

Which PostgreSQL version did you use? Did you enable assert checking?
Do you have an example database setup to work with?

> plan 2
>  QUERY PLAN
> ----------------
>  Nested Loop Anti Join  (cost=46.53..2914.58 rows=1 width=16) (actual time=18.306..23.065 rows=32 loops=1)
> ...
>  Execution Time: 451.161 ms

Truly strange; especially the 418ms difference between execution time
and the root node's "actual time". I haven't really seen such
differences happen, except when concurrent locks were held at the
table / index level.

> plan 1 - fast https://explain.depesz.com/s/XM1f
>
> plan 2 - slow https://explain.depesz.com/s/2rBw
>
> Strange - the time of last row is +/- same, but execution time is 10x worse

The only difference between the two plans that I see is that plan 1
doesn't use memoization, whereas plan 2 does use 2 memoize plan nodes
(one of 66 misses; one of 342 misses). The only "expensive" operation
that I see in memoize nodes is the check for memory size in
assert-enabled builds; and that should have very low overhead
considering that the size of the memoized data is only 8kB and 25kB
respectively.

This is PostgreSQL 14 used in production environment

 (2022-05-02 15:37:29) prd_aukro=# show debug_assertions ;
┌──────────────────┐
│ debug_assertions │
├──────────────────┤
│ off              │
└──────────────────┘
(1 řádka)

Čas: 0,295 ms
(2022-05-02 15:37:35) prd_aukro=# select version();
┌────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                                version                                                 │
├────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ PostgreSQL 14.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit │
└────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(1 řádka)
Čas: 0,629 ms

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

Regards

Pavel

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 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

David Rowley <dgrowleyml@gmail.com> writes:
> On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>> I found a query that is significantly slower with more memory

> If it was work_mem you increased, it seems strange that the plan would
> switch over to using a Nested Loop / Memoize plan.

Yeah, there's something unexplained there.

I spent some time studying cost_memoize_rescan, and the only
conclusions I arrived at were that the variable names are poorly
chosen and the comments are unhelpful.  For instance, one would
think that est_entry_bytes is the expected size of one cache entry,
but it seems to actually be the total space that would be occupied
if the whole input relation were loaded into the cache.

  And
the est_cache_entries computation seems nonsensical; if it does
make sense, the comment sure doesn't illuminate why.

On Tue, 3 May 2022 at 11:02, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> David Rowley <dgrowleyml@gmail.com> writes:
> > On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> >> I found a query that is significantly slower with more memory
>
> > If it was work_mem you increased, it seems strange that the plan would
> > switch over to using a Nested Loop / Memoize plan.
>
> Yeah, there's something unexplained there.
>
> I think that the most probable explanation for the symptoms is that
> cost_memoize_rescan is computing some insane value for est_entries,
> causing ExecInitMemoize to allocate-and-zero a huge hash table,
> which ExecEndMemoize then frees again.  Neither of those steps
> gets counted into any plan node's runtime, but EXPLAIN's total
> execution time will include them.  An insane value for est_entries
> could perhaps go along with a cost misestimate that convinces the
> planner to include the memoize even though it seems pointless.

That seems pretty unlikely to me. est_entries is based on the minimum
value of the expected number of total cache entries and the ndistinct
value. ndistinct cannot be insane here as ndistinct is never going to
be higher than the number of calls, which is the row estimate from the
outer side of the join. That's 91 in both cases here.   As far as I
can see, that's just going to make a table of 128 buckets.

I'm open to making improvements to the comments in that area. I do
remember spending quite a bit of time trying to make things as clear
as possible as it is fairly complex what's going on there.

On Tue, 3 May 2022 at 13:43, David G. Johnston
<david.g.johnston@gmail.com> wrote:
> hit_ratio = (est_entries / ndistinct) - (ndistinct / calls) || clamp to 0.0
> I don't understand the adjustment factor ndistinct/calls

I've attached a spreadsheet showing you the impact of subtracting
(ndistinct / calls).  What this is correcting for is the fact that the
first scan from each unique value is a cache miss.  The more calls we
have, the more hits we'll get.  If there was only 1 call per distinct
value then there'd never be any hits. Without subtracting (ndistinct /
calls) and assuming there's space in the cache for each ndistinct
value, we'd assume 100% cache hit ratio if calls == ndistinct.  What
we should assume in that case is a 0% hit ratio as the first scan for
each distinct parameter must always be a miss as we've never had a
chance to cache any tuples for it yet.

On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> I found a query that is significantly slower with more memory

Can you clarify what you mean here?  More memory was installed on the
machine? or work_mem was increased? or?

> plan 1 - fast https://explain.depesz.com/s/XM1f
>
> plan 2 - slow https://explain.depesz.com/s/2rBw

If it was work_mem you increased, it seems strange that the plan would
switch over to using a Nested Loop / Memoize plan.  Only 91 rows are
estimated on the outer side of the join. It's hard to imagine that
work_mem was so low that the Memoize costing code thought there would
ever be cache evictions.

> Strange - the time of last row is +/- same, but execution time is 10x worse
>
> It looks like slow environment cleaning

Can you also show EXPLAIN for the Memoize plan without ANALYZE?

Does the slowness present every time that plan is executed?

Can you show the EXPLAIN ANALYZE of the nested loop plan with
enable_memoize = off?  You may ned to disable hash and merge join.

David

po 2. 5. 2022 v 23:48 odesílatel David Rowley <dgrowleyml@gmail.com> napsal:

On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> I found a query that is significantly slower with more memory

Can you clarify what you mean here?  More memory was installed on the
machine? or work_mem was increased? or?

> plan 1 - fast https://explain.depesz.com/s/XM1f
>
> plan 2 - slow https://explain.depesz.com/s/2rBw

If it was work_mem you increased, it seems strange that the plan would
switch over to using a Nested Loop / Memoize plan.  Only 91 rows are
estimated on the outer side of the join. It's hard to imagine that
work_mem was so low that the Memoize costing code thought there would
ever be cache evictions.

> Strange - the time of last row is +/- same, but execution time is 10x worse
>
> It looks like slow environment cleaning

Can you also show EXPLAIN for the Memoize plan without ANALYZE?

yes - it is strange - it is just slow without execution

 ┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                                                                                  QUERY PLAN                                                                                                  │
├──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Nested Loop Anti Join  (cost=59.62..3168.15 rows=1 width=16)                                                                                                                                                 │
│   ->  Nested Loop Anti Join  (cost=59.34..3165.24 rows=1 width=16)                                                                                                                                           │
│         ->  Nested Loop Semi Join  (cost=58.48..3133.09 rows=1 width=16)                                                                                                                                     │
│               ->  Bitmap Heap Scan on item itembo0_  (cost=57.34..2708.22 rows=11 width=16)                                                                                                                  │
│                     Recheck Cond: ((ending_time IS NULL) OR ((status_id = ANY ('{1,4,5}'::bigint[])) AND (CURRENT_TIMESTAMP < ending_time) AND (starting_time <= CURRENT_TIMESTAMP)))                        │
│                     Filter: ((to_expose_date IS NULL) AND (status_id = ANY ('{1,4,5}'::bigint[])) AND (starting_time <= CURRENT_TIMESTAMP) AND ((ending_time IS NULL) OR (CURRENT_TIMESTAMP < ending_time))) │
│                     ->  BitmapOr  (cost=57.34..57.34 rows=1751 width=0)                                                                                                                                      │
│                           ->  Bitmap Index Scan on stehule354  (cost=0.00..2.08 rows=1 width=0)                                                                                                              │
│                                 Index Cond: (ending_time IS NULL)                                                                                                                                            │
│                           ->  Bitmap Index Scan on stehule1010  (cost=0.00..55.26 rows=1751 width=0)                                                                                                         │
│                                 Index Cond: ((status_id = ANY ('{1,4,5}'::bigint[])) AND (ending_time > CURRENT_TIMESTAMP) AND (starting_time <= CURRENT_TIMESTAMP))                                         │
│               ->  Nested Loop  (cost=1.14..37.71 rows=91 width=8)                                                                                                                                            │
│                     ->  Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2__1  (cost=0.57..3.80 rows=91 width=16)                                                               │
│                           Index Cond: (item_id = itembo0_.id)                                                                                                                                                │
│                     ->  Memoize  (cost=0.57..2.09 rows=1 width=8)                                                                                                                                            │
│                           Cache Key: itemsharei2__1.item_image_id                                                                                                                                            │
│                           Cache Mode: logical                                                                                                                                                                │
│                           ->  Index Only Scan using pk_item_image on item_image itemimageb3__1  (cost=0.56..2.08 rows=1 width=8)                                                                             │
│                                 Index Cond: (id = itemsharei2__1.item_image_id)                                                                                                                              │
│         ->  Nested Loop  (cost=0.85..32.14 rows=1 width=8)                                                                                                                                                   │
│               ->  Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2_  (cost=0.57..3.80 rows=91 width=16)                                                                       │
│                     Index Cond: (item_id = itembo0_.id)                                                                                                                                                      │
│               ->  Memoize  (cost=0.29..1.72 rows=1 width=8)                                                                                                                                                  │
│                     Cache Key: itemsharei2_.item_image_id                                                                                                                                                    │
│                     Cache Mode: logical                                                                                                                                                                      │
│                     ->  Index Only Scan using stehule3001 on item_image itemimageb3_  (cost=0.28..1.71 rows=1 width=8)                                                                                       │
│                           Index Cond: (id = itemsharei2_.item_image_id)                                                                                                                                      │
│   ->  Index Only Scan using ixfk_ima_itemid on item_missing_attribute itemmissin1_  (cost=0.28..1.66 rows=1 width=8)                                                                                         │
│         Index Cond: (item_id = itembo0_.id)                                                                                                                                                                  │
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(29 řádek)

Čas: 420,392 ms

Does the slowness present every time that plan is executed?

looks yes

 

Can you show the EXPLAIN ANALYZE of the nested loop plan with
enable_memoize = off?  You may ned to disable hash and merge join.

┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                                                                           QUERY PLAN                                                                                            │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Nested Loop Anti Join  (cost=1093.22..4488.89 rows=1 width=16) (actual time=5.723..60.470 rows=13 loops=1)                                                                                      │
│   ->  Nested Loop Anti Join  (cost=1092.94..4485.97 rows=1 width=16) (actual time=5.165..60.368 rows=41 loops=1)                                                                                │
│         ->  Gather  (cost=1001.70..4391.26 rows=1 width=16) (actual time=1.909..56.913 rows=41 loops=1)                                                                                         │
│               Workers Planned: 2                                                                                                                                                                │
│               Workers Launched: 2                                                                                                                                                               │
│               ->  Nested Loop Semi Join  (cost=1.70..3391.16 rows=1 width=16) (actual time=22.032..39.253 rows=14 loops=3)                                                                      │
│                     ->  Parallel Index Only Scan using stehule1010 on item itembo0_  (cost=0.57..2422.83 rows=5 width=16) (actual time=21.785..38.851 rows=14 loops=3)                          │
│                           Index Cond: ((status_id = ANY ('{1,4,5}'::bigint[])) AND (starting_time <= CURRENT_TIMESTAMP))                                                                        │
│                           Filter: ((to_expose_date IS NULL) AND ((ending_time IS NULL) OR (CURRENT_TIMESTAMP < ending_time)))                                                                   │
│                           Rows Removed by Filter: 1589                                                                                                                                          │
│                           Heap Fetches: 21                                                                                                                                                      │
│                     ->  Nested Loop  (cost=1.13..192.76 rows=91 width=8) (actual time=0.029..0.029 rows=1 loops=41)                                                                             │
│                           ->  Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2__1  (cost=0.57..3.80 rows=91 width=16) (actual time=0.015..0.015 rows=1 loops=41) │
│                                 Index Cond: (item_id = itembo0_.id)                                                                                                                             │
│                                 Heap Fetches: 2                                                                                                                                                 │
│                           ->  Index Only Scan using pk_item_image on item_image itemimageb3__1  (cost=0.56..2.08 rows=1 width=8) (actual time=0.013..0.013 rows=1 loops=41)                     │
│                                 Index Cond: (id = itemsharei2__1.item_image_id)                                                                                                                 │
│                                 Heap Fetches: 2                                                                                                                                                 │
│         ->  Hash Join  (cost=91.24..94.71 rows=1 width=8) (actual time=0.084..0.084 rows=0 loops=41)                                                                                            │
│               Hash Cond: (itemsharei2_.item_image_id = itemimageb3_.id)                                                                                                                         │
│               ->  Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2_  (cost=0.57..3.80 rows=91 width=16) (actual time=0.003..0.004 rows=6 loops=41)               │
│                     Index Cond: (item_id = itembo0_.id)                                                                                                                                         │
│                     Heap Fetches: 2                                                                                                                                                             │
│               ->  Hash  (cost=67.41..67.41 rows=1861 width=8) (actual time=3.213..3.214 rows=3950 loops=1)                                                                                      │
│                     Buckets: 4096 (originally 2048)  Batches: 1 (originally 1)  Memory Usage: 187kB                                                                                             │
│                     ->  Index Only Scan using stehule3001 on item_image itemimageb3_  (cost=0.28..67.41 rows=1861 width=8) (actual time=0.029..2.479 rows=3950 loops=1)                         │
│                           Heap Fetches: 2203                                                                                                                                                    │
│   ->  Index Only Scan using ixfk_ima_itemid on item_missing_attribute itemmissin1_  (cost=0.28..1.66 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=41)                                 │
│         Index Cond: (item_id = itembo0_.id)                                                                                                                                                     │
│         Heap Fetches: 0                                                                                                                                                                         │
│ Planning Time: 1.471 ms                                                                                                                                                                         │
│ Execution Time: 60.570 ms                                                                                                                                                                       │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(32 řádek)

Čas: 62,982 ms
 

David

Pavel Stehule <pavel.stehule@gmail.com> writes:
> there is really something strange (see attached file). Looks so this issue
> is much more related to planning time than execution time

You sure there's not something taking an exclusive lock on one of these
tables every so often?

                        regards, tom lane

On Tue, 3 May 2022 at 17:02, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> út 3. 5. 2022 v 6:57 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:
>> You sure there's not something taking an exclusive lock on one of these
>> tables every so often?
>
> I am almost sure, I can see this issue only every time when I set a higher work mem. I don't see this issue in other cases.

hmm, I don't think the query being blocked on a table lock would cause
this behaviour. As far as I know, all table locks should be obtained
before the timer starts for the "Execution Time" timer in EXPLAIN
ANALYZE.  However, locks are obtained on indexes at executor startup,
so if there was some delay in obtaining a lock on the index it would
show up this way.  I just don't know of anything that obtains a
conflicting lock on an index without the same conflicting lock on the
table that the index belongs to.

I do agree that the perf report does indicate that the extra time is
taken due to some large amount of memory being allocated. I just can't
quite see how that would happen in Memoize given that
estimate_num_groups() clamps the distinct estimate as the number of
input rows, which is 91 in both cases in your problem query.

Are you able to run the Memoize query in psql with \watch 0.1 for a
few seconds while you do:

perf record --call-graph dwarf --pid <pid> sleep 2

then send along the perf report.

I locally hacked build_hash_table() in nodeMemoize.c to make the
hashtable 100 million elements and I see my perf report for a trivial
Memoize query come up as:

+   99.98%     0.00%  postgres  postgres           [.] _start
+   99.98%     0.00%  postgres  libc.so.6          [.]
__libc_start_main_alias_2 (inlined)
+   99.98%     0.00%  postgres  libc.so.6          [.] __libc_start_call_main
+   99.98%     0.00%  postgres  postgres           [.] main
+   99.98%     0.00%  postgres  postgres           [.] PostmasterMain
+   99.98%     0.00%  postgres  postgres           [.] ServerLoop
+   99.98%     0.00%  postgres  postgres           [.] BackendStartup (inlined)
+   99.98%     0.00%  postgres  postgres           [.] BackendRun (inlined)
+   99.98%     0.00%  postgres  postgres           [.] PostgresMain
+   99.98%     0.00%  postgres  postgres           [.] exec_simple_query
+   99.98%     0.00%  postgres  postgres           [.] PortalRun
+   99.98%     0.00%  postgres  postgres           [.] FillPortalStore
+   99.98%     0.00%  postgres  postgres           [.] PortalRunUtility
+   99.98%     0.00%  postgres  postgres           [.] standard_ProcessUtility
+   99.98%     0.00%  postgres  postgres           [.] ExplainQuery
+   99.98%     0.00%  postgres  postgres           [.] ExplainOneQuery
+   99.95%     0.00%  postgres  postgres           [.] ExplainOnePlan
+   87.87%     0.00%  postgres  postgres           [.] standard_ExecutorStart
+   87.87%     0.00%  postgres  postgres           [.] InitPlan (inlined)
+   87.87%     0.00%  postgres  postgres           [.] ExecInitNode
+   87.87%     0.00%  postgres  postgres           [.] ExecInitNestLoop
+   87.87%     0.00%  postgres  postgres           [.] ExecInitMemoize
+   87.87%     0.00%  postgres  postgres           [.]
build_hash_table (inlined) <----
+   87.87%     0.00%  postgres  postgres           [.] memoize_create (inlined)
+   87.87%     0.00%  postgres  postgres           [.]
memoize_allocate (inlined)
+   87.87%     0.00%  postgres  postgres           [.]
MemoryContextAllocExtended
+   87.87%     0.00%  postgres  postgres           [.] memset (inlined)

Failing that, are you able to pg_dump these tables and load them into
a PostgreSQL instance that you can play around with and patch?
Provided you can actually recreate the problem on that instance.

David

Additional three ways to figure that one (all are IMHO production safe):
a) already mentioned perf with --call-graph dwarf -p PID
b) strace -p PID -e 'mmap' # verify if mmap() NULL is not having MAP_ANONYMOUS flag, size of mmap() request will somehow match work_mem sizing
c) gdb -p PID and then breakpoint for mmap and verify each mmap() # check MAP_ANONYMOUS as above

[1] - https://www.postgresql.org/message-id/CAFj8pRAo5CrF8mpPxMvnBYFSqu4HYDqRsQnLqGphckNHkHosFg%40mail.gmail.com

-J.

Hi Pavel,

> I have not debug symbols, so I have not more details now
> Breakpoint 1 at 0x7f557f0c16c0
> (gdb) c
> Continuing.

> Breakpoint 1, 0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
> (gdb) bt
> #0  0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
> #1  0x00007f557f04dd91 in sysmalloc () from /lib64/libc.so.6
> #2  0x00007f557f04eaa9 in _int_malloc () from /lib64/libc.so.6
> #3  0x00007f557f04fb1e in malloc () from /lib64/libc.so.6
> #4  0x0000000000932134 in AllocSetAlloc ()
> #5  0x00000000009376cf in MemoryContextAllocExtended ()
> #6  0x00000000006ad915 in ExecInitMemoize ()

Well the PGDG repo have the debuginfos (e.g. postgresql14-debuginfo) rpms / dpkgs(?) so I hope you are basically 1 command away of being able to debug it further what happens in ExecInitMemoize()
Those packages seem to be safe as they modify only /usr/lib/debug so should not have any impact on production workload.

-J.

út 3. 5. 2022 v 6:57 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:

Pavel Stehule <pavel.stehule@gmail.com> writes:
> there is really something strange (see attached file). Looks so this issue
> is much more related to planning time than execution time

You sure there's not something taking an exclusive lock on one of these
tables every so often?

I am almost sure, I can see this issue only every time when I set a higher work mem. I don't see this issue in other cases.

On Mon, May 2, 2022 at 10:02 PM Pavel Stehule <pavel.stehule@gmail.com> wrote:

út 3. 5. 2022 v 6:57 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:

Pavel Stehule <pavel.stehule@gmail.com> writes:
> there is really something strange (see attached file). Looks so this issue
> is much more related to planning time than execution time

You sure there's not something taking an exclusive lock on one of these
tables every so often?

I am almost sure, I can see this issue only every time when I set a higher work mem. I don't see this issue in other cases.

What are the values of work_mem and hash_mem_multiplier for the two cases?

David J.

On Thu, 5 May 2022 at 19:26, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> čt 5. 5. 2022 v 8:51 odesílatel Jakub Wartak <Jakub.Wartak@tomtom.com> napsal:
>> > Breakpoint 1, 0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
>> > (gdb) bt
>> > #0  0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
>> > #1  0x00007f557f04dd91 in sysmalloc () from /lib64/libc.so.6
>> > #2  0x00007f557f04eaa9 in _int_malloc () from /lib64/libc.so.6
>> > #3  0x00007f557f04fb1e in malloc () from /lib64/libc.so.6
>> > #4  0x0000000000932134 in AllocSetAlloc ()
>> > #5  0x00000000009376cf in MemoryContextAllocExtended ()
>> > #6  0x00000000006ad915 in ExecInitMemoize ()
>>
>> Well the PGDG repo have the debuginfos (e.g. postgresql14-debuginfo) rpms / dpkgs(?) so I hope you are basically 1 command away of being able to debug it further what happens in ExecInitMemoize()
>> Those packages seem to be safe as they modify only /usr/lib/debug so should not have any impact on production workload.
>
> I just have to wait for admin action - I have no root rights for the server.

Looking at ExecInitMemoize() it's hard to see what could take such a
long time other than the build_hash_table().  Tom did mention this,
but I can't quite see how the size given to that function could be
larger than 91 in your case.

If you get the debug symbols installed, can you use gdb to

break nodeMemoize.c:268
p size

maybe there's something I'm missing following the code and maybe there
is some way that est_entries is not set to what I thought it was.

It would also be good to see the same perf report again after the
debug symbols are installed in order to resolve those unresolved
function names.

David

On Fri, 6 May 2022 at 17:52, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> Breakpoint 1, build_hash_table (size=4369066, mstate=0xfc7f08) at nodeMemoize.c:268
> 268 if (size == 0)
> (gdb) p size
> $1 = 4369066

Thanks for the report.  I think I now see the problem.  Looking at
[1], it seems that's a bushy plan. That's fine, but less common than a
left deep plan.

I think the problem is down to some incorrect code in
get_memoize_path() where we pass the wrong value of "calls" to
create_memoize_path(). I think instead of outer_path->parent->rows it
instead should be outer_path->rows.

If you look closely at the plan, you'll see that the outer side of the
inner-most Nested Loop is parameterized by some higher-level nested
loop.

->  Nested Loop  (cost=1.14..79.20 rows=91 width=8) (actual
time=0.024..0.024 rows=1 loops=66)
                     ->  Index Only Scan using
uq_isi_itemid_itemimageid on item_share_image itemsharei2__1
(cost=0.57..3.85 rows=91 width=16) (actual time=0.010..0.010 rows=1
loops=66)
                           Index Cond: (item_id = itembo0_.id)
                           Heap Fetches: 21
                     ->  Memoize  (cost=0.57..2.07 rows=1 width=8)
(actual time=0.013..0.013 rows=1 loops=66)

so instead of passing 91 to create_memoize_path() as I thought. Since
I can't see any WHERE clause items filtering rows from the
itemsharei2__1 relation, then the outer_path->parent->rows is should
be whatever pg_class.reltuples says.

Are you able to send the results of:

explain select item_id from item_share_image group by item_id; -- I'm
interested in the estimated number of groups in the plan's top node.

select reltuples from pg_class where oid = 'item_share_image'::regclass;

I'm expecting the estimated number of rows in the top node of the
group by plan to be about 4369066.

David

[1] https://explain.depesz.com/s/2rBw#source

On Fri, 6 May 2022 at 21:27, David Rowley <dgrowleyml@gmail.com> wrote:
> I've attached a patch to fix.  I'll look at it in more detail after the weekend.

I've now pushed this fix to master and backpatched to 14.

David