From: | Suya Huang <shuang(at)connexity(dot)com> |
---|---|
To: | "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org> |
Subject: | what's the slowest part in the SQL |
Date: | 2016-08-09 23:27:54 |
Message-ID: | 1D0FF65A-EAB9-453C-9B95-684E05B494B7@connexity.com |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-performance |
Hi,
I’ve got a SQL runs for about 4 seconds first time it’s been executed,but very fast (20ms) for the consequent runs. I thought it’s because that the first time table being loaded into memory. However, if you change the where clause value from “cat” to “dog”, it runs about 4 seconds as it’s never been executed before. Therefore, it doesn’t sound like the reason of table not being cached.
Can someone explain why it behaves like this? It PG 9.3, I can try pg_prewarm to cache both tables by creating the extension (probably need to find a 9.4 box and copy those files) if the reason is table not being cached.
From execution plan below, it shows Nested Loop is the slowest part - actual time=349.257..4265.928 rows=457 , it’s really slow, for just 457 rows and takes 4 seconds!!! But very fast for repetitive runs.
dev=# explain analyze
SELECT COALESCE(w.displayname, o.name) FROM order o INNER JOIN data w
ON w.name = o.name WHERE (w.name LIKE '%cat%' OR w.displayname LIKE '%cat%') AND (NOT w.categories && ARRAY[1, 6, 10, 1337])
ORDER BY o.cnt DESC LIMIT 100;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=1723.11..1723.36 rows=100 width=50) (actual time=4267.352..4267.407 rows=100 loops=1)
-> Sort (cost=1723.11..1723.44 rows=131 width=50) (actual time=4267.351..4267.381 rows=100 loops=1)
Sort Key: o.cnt
Sort Method: top-N heapsort Memory: 32kB
-> Nested Loop (cost=97.61..1718.50 rows=131 width=50) (actual time=349.257..4265.928 rows=457 loops=1)
-> Bitmap Heap Scan on data w (cost=97.05..593.54 rows=131 width=40) (actual time=239.135..387.077 rows=892 loops=1)
Recheck Cond: (((name)::text ~~ '%cat%'::text) OR ((displayname)::text ~~ '%cat%'::text))
Rows Removed by Index Recheck: 3
Filter: (NOT (categories && '{1,6,10,1337}'::integer[]))
Rows Removed by Filter: 1646
-> BitmapOr (cost=97.05..97.05 rows=132 width=0) (actual time=238.931..238.931 rows=0 loops=1)
-> Bitmap Index Scan on idx_data_3 (cost=0.00..60.98 rows=131 width=0) (actual time=195.392..195.392 rows=2539 loops=1)
Index Cond: ((name)::text ~~ '%cat%'::text)
-> Bitmap Index Scan on idx_data_4 (cost=0.00..36.00 rows=1 width=0) (actual time=43.537..43.537 rows=14 loops=1)
Index Cond: ((displayname)::text ~~ '%cat%'::text)
-> Index Scan using idx_order_1_us on order o (cost=0.56..8.58 rows=1 width=30) (actual time=4.334..4.345 rows=1 loops=892)
Index Cond: (name = (w.name)::text)
Total runtime: 4267.560 ms
(18 rows)
Time: 4269.990 ms
dev=# explain analyze
SELECT COALESCE(w.displayname, o.name) FROM order o INNER JOIN data w
ON w.name = o.name WHERE (w.name LIKE '%cat%' OR w.displayname LIKE '%cat%') AND (NOT w.categories && ARRAY[1, 6, 10, 1337])
ORDER BY o.cnt DESC LIMIT 100;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=1723.11..1723.36 rows=100 width=50) (actual time=37.843..37.885 rows=100 loops=1)
-> Sort (cost=1723.11..1723.44 rows=131 width=50) (actual time=37.842..37.861 rows=100 loops=1)
Sort Key: o.cnt
Sort Method: top-N heapsort Memory: 32kB
-> Nested Loop (cost=97.61..1718.50 rows=131 width=50) (actual time=5.528..37.373 rows=457 loops=1)
-> Bitmap Heap Scan on data w (cost=97.05..593.54 rows=131 width=40) (actual time=3.741..11.799 rows=892 loops=1)
Recheck Cond: (((name)::text ~~ '%cat%'::text) OR ((displayname)::text ~~ '%cat%'::text))
Rows Removed by Index Recheck: 3
Filter: (NOT (categories && '{1,6,10,1337}'::integer[]))
Rows Removed by Filter: 1646
-> BitmapOr (cost=97.05..97.05 rows=132 width=0) (actual time=3.547..3.547 rows=0 loops=1)
-> Bitmap Index Scan on idx_data_3 (cost=0.00..60.98 rows=131 width=0) (actual time=3.480..3.480 rows=2539 loops=1)
Index Cond: ((name)::text ~~ '%cat%'::text)
-> Bitmap Index Scan on idx_data_4 (cost=0.00..36.00 rows=1 width=0) (actual time=0.067..0.067 rows=14 loops=1)
Index Cond: ((displayname)::text ~~ '%cat%'::text)
-> Index Scan using idx_order_1_us on order o (cost=0.56..8.58 rows=1 width=30) (actual time=0.027..0.027 rows=1 loops=892)
Index Cond: (name = (w.name)::text)
Total runtime: 37.974 ms
(18 rows)
Time: 40.158 ms
From | Date | Subject | |
---|---|---|---|
Next Message | Claudio Freire | 2016-08-09 23:52:48 | Re: what's the slowest part in the SQL |
Previous Message | Gerardo Herzig | 2016-08-08 11:21:00 | Re: [PERFORM] Create language plperlu Error |