Re: Specific query taking time to process

I have read through your comments so far – and they tally with the checks
we have been making to an extent – thanks for them.

We now only need 1 environment as we can replicate the performance problem
on a copy of live – snapshot/restore from AWS of live. We now have a vacuum
analyse running every night on the 3 tables in question on live – to
eliminate bloat and inaccurate stats as the root of the problem.

We can flip performance based on setting work_mem. For example, currently
work_mem up to an including 5069Kb the performance of the query is well
under 1 second – Upping work_mem just 1kb to 5097Kb then changes the query
plan and performance is a lot worse.

Fresh snapshot and restore.

5096kb – plan –

Nested Loop Semi Join (cost=3494.04..184505785.24 rows=1 width=8) (actual
time=6.404..130.145 rows=212 loops=1)

Buffers: shared hit=7369

-> Nested Loop (cost=3493.47..184505754.56 rows=36 width=16) (actual
time=6.394..129.351 rows=212 loops=1)

Buffers: shared hit=6318

-> HashAggregate (cost=72.32..81.03 rows=871 width=8) (actual
time=0.123..0.186 rows=228 loops=1)

Group Key: prop.node_id

Buffers: shared hit=99

-> Index Only Scan using idx_alf_nprop_s on
alf_node_properties prop (cost=0.70..70.14 rows=872 width=8) (actual
time=0.025..0.086 rows=228 loops=1)

Index Cond: ((qname_id = '242'::bigint) AND
(string_value = 'S434071'::text))

Heap Fetches: 2

Buffers: shared hit=99

-> Index Only Scan using idx_alf_node_tqn on alf_node node
(cost=3421.15..211831.99 rows=1 width=8) (actual time=0.566..0.566 rows=1
loops=228)

Index Cond: ((type_qname_id = 240) AND (store_id = 6) AND
(id = prop.node_id))

Filter: (NOT (SubPlan 1))

Heap Fetches: 13

Buffers: shared hit=6219

SubPlan 1

-> Materialize (cost=3420.59..419826.13 rows=163099
width=8) (actual time=0.007..0.246 rows=4909 loops=212)

Buffers: shared hit=5092

-> Bitmap Heap Scan on alf_node_aspects aspect_1
(cost=3420.59..418372.63 rows=163099 width=8) (actual time=1.402..5.243
rows=4909 loops=1)

Recheck Cond: (qname_id = 251)

Heap Blocks: exact=4801

Buffers: shared hit=5092

-> Bitmap Index Scan on fk_alf_nasp_qn
(cost=0.00..3379.81 rows=163099 width=0) (actual time=0.850..0.850
rows=7741 loops=1)

Index Cond: (qname_id = 251)

Buffers: shared hit=291

-> Index Only Scan using alf_node_aspects_pkey on alf_node_aspects
aspect (cost=0.57..4.70 rows=15 width=8) (actual time=0.003..0.003 rows=1
loops=212)

Index Cond: ((node_id = node.id) AND (qname_id = 245))

Heap Fetches: 15

Buffers: shared hit=1051

Planning time: 0.624 ms

Execution time: 130.222 ms

(32 rows)

5097Kb – plan –

Nested Loop Semi Join (cost=1019128.07..3400161.81 rows=1 width=8) (actual
time=4832.639..32783.503 rows=212 loops=1)

Buffers: shared hit=565 read=2191862

-> Hash Semi Join (cost=1019127.50..3400131.13 rows=36 width=16)
(actual time=4832.599..32779.613 rows=212 loops=1)

Hash Cond: (node.id = prop.node_id)

Buffers: shared hit=25 read=2191476

-> Bitmap Heap Scan on alf_node node
(cost=1019046.46..3388792.78 rows=4273414 width=8) (actual
time=4219.440..29678.682 rows=41976707 loops=1)

Recheck Cond: ((store_id = 6) AND (type_qname_id = 240))

Rows Removed by Index Recheck: 58872880

Filter: (NOT (hashed SubPlan 1))

Rows Removed by Filter: 2453

Heap Blocks: exact=32899 lossy=1939310

Buffers: shared read=2191402

-> Bitmap Index Scan on idx_alf_node_mdq
(cost=0.00..599197.73 rows=19566916 width=0) (actual
time=4186.449..4186.449 rows=41990879 loops=1)

Index Cond: ((store_id = 6) AND (type_qname_id = 240))

Buffers: shared read=214101

SubPlan 1

-> Bitmap Heap Scan on alf_node_aspects aspect_1
(cost=3420.59..418372.63 rows=163099 width=8) (actual time=2.635..21.981
rows=4909 loops=1)

Recheck Cond: (qname_id = 251)

Heap Blocks: exact=4801

Buffers: shared read=5092

-> Bitmap Index Scan on fk_alf_nasp_qn
(cost=0.00..3379.81 rows=163099 width=0) (actual time=2.016..2.016
rows=7741 loops=1)

Index Cond: (qname_id = 251)

Buffers: shared read=291

-> Hash (cost=70.14..70.14 rows=872 width=8) (actual
time=0.357..0.357 rows=228 loops=1)

Buckets: 1024 Batches: 1 Memory Usage: 17kB

Buffers: shared hit=25 read=74

-> Index Only Scan using idx_alf_nprop_s on
alf_node_properties prop (cost=0.70..70.14 rows=872 width=8) (actual
time=0.047..0.325 rows=228 loops=1)

Index Cond: ((qname_id = '242'::bigint) AND
(string_value = 'S434071'::text))

Heap Fetches: 2

Buffers: shared hit=25 read=74

-> Index Only Scan using alf_node_aspects_pkey on alf_node_aspects
aspect (cost=0.57..4.70 rows=15 width=8) (actual time=0.016..0.016 rows=1
loops=212)

Index Cond: ((node_id = node.id) AND (qname_id = 245))

Heap Fetches: 15

Buffers: shared hit=540 read=386

Planning time: 0.821 ms

Execution time: 32783.609 ms

(36 rows)

Note the second plan is not even using any index on alf_node initially.

On Thu, Jan 30, 2020 at 9:44 AM Fahiz Mohamed <fahiz(at)netwidz(dot)com> wrote:

> Hi Jeff,
>
> Thank you for your email, Sorry I couldn’t respond back to you. I am not
> working on this project at the moment. I have copied one of my colleague
> who working on this. He has some progress on this, he will update the email
> thread with those findings
>
> Appreciate your support.
>
> Thank you,
> Fahiz
> On 12 Dec 2019, 02:25 +0000, Jeff Janes <jeff(dot)janes(at)gmail(dot)com>, wrote:
>
> On Wed, Dec 11, 2019 at 5:21 PM Fahiz Mohamed <fahiz(at)netwidz(dot)com> wrote:
>
>> There is a slight different in both instance’s data. Inastanbce 1
>> contains latest data and instance 2 consists of data which is 3 weeks older
>> than instance 1.
>>
>
> In knowing where to look for differences in performance, there is a big
> difference between them being identical, and being generally similar, but
> not identical.
>
>
>> I hope the above data difference can make a drastic difference. Please
>> correct me if I am wrong.
>>
>
> They are similar in scale, but we know there is a big difference in
> distribution of some values. For example, we still know the slow plan has
> 4697 rows in aspect_1 where qname_id = 251, while the other plan has 85
> rows in aspect_1 meeting that same criterion. That is a big difference, and
> it is real difference in the data, not just a difference in planning or
> estimation. Is this difference driving the difference in plan choice?
> Probably not (plan choice is driven by estimated rows, not actual, and
> estimates are quite similar), but it does demonstrate the data is quite
> different between the two systems when you look under the hood. It is
> likely that there are other, similar differences in the distribution of
> particular values which is driving the difference in plans. It is just
> that we can't see those differences, because the EXPLAIN ANALYZE only
> reports on the plan it ran, not other plans it could have ran but didn't.
>
> Your query is now using the index named idx_alf_node_tqn in a way which
> is equally unproductive as the previous use of idx_alf_node_mdq was. It
> looks like they have the same columns, just in a different order. My
> previous advice to try "type_qname_id+0 = 240" should still apply.
>
> If you can't get that to work, then another avenue is to run "explain
> (analyze, buffers) select count(*) from alf_node where (type_qname_id =
> 240) AND (store_id = 6)" on both instances.
>
>
>
>
>> I did execute vacuum manually and I noticed the below in the output
>>
>> "INFO: vacuuming "public.alf_node_aspects"
>> INFO: "alf_node_aspects": found 0 removable, 150264654 nonremovable row
>> versions in 812242 pages
>> DETAIL: 0 dead row versions cannot be removed yet.
>> CPU 13.53s/33.35u sec elapsed 77.88 sec.
>>
>
> I'm not really sure what that means. I certainly would not have expected
> 0 removable. There should have been some prior output, something like:
>
> INFO: scanned index "fk_alf_nasp_qn" to remove 500000 row versions
>
> It could be that autovacuum had already gotten around to vacuuming after
> your initial email but before you did the above, meaning there was not much
> for your manual to do.
>
> But you can see that the vacuum did have an effect, by comparing these
> lines (despite them finding about same number of rows)
>
> Heap Blocks: exact=40765
>
> Heap Blocks: exact=1774
>
> It wasn't all that large of an effect in this case, but it is still
> something worth fixing.
>
> Cheers,
>
> Jeff
>
>

--
[image: logo] <http://www.zaizi.com/> *Duncan Whitham* Developer*, *
*Zaizi*
*|* *m:* (+44)751 502 7049 *|* *t:* (+44)20 3582 8330

*|* *e:* dwhitham(at)zaizi(dot)com *|* *w:* http://www.zaizi.com/

<https://www.facebook.com/ZaiziLtd/> <https://twitter.com/zaizi>
<https://www.linkedin.com/company/zaizi> <https://plus.google.com/+Zaizi>
<https://vimeo.com/zaizi> <https://www.youtube.com/user/zaizivids>

--

This message should be regarded as confidential. If you have received this
email in error please notify the sender and destroy it immediately.
Statements of intent shall only become binding when confirmed in hard copy
by an authorised signatory. 

Zaizi Ltd is registered in England and Wales
with the registration number 6440931. The Registered Office is Kings House,
174 Hammersmith Road, London W6 7JP.