Slow Postgresql server

Jason Lustig skrev:

and work_mem to 8096. What would cause the computer to only use such a
small percentage of the CPU, with more than half of it waiting on I/O
requests?

Do your webpages write things to the database on each connect?

Maybe it do a bunch of writes each individually commited? For every
commit pg will wait for the data to be written down to the disk platter
before it move on. So if you do several writes you want to do them in
one transaction so you only need one commit.

/Dennis

On Wed, 11 Apr 2007, Jason Lustig wrote:

Hello all,

My website has been having issues with our new Linux/PostgreSQL server being
somewhat slow. I have done tests using Apache Benchmark and for pages that do
not connect to Postgres, the speeds are much faster (334 requests/second v.
1-2 requests/second), so it seems that Postgres is what's causing the problem
and not Apache. I did some reserach, and it seems that the bottleneck is in
fact the hard drives! Here's an excerpt from vmstat:

procs -----------memory---------- ---swap-- -----io---- --system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa
st
1 1 140 24780 166636 575144 0 0 0 3900 1462 3299 1 4 49 48
0
0 1 140 24780 166636 575144 0 0 0 3828 1455 3391 0 4 48 48
0
1 1 140 24780 166636 575144 0 0 0 2440 960 2033 0 3 48 48
0
0 1 140 24780 166636 575144 0 0 0 2552 1001 2131 0 2 50 49
0
0 1 140 24780 166636 575144 0 0 0 3188 1233 2755 0 3 49 48
0
0 1 140 24780 166636 575144 0 0 0 2048 868 1812 0 2 49 49
0
0 1 140 24780 166636 575144 0 0 0 2720 1094 2386 0 3 49 49
0

As you can see, almost 50% of the CPU is waiting on I/O. This doesn't seem
like it should be happening, however, since we are using a RAID 1 setup
(160+160). We have 1GB ram, and have upped shared_buffers to 13000 and
work_mem to 8096. What would cause the computer to only use such a small
percentage of the CPU, with more than half of it waiting on I/O requests?

Well, the simple answer is a slow disk subsystem. Is it hardware or software
RAID1? If hardware, what's the RAID controller? Based on your vmstat output,
I'd guess that this query activity is all writes since I see only blocks out.
Can you identify what the slow queries are? What version of postgres? How
large is the database? Can you post the non-default values in your
postgresql.conf?

I'd suggest you test your disk subsystem to see if it's as performant as you
think with bonnie++. Here's some output from my RAID1 test server:

Version 1.03 ------Sequential Output------ --Sequential Input- --Random-
-Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP /sec %CP
pgtest 4G 47090 92 52348 11 30954 6 41838 65 73396 8 255.9 1
------Sequential Create------ --------Random Create--------
-Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
files /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP
16 894 2 +++++ +++ 854 1 817 2 +++++ +++ 969 2

So, that's 52MB/sec block writes and 73MB/sec block reads. That's typical of
a RAID1 on 2 semi-fast SATA drives.

If you're doing writes to the DB on every web page, you might consider playing
with the commit_delay and commit_siblings parameters in the postgresql.conf.
Also, if you're doing multiple inserts as separate transactions, you should
consider batching them up in one transaction.

--
Jeff Frost, Owner <jeff@frostconsultingllc.com>
Frost Consulting, LLC http://www.frostconsultingllc.com/
Phone: 650-780-7908 FAX: 650-649-1954

1= RAID 1improves data =intregrity=, not IO performance.
Your HD IO performance is essentially that of 1 160GB HD of whatever
performance one of those HDs have.
(what kind of HDs are they anyway? For instance 7200rpm 160GB HDs
are not particularly "high performance")
BEST case is streaming IO involving no seeks => ~50 MBps.
You can't get even that as the back end of a website.

2= 1GB of RAM is -small- for a DB server.

You need to buy RAM and HD.

Boost the RAM to 4GB, change pg config parameters appropriately and
see how much it helps.
Non ECC RAM is currently running ~$60-$75 per GB for 1 or 2 GB sticks
ECC RAM prices will be ~ 1.5x - 2x that, $120 - $150 per GB for 1 or
2 GB sticks.
(do !not! buy 4GB sticks unless you have a large budget. Their price
pr GB is still too high)

