what's the slowest part in the SQL

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