Re: unexpected result for wastedbytes query after vacuum full
Le mar. 10 déc. 2019 à 20:48, Jeff Janes a écrit : > On Tue, Dec 10, 2019 at 11:43 AM Guillaume Lelarge > wrote: > > This query uses the column statistics to estimate bloat. AFAIK, json >> columns don't have statistics, so the estimation can't be relied on (for >> this specific table at least). >> > > This was true prior to 9.5 (for xml at least, I don't know about json), > but should not be true from that release onward. But still the difference > between 74440704 and 74506240, this does seem to me to be straining at a > gnat to swallow a camel. > > I just checked, and you're right. There are less statistics with json, but the important ones (null_frac and avg_width) are available for json and jsonb datatypes. So the query should work even for tables using these datatypes. Thanks for the information, that's very interesting. And I apologize for the noise. -- Guillaume.
Re: Specific query taking time to process
This seems beyond me at this point, but I am curious if you also vacuumed alf_node_properties and alf_node tables and checked when they last got (auto)vacuumed/analyzed. With default configs for autovacuum parameters and tables with that many rows, they don't qualify for autovacuum very often. I don't have much experience with tables in excess of 50 million rows because of manual sharding clients data. You mention work_mem is set differently. Did you try setting work_mem back to 4MB in session on instance 1 just to test the query? I don't know if work_mem is included in planning stage, but I would think it may be considered. It would be odd for more available memory to end up with a slower plan, but I like to eliminate variables whenever possible. It might be worthwhile to see about increasing default_statistics_target to get more specific stats, but that can result in a dramatic increase in planning time for even simple queries. Hopefully one of the real experts chimes in.
Re: Specific query taking time to process
On Tue, Dec 10, 2019 at 3:40 AM Fahiz Mohamed wrote: > Thank you very much for your prompt responses. > > I have analysed more regarding this and found the long running query. > > I ran "explain analyse" on this query and I got following result. (We have > 2 identical DB instances and they consist of same data. Instane 1 took 20+ > second to process and instance 2 took less than a second) > They do not consist of the same data. One returns 17 rows, the other 22. One finds 5635 rows (scattered over 40765 blocks!) where qname_id = 251, the other find 85 rows for the same condition. It seems the first one is not very well vacuumed. I don't know if these differences are enough to be driving the different plans (the estimation differences appear smaller than the actual differences), but clearly the data is not the same. Your first query is using the index idx_alf_node_mdq in a way which seems to be counter-productive. Perhaps you could inhibit it to see what plan it chooses then. For example, specify in your query "type_qname_id+0 = 240" to prevent the use of that index. Or you could drop the index, if it is not vital. But if the data has not be ANALYZEd recently, you should do that before anything else. Might as well make it a VACUUM ANALYZE. Cheers, Jeff >
Re: Specific query taking time to process
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. Following are the number of rows in each table in both instances Instance 1 alf_node : 96493129 rows alf_node_properties : 455599288 rows alf_node_aspects : 150153006 rowsInstance 2 alf_node : 90831396 rows alf_node_properties : 440792247 rows alf_node_aspects : 146648241 rows I hope the above data difference can make a drastic difference. Please correct me if I am wrong. I checked "pg_stat_user_tables" and autovacuum never run against those tables. 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. INFO: analyzing "public.alf_node_aspects" INFO: "alf_node_aspects": scanned 3 of 812242 pages, containing 555 live rows and 0 dead rows; 3 rows in sample, 150264770 estimated total rows" Did the vacuum worked fine? I did "explain( analyze, buffers )" below are the results: Instance 1: Nested Loop Semi Join (cost=441133.07..1352496.76 rows=1 width=8) (actual time=9054.324..10029.748 rows=22 loops=1) Buffers: shared hit=1617812 -> Merge Semi Join (cost=441132.50..1352359.19 rows=41 width=16) (actual time=9054.296..10029.547 rows=22 loops=1) Merge Cond: (node.id = prop.node_id) Buffers: shared hit=1617701 -> Index Only Scan using idx_alf_node_tqn on alf_node node (cost=441041.93..1340831.48 rows=4593371 width=8) (actual t ime=4.418..7594.637 rows=40998148 loops=1) Index Cond: ((type_qname_id = 240) AND (store_id = 6)) Filter: (NOT (hashed SubPlan 1)) Rows Removed by Filter: 130 Heap Fetches: 0 Buffers: shared hit=1617681 SubPlan 1 -> Bitmap Heap Scan on alf_node_aspects aspect_1 (cost=3418.63..440585.22 rows=182459 width=8) (actual time=0. 583..2.992 rows=4697 loops=1) Recheck Cond: (qname_id = 251) Heap Blocks: exact=1774 Buffers: shared hit=1791 -> Bitmap Index Scan on fk_alf_nasp_qn (cost=0.00..3373.01 rows=182459 width=0) (actual time=0.384..0.38 4 rows=4697 loops=1) Index Cond: (qname_id = 251) Buffers: shared hit=17 -> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop (cost=0.70..41.74 rows=852 width=8) (actual time= 0.022..0.037 rows=23 loops=1) Index Cond: ((qname_id = '242'::bigint) AND (string_value = 'E292432'::text)) Heap Fetches: 0 Buffers: shared hit=20 -> Index Only Scan using alf_node_aspects_pkey on alf_node_aspects aspect (cost=0.57..38.80 rows=14 width=8) (actual time=0. 007..0.007 rows=1 loops=22) Index Cond: ((node_id = node.id) AND (qname_id = 245)) Heap Fetches: 22 Buffers: shared hit=111 Planning time: 0.621 ms Execution time: 10029.799 ms (29 rows) Instance 2: Nested Loop Semi Join (cost=6471.94..173560891.23 rows=2 width=8) (actual time=0.162..0.470 rows=17 loops=1) Buffers: shared hit=257 -> Nested Loop (cost=6471.37..173560734.51 rows=45 width=16) (actual time=0.154..0.392 rows=17 loops=1) Buffers: shared hit=172 -> HashAggregate (cost=3508.15..3516.80 rows=865 width=8) (actual time=0.039..0.043 rows=18 loops=1) Group Key: prop.node_id Buffers: shared hit=23 -> Index Only Scan using idx_alf_nprop_s on alf_node_properties prop (cost=0.70..3505.99 rows=866 width=8) (actual time=0.019..0.033 rows=18 loops=1) Index Cond: ((qname_id = '242'::bigint) AND (string_value = 'E292432'::text)) Heap Fetches: 18 Buffers: shared hit=23 -> Index Scan using alf_node_pkey on alf_node node (cost=2963.22..200644.17 rows=1 width=8) (actual time=0.019.. 0.019 rows=1 loops=18) Index Cond: (id = prop.node_id) Filter: ((type_qname_id <> 145) AND (store_id = 6) AND (type_qname_id = 240) AND (NOT (SubPlan 1))) Rows Removed by Filter: 0 Buffers: shared hit=149 SubPlan 1 -> Materialize (cost=2962.65..397913.00 rows=158204 width=8) (actual time=0.002..0.009 rows=85 loops=17) Buffers: shared hit=59 -> Bitmap Heap Scan on alf_node_aspects aspect_1 (cost=2962.65..396503.98 rows=158204 width=8) (ac tual time=0.025..0.085 rows=85 loops=1) Recheck Cond: (qname_id = 251) Heap Blocks: exact=55 Buffers: shared hit=59 -> Bitmap Index Scan on fk_alf_nasp_qn (cost=0.00..2923.10 rows=158204 width=0) (actual time =0.019..0.019 rows=87 loops=1) Index Cond: (qname_id = 251) Buffers: shared hit=4 -> Index Only Scan using alf_node_aspects_pkey on alf_node_aspects aspect (cost=0.57..34.32 rows=12 width=8) (actual t ime=0.004..0.004 rows=1 loops=17) Index Cond: ((node_id = node.id) AND (qname_id = 245)) Heap Fetches: 17 Buffers: shared hit=85 Planning time: 0.642 ms Execution time: 0.546 ms (32 rows) With the vacuum and reindex on those tables manage to reduce the time to 10s from 30s, but still I don't get the exact performance as Instance 2. work_mem was set to 4mb previously and in instance 1 its set to 160mb and instance 2 still using 4mb as work_mem. shared_buf
Re: Specific query taking time to process
On Wed, Dec 11, 2019 at 5:21 PM Fahiz Mohamed 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 50 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
