pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedwhat's the slowest part in the SQL
14+ messages / 4 participants
[nested] [flat]
* what's the slowest part in the SQL
@ 2016-08-09 23:27 Suya Huang <shuang@connexity.com>
0 siblings, 2 replies; 14+ messages in thread
From: Suya Huang @ 2016-08-09 23:27 UTC (permalink / raw)
To: 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
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-09 23:52 Claudio Freire <klaussfreire@gmail.com>
parent: Suya Huang <shuang@connexity.com>
1 sibling, 1 reply; 14+ messages in thread
From: Claudio Freire @ 2016-08-09 23:52 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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".
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:12 Suya Huang <shuang@connexity.com>
parent: Claudio Freire <klaussfreire@gmail.com>
0 siblings, 1 reply; 14+ messages in thread
From: Suya Huang @ 2016-08-10 00:12 UTC (permalink / raw)
To: Claudio Freire <klaussfreire@gmail.com>; +Cc: pgsql-performance
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 my question 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".
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:28 Claudio Freire <klaussfreire@gmail.com>
parent: Suya Huang <shuang@connexity.com>
0 siblings, 1 reply; 14+ messages in thread
From: Claudio Freire @ 2016-08-10 00:28 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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. So my 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.
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:34 Suya Huang <shuang@connexity.com>
parent: Claudio Freire <klaussfreire@gmail.com>
0 siblings, 2 replies; 14+ messages in thread
From: Suya Huang @ 2016-08-10 00:34 UTC (permalink / raw)
To: Claudio Freire <klaussfreire@gmail.com>; +Cc: pgsql-performance
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=526 loops=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.637 rows=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.267 rows=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.814 rows=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=526 loops=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.216 rows=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.022 rows=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.026 rows=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. So my 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.
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:45 Tom Lane <tgl@sss.pgh.pa.us>
parent: Suya Huang <shuang@connexity.com>
1 sibling, 1 reply; 14+ messages in thread
From: Tom Lane @ 2016-08-10 00:45 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: Claudio Freire <klaussfreire@gmail.com>; pgsql-performance
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.814 rows=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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:46 Claudio Freire <klaussfreire@gmail.com>
parent: Suya Huang <shuang@connexity.com>
1 sibling, 1 reply; 14+ messages in thread
From: Claudio Freire @ 2016-08-10 00:46 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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=526 loops=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.216 rows=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.022 rows=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.026 rows=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.
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 00:49 Claudio Freire <klaussfreire@gmail.com>
parent: Claudio Freire <klaussfreire@gmail.com>
0 siblings, 1 reply; 14+ messages in thread
From: Claudio Freire @ 2016-08-10 00:49 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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=526 loops=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.216 rows=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.022 rows=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.026 rows=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?
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 01:43 Suya Huang <shuang@connexity.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 14+ messages in thread
From: Suya Huang @ 2016-08-10 01:43 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Claudio Freire <klaussfreire@gmail.com>; pgsql-performance
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 as it 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.814 rows=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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 01:46 Suya Huang <shuang@connexity.com>
parent: Claudio Freire <klaussfreire@gmail.com>
0 siblings, 1 reply; 14+ messages in thread
From: Suya Huang @ 2016-08-10 01:46 UTC (permalink / raw)
To: Claudio Freire <klaussfreire@gmail.com>; +Cc: pgsql-performance
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=526 loops=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.216 rows=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.022 rows=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.026 rows=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?
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 01:57 Tom Lane <tgl@sss.pgh.pa.us>
parent: Suya Huang <shuang@connexity.com>
0 siblings, 1 reply; 14+ messages in thread
From: Tom Lane @ 2016-08-10 01:57 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: Claudio Freire <klaussfreire@gmail.com>; pgsql-performance
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 memory as 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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 02:02 Suya Huang <shuang@connexity.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 14+ messages in thread
From: Suya Huang @ 2016-08-10 02:02 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Claudio Freire <klaussfreire@gmail.com>; pgsql-performance
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 memory if 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 memory as 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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-10 18:10 Claudio Freire <klaussfreire@gmail.com>
parent: Suya Huang <shuang@connexity.com>
0 siblings, 0 replies; 14+ messages in thread
From: Claudio Freire @ 2016-08-10 18:10 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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?
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: what's the slowest part in the SQL
@ 2016-08-16 13:56 Merlin Moncure <mmoncure@gmail.com>
parent: Suya Huang <shuang@connexity.com>
1 sibling, 0 replies; 14+ messages in thread
From: Merlin Moncure @ 2016-08-16 13:56 UTC (permalink / raw)
To: Suya Huang <shuang@connexity.com>; +Cc: pgsql-performance
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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
^ permalink raw reply [nested|flat] 14+ messages in thread
end of thread, other threads:[~2016-08-16 13:56 UTC | newest]
Thread overview: 14+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2016-08-09 23:27 what's the slowest part in the SQL Suya Huang <shuang@connexity.com>
2016-08-09 23:52 ` Claudio Freire <klaussfreire@gmail.com>
2016-08-10 00:12 ` Suya Huang <shuang@connexity.com>
2016-08-10 00:28 ` Claudio Freire <klaussfreire@gmail.com>
2016-08-10 00:34 ` Suya Huang <shuang@connexity.com>
2016-08-10 00:45 ` Tom Lane <tgl@sss.pgh.pa.us>
2016-08-10 01:43 ` Suya Huang <shuang@connexity.com>
2016-08-10 01:57 ` Tom Lane <tgl@sss.pgh.pa.us>
2016-08-10 02:02 ` Suya Huang <shuang@connexity.com>
2016-08-10 00:46 ` Claudio Freire <klaussfreire@gmail.com>
2016-08-10 00:49 ` Claudio Freire <klaussfreire@gmail.com>
2016-08-10 01:46 ` Suya Huang <shuang@connexity.com>
2016-08-10 18:10 ` Claudio Freire <klaussfreire@gmail.com>
2016-08-16 13:56 ` Merlin Moncure <mmoncure@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox