Re: what's the slowest part in the SQL

Hi Claudio,

here comes the dog version:

dev=# explain analyze
dev-# SELECT COALESCE(w.displayname, o.name) FROM order o INNER JOIN data w
dev-# ON w.name = o.name WHERE (w.name LIKE '%dog%' OR w.displayname LIKE '%dog%') AND (NOT w.categories && ARRAY[1, 6,
10,1337])
 
dev-# ORDER BY o.cnt DESC LIMIT 100;
                                                                              QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1761.35..1761.60 rows=100 width=50) (actual time=3622.605..3622.647 rows=100 loops=1)
   ->  Sort  (cost=1761.35..1761.69 rows=138 width=50) (actual time=3622.603..3622.621 rows=100 loops=1)
         Sort Key: o.cnt
         Sort Method: quicksort  Memory: 32kB
         ->  Nested Loop  (cost=53.66..1756.44 rows=138 width=50) (actual time=215.934..3622.397 rows=101 loops=1)
               ->  Bitmap Heap Scan on data w  (cost=53.11..571.37 rows=138 width=40) (actual time=146.340..562.583
rows=526loops=1)
 
                     Recheck Cond: (((name)::text ~~ '%dog%'::text) OR ((displayname)::text ~~ '%dog%'::text))
                     Rows Removed by Index Recheck: 7
                     Filter: (NOT (categories && '{1,6,10,1337}'::integer[]))
                     Rows Removed by Filter: 1249
                     ->  BitmapOr  (cost=53.11..53.11 rows=138 width=0) (actual time=145.906..145.906 rows=0 loops=1)
                           ->  Bitmap Index Scan on idx_data_3  (cost=0.00..32.98 rows=131 width=0) (actual
time=133.637..133.637rows=1782 loops=1)
 
                                 Index Cond: ((name)::text ~~ '%dog%'::text)
                           ->  Bitmap Index Scan on idx_data_4  (cost=0.00..20.05 rows=7 width=0) (actual
time=12.267..12.267rows=3 loops=1)
 
                                 Index Cond: ((displayname)::text ~~ '%dog%'::text)
               ->  Index Scan using idx_order_1_us on order o  (cost=0.56..8.58 rows=1 width=30) (actual
time=5.814..5.814rows=0 loops=526)
 
                     Index Cond: (name = (w.name)::text)
 Total runtime: 3622.756 ms
(18 rows)

Time: 3652.654 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 '%dog%' OR w.displayname LIKE '%dog%') AND (NOT w.categories && ARRAY[1, 6,
10,1337])
 
      ORDER BY o.cnt DESC LIMIT 100;
                                                                              QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1761.35..1761.60 rows=100 width=50) (actual time=21.938..21.980 rows=100 loops=1)
   ->  Sort  (cost=1761.35..1761.69 rows=138 width=50) (actual time=21.937..21.953 rows=100 loops=1)
         Sort Key: o.cnt
         Sort Method: quicksort  Memory: 32kB
         ->  Nested Loop  (cost=53.66..1756.44 rows=138 width=50) (actual time=3.791..21.818 rows=101 loops=1)
               ->  Bitmap Heap Scan on data w  (cost=53.11..571.37 rows=138 width=40) (actual time=3.467..7.802
rows=526loops=1)
 
                     Recheck Cond: (((name)::text ~~ '%dog%'::text) OR ((displayname)::text ~~ '%dog%'::text))
                     Rows Removed by Index Recheck: 7
                     Filter: (NOT (categories && '{1,6,10,1337}'::integer[]))
                     Rows Removed by Filter: 1249
                     ->  BitmapOr  (cost=53.11..53.11 rows=138 width=0) (actual time=3.241..3.241 rows=0 loops=1)
                           ->  Bitmap Index Scan on idx_data_3  (cost=0.00..32.98 rows=131 width=0) (actual
time=3.216..3.216rows=1782 loops=1)
 
                                 Index Cond: ((name)::text ~~ '%dog%'::text)
                           ->  Bitmap Index Scan on idx_data_4  (cost=0.00..20.05 rows=7 width=0) (actual
time=0.022..0.022rows=3 loops=1)
 
                                 Index Cond: ((displayname)::text ~~ '%dog%'::text)
               ->  Index Scan using idx_order_1_us on order o  (cost=0.56..8.58 rows=1 width=30) (actual
time=0.025..0.026rows=0 loops=526)
 
                     Index Cond: (name = (w.name)::text)
 Total runtime: 22.069 ms
(18 rows)


On 8/10/16, 10:28 AM, "Claudio Freire" <klaussfreire@gmail.com> wrote:

On Tue, Aug 9, 2016 at 9:12 PM, Suya Huang <shuang@connexity.com> wrote:
> Hi Claudio,
>
> The plan for dog is exactly the same as what’s for cat, thus I didn’t paste them here.

Are you sure?

The plan itself may be the same, but the numbers may be different, and
in fact be key to understanding the problem.

>
> Richard Albright just pointed that it’s because the result has been cached not the table, I think that makes sense.
Somy question changes to the efficiency of NESTED LOOP JOIN, 400 rows for 4 seconds, sounds slow to me. Is that
normal?

From the looks of those timing numbers, everything involving reads
from disk is slower on the first run. That clearly points to disk
cache effects. So this explain looks completely normal.

If the query for "dog" doesn't get a speedup on second runs, it could
just be that the data it visits doesn't fit in disk cache, so the
numbers are important, they can tell you that.