If adding RAM helps as much as I suspect it will, find out how big
the "hot" section of your DB is and see if you can buy enough RAM to
make it RAM resident.
If you can do this, it will result in the lowest term DB maintenance.

If you can't do that for whatever reason, the next step is to improve
your HD subsystem.
Cheap RAID cards with enough BB cache to allow writes to be coalesced
into larger streams (reducing seeks) will help, but you fundamentally
you will need more HDs.

RAID 5 is an reasonable option for most website DBs workloads.
To hit the 300MBps speeds attainable by the cheap RAID cards, you are
going to at least 7 HDs (6 HDs * 50MBps ASTR = 300MBps ASTR + the
equivalent of 1 HD gets used for the "R" in RAID). A minimum of 8
HDs are need for this performance if you want to use RAID 6.
Most tower case (not mini-tower, tower) cases can hold this internally.
Price per MBps of HD is all over the map. The simplest (but not
necessarily best) option is to buy more of the 160GB HDs you already have.
Optimizing the money spent when buying HDs for a RAID set is a bit
more complicated than doing so for RAM. Lot's of context dependent
things affect the final decision.

I see you are mailing from Brandeis. I'm local. Drop me some
private email at the address I'm posting from if you want and I'll
send you further contact info so we can talk in more detail.

Cheers,
Ron Peacetree

At 06:02 PM 4/11/2007, Jason Lustig wrote:

On 12.04.2007, at 07:26, Ron wrote:

You need to buy RAM and HD.

Before he does that, wouldn't it be more useful, to find out WHY he
has so much IO?

Have I missed that or has nobody suggested finding the slow queries
(when you have much IO on them, they might be slow at least with a
high shared memory setting).

So, my first idea is, to turn on query logging for queries longer
than a xy milliseconds, "explain analyse" these queries and see
wether there are a lot of seq scans involved, which would explain the
high IO.

Just an idea, perhaps I missed that step in that discussion
somewhere ...

But yes, it might also be, that the server is swapping, that's
another thing to find out.

cug

At 10:08 AM 4/12/2007, Guido Neitzer wrote:

On 12.04.2007, at 07:26, Ron wrote:

You need to buy RAM and HD.

Before he does that, wouldn't it be more useful, to find out WHY he
has so much IO?

1= Unless I missed something, the OP described pg being used as a
backend DB for a webserver.

I know the typical IO demands of that scenario better than I sometimes want to.
:-(

2= 1GB of RAM + effectively 1 160GB HD = p*ss poor DB IO support.
~ 1/2 that RAM is going to be used for OS stuff, leaving only ~512MB
of RAM to be used supporting pg.
That RAID 1 set is effectively 1 HD head that all IO requests are
going to contend for.
Even if the HD in question is a 15Krpm screamer, that level of HW
contention has very adverse implications.

Completely agree that at some point the queries need to be examined
(ditto the table schema, etc), but this system is starting off in a
Bad Place for its stated purpose IME.
Some minimum stuff is obvious even w/o spending time looking at
anything beyond the HW config.

Cheers,
Ron Peacetree

On 12.04.2007, at 08:59, Ron wrote:

1= Unless I missed something, the OP described pg being used as a
backend DB for a webserver.

Yep.

I know the typical IO demands of that scenario better than I
sometimes want to.
:-(

Yep. Same here. ;-)

2= 1GB of RAM + effectively 1 160GB HD = p*ss poor DB IO support.

Absolutely right. Depending a little bit on the DB and WebSite layout
and on the actual requirements, but yes - it's not really a kick-ass
machine ...

Completely agree that at some point the queries need to be examined
(ditto the table schema, etc), but this system is starting off in a
Bad Place for its stated purpose IME.
Some minimum stuff is obvious even w/o spending time looking at
anything beyond the HW config.

Depends. As I said - if the whole DB fits into the remaining space,
and a lot of website backend DBs do, it might just work out. But this
seems not to be the case - either the site is chewing on seq scans
all the time which will cause I/O or it is bound by the lack of
memory and swaps the whole time ... He has to find out.

cug

On Thu, 12 Apr 2007, Jason Lustig wrote:

0 <-- BM starts here
10 0 180 700436 16420 91740 0 0 0 176 278 2923 59 41 0
0 0
11 0 180 696736 16420 91740 0 0 0 0 254 2904 57 43 0
0 0
12 0 180 691272 16420 91740 0 0 0 0 255 3043 60 39 1
0 0
9 0 180 690396 16420 91740 0 0 0 0 254 3078 63 36 2 0
0

Obviously, I've turned off logging now but I'd like to get it running again
(without bogging down the server) so that I can profile the system and find
out which queries I need to optimize. My logging settings (with unnecessary
comments taken out) were:

So what did you get in the logs when you had logging turned on? If you have
the statement logging, perhaps it's worth running through pgfouine to generate
a report.

log_destination = 'syslog' # Valid values are combinations of
redirect_stderr = off # Enable capturing of stderr into log
log_min_duration_statement = 0 # -1 is disabled, 0 logs all
statements
silent_mode = on # DO NOT USE without syslog or
log_duration = off
log_line_prefix = 'user=%u,db=%d' # Special values:
log_statement = 'none' # none, ddl, mod, all

Perhaps you just want to log slow queries > 100ms? But since you don't seem
to know what queries you're running on each web page, I'd suggest you just
turn on the following and run your benchmark against it, then turn it back
off:

log_duration = on
log_statement = 'all'

Then go grab pgfouine and run the report against the logs to see what queries
are chewing up all your time.

So you know, we're using Postgres 8.2.3. The database currently is pretty
small (we're just running a testing database right now with a few megabytes
of data). No doubt some of our queries are slow, but I was concerned because
no matter how slow the queries were (at most the worst were taking a couple
of msecs anyway), I was getting ridiculously slow responses from the server.
Outside of logging, our only other non-default postgresql.conf items are:

shared_buffers = 13000 # min 128kB or max_connections*16kB
work_mem = 8096 # min 64kB

In terms of the server itself, I think that it uses software raid. How can I
tell? Our hosting company set it up with the server so I guess I could ask
them, but is there a program I can run which will tell me the information? I
also ran bonnie++ and got this output:

Version  1.03       ------Sequential Output------ --Sequential Input- 
--Random-
-Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- 
--Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec 
%CP
pgtest 2000M 29277  67 33819  15 15446   4 35144  62 48887   5 152.7   0
------Sequential Create------ --------Random 
Create--------
-Create-- --Read--- -Delete-- -Create-- --Read--- 
-Delete--
files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec 
%CP
16 17886  77 +++++ +++ +++++ +++ 23258  99 +++++ +++ +++++ 
+++

So I'm getting 33MB and 48MB write/read respectively. Is this slow? Is there
anything I should be doing to optimize our RAID configuration?

It's not fast, but at least it's about the same speed as an average IDE drive
from this era. More disks would help, but since you indicate the DB fits in
RAM with plenty of room to spare, how about you update your
effective_cache_size to something reasonable. You can use the output of the
'free' command and take the cache number and divide by 8 to get a reasonable
value on linux. Then turn on logging and run your benchmark. After that, run
a pgfouine report against the log and post us the explain analyze from your
slow queries.

And if Ron is indeed local, it might be worthwhile to contact him. Someone
onsite would likely get this taken care of much faster than we can on the
mailing list.

--
Jeff Frost, Owner <jeff@frostconsultingllc.com>
Frost Consulting, LLC http://www.frostconsultingllc.com/
Phone: 650-780-7908 FAX: 650-649-1954

On Thu, 2007-04-12 at 10:19, Guido Neitzer wrote:

On 12.04.2007, at 08:59, Ron wrote:

Depends. As I said - if the whole DB fits into the remaining space,
and a lot of website backend DBs do, it might just work out. But this
seems not to be the case - either the site is chewing on seq scans
all the time which will cause I/O or it is bound by the lack of
memory and swaps the whole time ... He has to find out.

It could also be something as simple as a very bloated data store.

I'd ask the user what vacuum verbose says at the end

On Thu, 12 Apr 2007, Scott Marlowe wrote:

On Thu, 2007-04-12 at 10:19, Guido Neitzer wrote:

On 12.04.2007, at 08:59, Ron wrote:

Depends. As I said - if the whole DB fits into the remaining space,
and a lot of website backend DBs do, it might just work out. But this
seems not to be the case - either the site is chewing on seq scans
all the time which will cause I/O or it is bound by the lack of
memory and swaps the whole time ... He has to find out.

It could also be something as simple as a very bloated data store.

I'd ask the user what vacuum verbose says at the end

You know, I should answer emails at night...we didn't ask when the last time
the data was vacuumed or analyzed and I believe he indicated that the only
non-default values were memory related, so no autovacuum running.

Jason,

Before you go any further, run 'vacuum analyze;' on your DB if you're not
doing this with regularity and strongly consider enabling autovacuum.

--
Jeff Frost, Owner <jeff@frostconsultingllc.com>
Frost Consulting, LLC http://www.frostconsultingllc.com/
Phone: 650-780-7908 FAX: 650-649-1954

Jeff Frost wrote:

You know, I should answer emails at night...

Indeed you shouldN'T ;-)

Carlos
--

Hey there;

On a Postgres 8.2.3 server, I've got a query that is running very slow in
some cases. With some work, I've determined the 'slow part' of the query.
:) This is a query on a table with like 10 million rows or something like
that. encounter_id is an integer and receipt is of type 'date'.

This query runs really slow [minutes] (query and explain below):

select extract(epoch from ds.receipt) from detail_summary ds where
ds.receipt >= '1998-12-30 0:0:0' and
ds.encounter_id in
(8813186,8813187,8813188,8813189,8813190,8813191,8813192,
8813193,8813194,8813195,8813196,8813197,8813198,8813199,
8813200,8813201,8813202,8813203,8813204,8813205,8813206,
8813207,8813208,8813209,8813210,8813211,8813212,8813213,
8813214,8813215,8813216,8813217,8813218,8813219,8813220,
8813221,8813222,8813223,8813224,8813225,8813226,8813227,
8813228,8813229,8813230,8813231,8813232,8813233,8813234,
8813235,8813236,8813237,8813238,8813239,8813240,8813241,
8813242,8813243,8813244,8813245,8813246,8813247,8813248,
8813249,8813250,8813251,8813252,8813253,8813254,8813255,
8813256,8813257,8813258,8813259,8813260,8813261,8813262,
8813263,8813264,8813265,8813266,8813267,8813268,8813269,
8813270,8813271,8813272,8813273,8813274,8813275,8813276,
8813277,8813278,8813279,8813280,8813281,8813282,8813283,
8813284,8815534)

Results in the 'explain' :

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
(2 rows)

Turning enable_seqscan to off results in a slightly more interesting
explain, but an equally slow query.

HOWEVER! The simple removal of the receipt date paramater results in a
fast query, as such:

select extract(epoch from ds.receipt) from detail_summary ds where
ds.encounter_id in
(8813186,8813187,8813188,8813189,8813190,8813191,8813192,
8813193,8813194,8813195,8813196,8813197,8813198,8813199,
8813200,8813201,8813202,8813203,8813204,8813205,8813206,
8813207,8813208,8813209,8813210,8813211,8813212,8813213,
8813214,8813215,8813216,8813217,8813218,8813219,8813220,
8813221,8813222,8813223,8813224,8813225,8813226,8813227,
8813228,8813229,8813230,8813231,8813232,8813233,8813234,
8813235,8813236,8813237,8813238,8813239,8813240,8813241,
8813242,8813243,8813244,8813245,8813246,8813247,8813248,
8813249,8813250,8813251,8813252,8813253,8813254,8813255,
8813256,8813257,8813258,8813259,8813260,8813261,8813262,
8813263,8813264,8813265,8813266,8813267,8813268,8813269,
8813270,8813271,8813272,8813273,8813274,8813275,8813276,
8813277,8813278,8813279,8813280,8813281,8813282,8813283,
8813284 ,8815534)

This query returns instantly and explains as:

Bitmap Heap Scan on detail_summary ds (cost=161.00..14819.81 rows=9963
width=4)
Recheck Cond: (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[]))
-> Bitmap Index Scan on detail_summary_encounter_id_idx
(cost=0.00..160.75 rows=9963 width=0)
Index Cond: (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[]))

Any thoughts? Both encounter_id and receipt date are indexed columns.
I've vacuumed and analyzed the table. I tried making a combined index of
encounter_id and receipt and it hasn't worked out any better.

Thanks!

Steve

Steve <cheetah@tanabi.org> writes:

On a Postgres 8.2.3 server, I've got a query that is running very slow in
some cases.

Could we see the exact definition of that table and its indexes?
It looks like the planner is missing the bitmap scan for some reason,
but I've not seen a case like that before.

Also, I assume the restriction on receipt date is very nonselective?
It doesn't seem to have changed the estimated rowcount much.

regards, tom lane

Could we see the exact definition of that table and its indexes?
It looks like the planner is missing the bitmap scan for some reason,
but I've not seen a case like that before.

Also, I assume the restriction on receipt date is very nonselective?
It doesn't seem to have changed the estimated rowcount much.

This is true -- This particular receipt date is actually quite
meaningless. It's equivalent to saying 'all receipt dates'. I don't
think there's even any data that goes back before 2005.

Here's the table and it's indexes. Before looking, a note; there's
several 'revop' indexes, this is for sorting. The customer insisted on,
frankly, meaninglessly complicated sorts. I don't think any of that
matters for our purposes here though :)

Column | Type |
Modifiers
-----------------------+------------------------+--------------------------------------------------------------------
detailsummary_id | integer | not null default
nextval(('detailsummary_id_seq'::text)::regclass)
detailgroup_id | integer |
receipt | date |
batchnum | integer |
encounternum | integer |
procedureseq | integer |
procedurecode | character varying(5) |
wrong_procedurecode | character varying(5) |
batch_id | integer |
encounter_id | integer |
procedure_id | integer |
carrier_id | integer |
product_line | integer |
provider_id | integer |
member_num | character varying(20) |
wrong_member_num | character varying(20) |
member_name | character varying(40) |
patient_control | character varying(20) |
rendering_prov_id | character varying(15) |
rendering_prov_name | character varying(30) |
referring_prov_id | character varying(15) |
referring_prov_name | character varying(30) |
servicedate | date |
wrong_servicedate | date |
diagnosis_codes | character varying(5)[] |
wrong_diagnosis_codes | character varying(5)[] |
ffs_charge | double precision |
export_date | date |
hedis_date | date |
raps_date | date |
diagnosis_pointers | character(1)[] |
modifiers | character(2)[] |
units | double precision |
pos | character(2) |
isduplicate | boolean |
duplicate_id | integer |
encounter_corrected | boolean |
procedure_corrected | boolean |
numerrors | integer |
encerrors_codes | integer[] |
procerror_code | integer |
error_servicedate | text |
e_duplicate_id | integer |
ecode_counts | integer[] |
p_record_status | integer |
e_record_status | integer |
e_delete_date | date |
p_delete_date | date |
b_record_status | integer |
b_confirmation | character varying(20) |
b_carrier_cobol_id | character varying(16) |
b_provider_cobol_id | character varying(20) |
b_provider_tax_id | character varying(16) |
b_carrier_name | character varying(50) |
b_provider_name | character varying(50) |
b_submitter_file_id | character varying(40) |
e_hist_carrier_id | integer |
p_hist_carrier_id | integer |
e_duplicate_id_orig | character varying(25) |
p_duplicate_id_orig | character varying(25) |
num_procerrors | integer |
num_encerrors | integer |
export_id | integer |
raps_id | integer |
hedis_id | integer |
Indexes:
"detail_summary_b_record_status_idx" btree (b_record_status)
"detail_summary_batch_id_idx" btree (batch_id)
"detail_summary_batchnum_idx" btree (batchnum)
"detail_summary_carrier_id_idx" btree (carrier_id)
"detail_summary_duplicate_id_idx" btree (duplicate_id)
"detail_summary_e_record_status_idx" btree (e_record_status)
"detail_summary_encounter_id_idx" btree (encounter_id)
"detail_summary_encounternum_idx" btree (encounternum)
"detail_summary_export_date_idx" btree (export_date)
"detail_summary_hedis_date_idx" btree (hedis_date)
"detail_summary_member_name_idx" btree (member_name)
"detail_summary_member_num_idx" btree (member_num)
"detail_summary_p_record_status_idx" btree (p_record_status)
"detail_summary_patient_control_idx" btree (patient_control)
"detail_summary_procedurecode_idx" btree (procedurecode)
"detail_summary_product_line_idx" btree (product_line)
"detail_summary_provider_id_idx" btree (provider_id)
"detail_summary_raps_date_idx" btree (raps_date)
"detail_summary_receipt_encounter_idx" btree (receipt, encounter_id)
"detail_summary_receipt_id_idx" btree (receipt)
"detail_summary_referrering_prov_id_idx" btree (referring_prov_id)
"detail_summary_rendering_prov_id_idx" btree (rendering_prov_id)
"detail_summary_rendering_prov_name_idx" btree (rendering_prov_name)
"detail_summary_servicedate_idx" btree (servicedate)
"ds_sort_1" btree (receipt date_revop, carrier_id, batchnum,
encounternum, procedurecode, encounter_id)
"ds_sort_10" btree (receipt date_revop, carrier_id, batchnum,
encounternum, procedurecode, encounter_id, procedure_id)
"ed_cbee_norev" btree (export_date, carrier_id, batchnum,
encounternum, encounter_id)
"ed_cbee_norev_p" btree (export_date, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"ed_cbee_rev" btree (export_date date_revop, carrier_id, batchnum,
encounternum, encounter_id)
"ed_cbee_rev_p" btree (export_date date_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"mcbe" btree (member_name, carrier_id, batchnum, encounternum,
encounter_id)
"mcbe_p" btree (member_name, carrier_id, batchnum, encounternum,
encounter_id, procedure_id)
"mcbe_rev" btree (member_name text_revop, carrier_id, batchnum,
encounternum, encounter_id)
"mcbe_rev_p" btree (member_name text_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"mcbee_norev" btree (member_num, carrier_id, batchnum, encounternum,
encounter_id)
"mcbee_norev_p" btree (member_num, carrier_id, batchnum, encounternum,
encounter_id, procedure_id)
"mcbee_rev" btree (member_num text_revop, carrier_id, batchnum,
encounternum, encounter_id)
"mcbee_rev_p" btree (member_num text_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"pcbee_norev" btree (patient_control, carrier_id, batchnum,
encounternum, encounter_id)
"pcbee_norev_p" btree (patient_control, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"pcbee_rev" btree (patient_control text_revop, carrier_id, batchnum,
encounternum, encounter_id)
"pcbee_rev_p" btree (patient_control text_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"rcbee_norev" btree (receipt, carrier_id, batchnum, encounternum,
encounter_id)
"rcbee_norev_p" btree (receipt, carrier_id, batchnum, encounternum,
encounter_id, procedure_id)
"rp_cbee_norev" btree (rendering_prov_name, carrier_id, batchnum,
encounternum, encounter_id)
"rp_cbee_norev_p" btree (rendering_prov_name, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"rp_cbee_rev" btree (rendering_prov_name text_revop, carrier_id,
batchnum, encounternum, encounter_id)
"rp_cbee_rev_p" btree (rendering_prov_name text_revop, carrier_id,
batchnum, encounternum, encounter_id, procedure_id)
"sd_cbee_norev" btree (servicedate, carrier_id, batchnum,
encounternum, encounter_id)
"sd_cbee_norev_p" btree (servicedate, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"sd_cbee_rev" btree (servicedate date_revop, carrier_id, batchnum,
encounternum, encounter_id)
"sd_cbee_rev_p" btree (servicedate date_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)
"testrev" btree (receipt date_revop, carrier_id, batchnum,
encounternum, encounter_id)
"testrev_p" btree (receipt date_revop, carrier_id, batchnum,
encounternum, encounter_id, procedure_id)

On Thu, 2007-04-12 at 16:03, Steve wrote:

Hey there;

On a Postgres 8.2.3 server, I've got a query that is running very slow in
some cases. With some work, I've determined the 'slow part' of the query.
:) This is a query on a table with like 10 million rows or something like
that. encounter_id is an integer and receipt is of type 'date'.

SNIP

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
(2 rows)

How accurate is the row estimate made by the planner? (explain analyze
to be sure)

Hi all,

Wow! That's a lot to respond to. Let me go through some of the
ideas... First, I just turned on autovacuum, I forgot to do that. I'm
not seeing a major impact though. Also, I know that it's not optimal
for a dedicated server. It's not just for postgres, it's also got our
apache server on it. We're just getting started and didn't want to
make the major investment right now in getting the most expensive
server we can get. Within the next year, as our traffic grows, we
will most likely upgrade, but for now when we're in the beginning
phases of our project, we're going to work with this server.

In terms of RAID not helping speed-wise (only making an impact in
data integrity) - I was under the impression that even a mirrored
disk set improves speed, because read requests can be sent to either
of the disk controllers. Is this incorrect?

I turned on logging again, only logging queries > 5ms. and it caused
the same problems. I think it might be an issue within the OS's
logging facilities, since it's going through stderr.

Some of the queries are definitely making an impact on the speed. We
are constantly trying to improve performance, and part of that is
reassessing our indexes and denormalizing data where it would help.
We're also doing work with memcached to cache the results of some of
the more expensive operations.

Thanks for all your help guys - it's really fantastic to see the
community here! I've got a lot of database experience (mostly with ms
sql and mysql) but this is my first time doing serious work with
postgres and it's really a great system with great people too.

Jason

On Apr 12, 2007, at 11:35 AM, Jeff Frost wrote:

Steve <cheetah@tanabi.org> writes:

Here's the table and it's indexes. Before looking, a note; there's
several 'revop' indexes, this is for sorting. The customer insisted on,
frankly, meaninglessly complicated sorts. I don't think any of that
matters for our purposes here though :)

Oy vey ... I hope this is a read-mostly table, because having that many
indexes has got to be killing your insert/update performance.

I see that some of the revop indexes might be considered relevant to
this query, so how exactly have you got those opclasses defined?
There's built-in support for reverse sort as of CVS HEAD, but in
existing releases you must have cobbled something together, and I wonder
if that could be a contributing factor ...

regards, tom lane

Oy vey ... I hope this is a read-mostly table, because having that many
indexes has got to be killing your insert/update performance.

Hahaha yeah these are read-only tables. Nightly inserts/updates.
Takes a few hours, depending on how many records (between 4 and 10
usually). But during the day, while querying, read only.

I see that some of the revop indexes might be considered relevant to
this query, so how exactly have you got those opclasses defined?
There's built-in support for reverse sort as of CVS HEAD, but in
existing releases you must have cobbled something together, and I wonder
if that could be a contributing factor ...

Here's the revops (the c functions are at the bottom):

CREATE FUNCTION ddd_date_revcmp(date, date) RETURNS integer
AS '/usr/local/pgsql/contrib/cmplib.so', 'ddd_date_revcmp'
LANGUAGE c STRICT;

CREATE FUNCTION ddd_int_revcmp(integer, integer) RETURNS integer
AS '/usr/local/pgsql/contrib/cmplib.so', 'ddd_int_revcmp'
LANGUAGE c STRICT;

CREATE FUNCTION ddd_text_revcmp(text, text) RETURNS integer
AS '/usr/local/pgsql/contrib/cmplib.so', 'ddd_text_revcmp'
LANGUAGE c STRICT;

CREATE OPERATOR CLASS date_revop
FOR TYPE date USING btree AS
OPERATOR 1 >(date,date) ,
OPERATOR 2 >=(date,date) ,
OPERATOR 3 =(date,date) ,
OPERATOR 4 <=(date,date) ,
OPERATOR 5 <(date,date) ,
FUNCTION 1 ddd_date_revcmp(date,date);

CREATE OPERATOR CLASS int4_revop
FOR TYPE integer USING btree AS
OPERATOR 1 >(integer,integer) ,
OPERATOR 2 >=(integer,integer) ,
OPERATOR 3 =(integer,integer) ,
OPERATOR 4 <=(integer,integer) ,
OPERATOR 5 <(integer,integer) ,
FUNCTION 1 ddd_int_revcmp(integer,integer);

CREATE OPERATOR CLASS text_revop
FOR TYPE text USING btree AS
OPERATOR 1 >(text,text) ,
OPERATOR 2 >=(text,text) ,
OPERATOR 3 =(text,text) ,
OPERATOR 4 <=(text,text) ,
OPERATOR 5 <(text,text) ,
FUNCTION 1 ddd_text_revcmp(text,text);

Datum ddd_date_revcmp(PG_FUNCTION_ARGS){
DateADT arg1=PG_GETARG_DATEADT(0);
DateADT arg2=PG_GETARG_DATEADT(1);

PG_RETURN_INT32(arg2 - arg1);
}

Datum ddd_int_revcmp(PG_FUNCTION_ARGS){
int32 arg1=PG_GETARG_INT32(0);
int32 arg2=PG_GETARG_INT32(1);

PG_RETURN_INT32(arg2 - arg1);
}

Datum ddd_text_revcmp(PG_FUNCTION_ARGS){
char* arg1=(char*)VARDATA(PG_GETARG_TEXT_P(0));
char* arg2=(char*)VARDATA(PG_GETARG_TEXT_P(1));

if((*arg1) != (*arg2)){
PG_RETURN_INT32(*arg2 - *arg1);
}else{
PG_RETURN_INT32(strcmp(arg2,arg1));
}
}

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
(2 rows)

How accurate is the row estimate made by the planner? (explain analyze
to be sure)

Results:

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
(actual time=62871.386..257258.249 rows=112 loops=1)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
Total runtime: 257258.652 ms

On Thu, 2007-04-12 at 17:04, Steve wrote:

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
(2 rows)

How accurate is the row estimate made by the planner? (explain analyze
to be sure)

Results:

Seq Scan on detail_summary ds (cost=0.00..1902749.83 rows=9962 width=4)
(actual time=62871.386..257258.249 rows=112 loops=1)
Filter: ((receipt >= '1998-12-30'::date) AND (encounter_id = ANY
('{8813186,8813187,8813188,8813189,8813190,8813191,8813192,8813193,8813194,8813195,8813196,8813197,8813198,8813199,8813200,8813201,8813202,8813203,8813204,8813205,8813206,8813207,8813208,8813209,8813210,8813211,8813212,8813213,8813214,8813215,8813216,8813217,8813218,8813219,8813220,8813221,8813222,8813223,8813224,8813225,8813226,8813227,8813228,8813229,8813230,8813231,8813232,8813233,8813234,8813235,8813236,8813237,8813238,8813239,8813240,8813241,8813242,8813243,8813244,8813245,8813246,8813247,8813248,8813249,8813250,8813251,8813252,8813253,8813254,8813255,8813256,8813257,8813258,8813259,8813260,8813261,8813262,8813263,8813264,8813265,8813266,8813267,8813268,8813269,8813270,8813271,8813272,8813273,8813274,8813275,8813276,8813277,8813278,8813279,8813280,8813281,8813282,8813283,8813284,8815534}'::integer[])))
Total runtime: 257258.652 ms

So there's a misjudgment of the number of rows returned by a factor of
about 88. That's pretty big. Since you had the same number without the
receipt date (I think...) then it's the encounter_id that's not being
counted right.

Try upping the stats target on that column and running analyze again and
see if you get closer to 112 in your analyze or not.