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