Thread: Expected performance of querying 5k records from 4 million records?

Anish,

> I've been struggling with this issue for the last several days, and I feel
> like I'm running into a few different issues that I don't understand.  I'm
> using postgres 9.0.8, and here's the OS I'm running this on:
> inux  2.6.18-308.4.1.el5xen #1 SMP Tue Apr 17 17:49:15 EDT 2012 x86_64
> x86_64 x86_64 GNU/Linux

RAM?  What does your disk support look like? (disks especially are
relevant, see below).

> explain analyze select data_id, dataset_id, stat from data_part_201 where
> dataset_id = 201
> and stat_id = 6 and data_id>=50544630 and data_id<=50549979;
>
>  Bitmap Heap Scan on data_part_201  (cost=115.79..14230.69 rows=4383
> width=16) (actual time=36.103..1718.141 rows=5350 loops=1)
>    Recheck Cond: ((data_id >= 50544630) AND (data_id <= 50549979))
>    Filter: ((dataset_id = 201) AND (stat_id = 6))
>    ->  Bitmap Index Scan on data_unq_201  (cost=0.00..114.70 rows=5403
> width=0) (actual time=26.756..26.756 rows=5350 loops=1)
>          Index Cond: ((data_id >= 50544630) AND (data_id <= 50549979))
>  Total runtime: 1728.447 ms
> (6 rows)

I've seen extremely slow Bitmap Heap Scans like this before.  There's a
few things which can cause them in my experience:

1) Table is on disk, and random access to disk is very slow for some reason.

2) Recheck condition is computationally expensive (unlikely here)

3) Index is very bloated and needs reindexing (again, unlikely because
the initial Bitmap Index Scan is quite fast).

To test the above: run the exact same query several times in a row.
Does it get dramatically faster on the 2nd and successive runs?

>  Index Scan using data_part_202_dataset_regionset_data_idx on data_part_202
>  (cost=0.00..7987.83 rows=4750 width=16) (actual time=39.152..27339.401
> rows=5350 loops=1)
>    Index Cond: ((dataset_id = 202) AND (data_id >= 50544630) AND (data_id
> <= 50549979) AND (stat_id = 6))
>  Total runtime: 27349.091 ms
> (3 rows)

I'll point out that you're now querying a different partition than you
did above.

Again, this would point to random access to the underlying partition
being very slow.

> QUESTION 3:
> If I do the following:  reindex table data_part_204 the query now takes
> 50-70 milliseconds.  Is this because the table is getting cached?  How do I
> know if a particular query is coming from the cache? The reason why I think
> "reindex table" is caching the results, is that select count(*) from the
> partition also causes the query to be fast.

Yes, it's most likely because the table is being cached.  To test this,
run one of the slow query versions above repeatedly.

Things to investigate:

1) Is there some reason why random access on your disks would be
unusually slow?  iSCSI, cheap NAS/SAN, RAID 5+0, running on OSX or
Windows, etc.?

2) Is there a possibility that the partitions or indexes involved might
be unusually bloated, such as a large number of historical updates to
indexed columns?  If so, does a CLUSTER on one partition make the issue
go away?

3) Test your database using PostgreSQL 9.2 Beta2.  Do the new index-only
scans solve this issue?

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

On Fri, Jun 15, 2012 at 9:17 AM, Anish Kejariwal <anishkej@gmail.com> wrote:
>
> Below are the tables, queries, and execution plans with my questions with
> more detail.  (Since I have 250 partitions, I can query one partition after
> the other to ensure that I'm not pulling results form the cache)

Doesn't that explain why it is slow?  If you have 15000 rpm drives and
each row is in a different block and uncached, it would take 20
seconds to read them all in.  You are getting 10 times better than
that, either due to caching or because your rows are clustered, or
because effective_io_concurrency is doing its thing.

>
> explain analyze select data_id, dataset_id, stat from data_part_201 where
> dataset_id = 201
> and stat_id = 6 and data_id>=50544630 and data_id<=50549979;

What does "explain (analyze, buffers)" show?


> QUESTION 1: you can see that the query is very simple.  is this the optimal
> execution plan? any tips on what to look into to increase performance?
>
> I then tried adding the following multi-column index:
> "data_part_202_dataset_regionset_data_idx" btree (dataset_id, data_id,
> stat_id)

Since you query stat_id for equality and data_id for range, you should
probably reverse the order of those columns in the index.


>
> QUESTION 3:
> If I do the following:  reindex table data_part_204 the query now takes
> 50-70 milliseconds.  Is this because the table is getting cached?  How do I
> know if a particular query is coming from the cache?

Using explain (analyze, buffers) will show you if it is coming from
the shared_buffers cache.

It is harder to see if it is coming from the file system cache.  If
the server is mostly idle other than your stuff, you can run vmstat
and see how much physical IO is caused by your activity.

Cheers,

Jeff

On 6/18/12 9:39 AM, Anish Kejariwal wrote:
> Thanks for the help, Jeff and Josh.  It looks reclustering the multi-column
> index might solve things.  For my particular query, because I'm getting a
> range of records back, it makes sense that reclustering will benefit me if
> I have a slow disk even if I had expected that the indices would be
> sufficient .  I now need to make sure that the speed up I'm seeing is not
> because things have been cached.

Well, other than that your performance is as expected because of your
much-larger-than-RAM database and your relatively slow disk.

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

Given a baseline postgresql.conf config and a couple DL580 40 core/256GB memory I noticed a large over head for
pgbouncer,has  anyone seen this before?
 


$ pgbench -h `hostname -i` -j 32 -p 4320 -U asgprod -s 500 -c 32 -S -T 60 pgbench_500
Scale option ignored, using pgbench_branches table count = 500
starting vacuum...end.
transaction type: SELECT only
scaling factor: 500
query mode: simple
number of clients: 32
number of threads: 32
duration: 60 s
number of transactions actually processed: 1743073
tps = 29049.886666 (including connections establishing)
tps = 29050.308194 (excluding connections establishing)

$ pgbench -h `hostname -i` -j 32 -p 4310 -U asgprod -s 500 -c 32 -S -T 60 pgbench_500
Scale option ignored, using pgbench_branches table count = 500
starting vacuum...end.
transaction type: SELECT only
scaling factor: 500
query mode: simple
number of clients: 32
number of threads: 32
duration: 60 s
number of transactions actually processed: 8692204
tps = 144857.505107 (including connections establishing)
tps = 144880.181341 (excluding connections establishing)

processor       : 39
vendor_id       : GenuineIntel
cpu family      : 6
model           : 47
model name      :        Intel(R) Xeon(R) CPU E7- 4860  @ 2.27GHz



This email is confidential and subject to important disclaimers and
conditions including on offers for the purchase or sale of
securities, accuracy and completeness of information, viruses,
confidentiality, legal privilege, and legal entity disclaimers,
available at http://www.jpmorgan.com/pages/disclosures/email.

On 06/19/2012 09:00 AM, Strange, John W wrote:
> Given a baseline postgresql.conf config and a couple DL580 40 core/256GB memory I noticed a large over head for
pgbouncer,has  anyone seen this before? 
>
>
> $ pgbench -h `hostname -i` -j 32 -p 4320 -U asgprod -s 500 -c 32 -S -T 60 pgbench_500
> Scale option ignored, using pgbench_branches table count = 500
> starting vacuum...end.
> transaction type: SELECT only
> scaling factor: 500
> query mode: simple
> number of clients: 32
> number of threads: 32
> duration: 60 s
> number of transactions actually processed: 1743073
> tps = 29049.886666 (including connections establishing)
> tps = 29050.308194 (excluding connections establishing)
>
> $ pgbench -h `hostname -i` -j 32 -p 4310 -U asgprod -s 500 -c 32 -S -T 60 pgbench_500
> Scale option ignored, using pgbench_branches table count = 500
> starting vacuum...end.
> transaction type: SELECT only
> scaling factor: 500
> query mode: simple
> number of clients: 32
> number of threads: 32
> duration: 60 s
> number of transactions actually processed: 8692204
> tps = 144857.505107 (including connections establishing)
> tps = 144880.181341 (excluding connections establishing)
>
> processor       : 39
> vendor_id       : GenuineIntel
> cpu family      : 6
> model           : 47
> model name      :        Intel(R) Xeon(R) CPU E7- 4860  @ 2.27GHz
>
>
I'm very dubious that the stats are meaningful as run. Were the above
stats generated on consecutive runs on the same machine or was the test
database fully returned to baseline between runs and the machine
restarted to clear cache?

I doubt anyone here would trust the results of a 60-second pgbench run -
especially a select-only test on a server that will likely end up with
virtually everything ultimately in cache. Make sure each run is started
from the same state and run for 30-60 minutes.

Still, you *are* adding a layer between the client and the server.
Running the simplest of read-only queries against a fully-cached
database on a fast many-core machine is likely to emphasize any latency
introduced by pgbouncer. But it's also not a use-case for which
pgbouncer is intended. If you were to add -C so each query required a
new client connection a different picture would emerge. Same thing if
you had 2000 client connections of which only a handful were running
queries at any moment.

Cheers,
Steve