Thread: what's the slowest part in the SQL

what's the slowest part in the SQL

From
Suya Huang
Date:

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

Re: what's the slowest part in the SQL

From
Claudio Freire
Date:
On Tue, Aug 9, 2016 at 8:27 PM, Suya Huang <shuang@connexity.com> wrote:
> 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;

You're showing the explain for "cat", where the interesting one is
probably "dog".


Re: what's the slowest part in the SQL

From
Suya Huang
Date:
Hi Claudio,

The plan for dog is exactly the same as what’s for cat, thus I didn’t paste them here.

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

Thanks,
Suya

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

On Tue, Aug 9, 2016 at 8:27 PM, Suya Huang <shuang@connexity.com> wrote:
> 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;

You're showing the explain for "cat", where the interesting one is
probably "dog".



Re: what's the slowest part in the SQL

From
Claudio Freire
Date:
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.


Re: what's the slowest part in the SQL

From
Suya Huang
Date:
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.



Re: what's the slowest part in the SQL

From
Tom Lane
Date:
Suya Huang <shuang@connexity.com> writes:
>                ->  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) 

4 or so ms per row fetched is well within expectation for random access to
spinning-rust media.  For example, a 15K RPM drive spins at 4 ms per
revolution, so rotational delay alone would probably explain this number,
never mind needing to do any seeks.  So I see nothing even slightly
unexpected here, assuming that the "order" table is large enough that none
of what you need is in RAM already.  If you need more performance, look
into SSDs.

(If you have storage kit for which you'd expect better performance than
this, you should start by explaining what it is.)

            regards, tom lane


Re: what's the slowest part in the SQL

From
Claudio Freire
Date:
On Tue, Aug 9, 2016 at 9:34 PM, Suya Huang <shuang@connexity.com> wrote:
> 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)

Maybe I misunderstood your question, but dog here seems to behave just like cat.

Are you expecting that running first "cat" and then "dog" should make
"dog" go fast?

That's not how it works, the rows for cat and dog may not reside on
the same pages, so what's cached for "cat" doesn't work for "dog" and
viceversa. It could even be the other way around, if by chance they
resided on the same page, so... it still looks normal.

Clearly your bottleneck is the I/O subsystem.


Re: what's the slowest part in the SQL

From
Claudio Freire
Date:
On Tue, Aug 9, 2016 at 9:46 PM, Claudio Freire <klaussfreire@gmail.com> wrote:
> On Tue, Aug 9, 2016 at 9:34 PM, Suya Huang <shuang@connexity.com> wrote:
>> 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)
>
> Maybe I misunderstood your question, but dog here seems to behave just like cat.
>
> Are you expecting that running first "cat" and then "dog" should make
> "dog" go fast?
>
> That's not how it works, the rows for cat and dog may not reside on
> the same pages, so what's cached for "cat" doesn't work for "dog" and
> viceversa. It could even be the other way around, if by chance they
> resided on the same page, so... it still looks normal.
>
> Clearly your bottleneck is the I/O subsystem.

Btw, what kind of index are idx_data_3 and idx_data_4?


Re: what's the slowest part in the SQL

From
Suya Huang
Date:
Thank you Tom very much, that’s the piece of information I miss. 

So, should I expect that the nested loop join would be much faster if I cache both tables (use pg_prewarm) into memory
asit waives the disk read?
 

Thanks,
Suya

On 8/10/16, 10:45 AM, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:

Suya Huang <shuang@connexity.com> writes:
>                ->  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)
 

4 or so ms per row fetched is well within expectation for random access to
spinning-rust media.  For example, a 15K RPM drive spins at 4 ms per
revolution, so rotational delay alone would probably explain this number,
never mind needing to do any seeks.  So I see nothing even slightly
unexpected here, assuming that the "order" table is large enough that none
of what you need is in RAM already.  If you need more performance, look
into SSDs.

(If you have storage kit for which you'd expect better performance than
this, you should start by explaining what it is.)

            regards, tom lane



Re: what's the slowest part in the SQL

From
Suya Huang
Date:
Hi Claudio,

Here is the index definition
    "idx_data_3" gin (name gin_trgm_ops), tablespace "tbs_data"
    "idx_data_4" gin (displayname gin_trgm_ops), tablespace "tbs_data"

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

On Tue, Aug 9, 2016 at 9:46 PM, Claudio Freire <klaussfreire@gmail.com> wrote:
> On Tue, Aug 9, 2016 at 9:34 PM, Suya Huang <shuang@connexity.com> wrote:
>> 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)
>
> Maybe I misunderstood your question, but dog here seems to behave just like cat.
>
> Are you expecting that running first "cat" and then "dog" should make
> "dog" go fast?
>
> That's not how it works, the rows for cat and dog may not reside on
> the same pages, so what's cached for "cat" doesn't work for "dog" and
> viceversa. It could even be the other way around, if by chance they
> resided on the same page, so... it still looks normal.
>
> Clearly your bottleneck is the I/O subsystem.

Btw, what kind of index are idx_data_3 and idx_data_4?



Re: what's the slowest part in the SQL

From
Tom Lane
Date:
Suya Huang <shuang@connexity.com> writes:
> Thank you Tom very much, that’s the piece of information I miss.
> So, should I expect that the nested loop join would be much faster if I cache both tables (use pg_prewarm) into
memoryas it waives the disk read? 

pg_prewarm is not going to magically fix things if your table is bigger
than RAM, which it apparently is.

            regards, tom lane


Re: what's the slowest part in the SQL

From
Suya Huang
Date:
Not really, the server has 2 GB memory (PROD is a lot more than this dev box), so the table should be able to fit in
memoryif we preload them.
 

MemTotal:        2049572 kB

dev=# select pg_size_pretty(pg_relation_size('data'));
 pg_size_pretty
----------------
 141 MB
(1 row)

Time: 2.640 ms

dev=# select pg_size_pretty(pg_relation_size('order'));
 pg_size_pretty
----------------
 516 MB
(1 row)

Thanks,
Suya
On 8/10/16, 11:57 AM, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:

Suya Huang <shuang@connexity.com> writes:
> Thank you Tom very much, that’s the piece of information I miss. 
> So, should I expect that the nested loop join would be much faster if I cache both tables (use pg_prewarm) into
memoryas it waives the disk read?
 

pg_prewarm is not going to magically fix things if your table is bigger
than RAM, which it apparently is.

            regards, tom lane



Re: what's the slowest part in the SQL

From
Claudio Freire
Date:
On Tue, Aug 9, 2016 at 10:46 PM, Suya Huang <shuang@connexity.com> wrote:
> Hi Claudio,
>
> Here is the index definition
>     "idx_data_3" gin (name gin_trgm_ops), tablespace "tbs_data"
>     "idx_data_4" gin (displayname gin_trgm_ops), tablespace "tbs_data"


GIN indexes are quite big, they can be bigger than the data. Check
their size, it's possible that you can't fit data + indexes on those
2GB.

But if prod is going to be bigger, prehaps it's a non-issue for you?


Re: what's the slowest part in the SQL

From
Merlin Moncure
Date:
On Tue, Aug 9, 2016 at 6:27 PM, Suya Huang <shuang@connexity.com> wrote:
> 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.

LIMIT clause operations combined with random access are particularly
sensitive to caching on slow media.  The exact pages you want are
scattered around the dist but repeated scans of the same values will
pull up exactly the ones you want.  You can warm the table assuming
your memory is sufficient enough to cache all the data you need.
Another (I think better-) plan is to buy media with faster random
access.

Are you using pg_trgm to index the 'name' field?  gist/gin indexes are
*very* dependent on caching/fast drives as the indexes tend to be fat.

merlin