I'm having some trouble with postgres performance on my linode. I have a very large database (13M records) on which I do fairly complicated queries. On my development machine (which is a MacBook Pro) the queries run in a 2-4 seconds. On the linode with the same database the same queries take 200 seconds. I thought the problem was memory so I upgraded from 360 to 540 to 1080 linode, but I keep seeing the same slow performance.

So I'm wondering if there isn't some other problem. Has anybody configured postgres to work well with very large databases on linode?

Any help would be greatly appreciated.

Thanks,

-Eric

I'm not too familiar with Postgres so can't directly help, but it's going to be hard for anyone to answer without the following details about both your development and production systems:

• Operating system and version
• Processor and speed
• Memory
• Postgres version
• How you're connecting (e.g., PHP pg functions, Perl DBI) and version

If you're using something like Wordpress it'd also be useful to know what version and any extensions (especially caching ones) that may be in use.

Good point. Thanks. Here are the details:

Development: MacBook Pro Late 2008 model, 4G RAM
Production: Linode 1G, Ubuntu 8.04 LTS
Postgres: 8.3

Connection to postgres is via Rails 2.2.2 under Apache & Passenger, for a web-app I'm developing.

I've taken the step of increasing shmmax and shmall with:
$ sysctl -w kernel.shmmax=134217728
$ sysctl -w kernel.shmall=2097152

and then increasing shared buffers to 120M but that doesn't seem to make a bit of difference.

Your laptop can't possibly be faster than a Linode 1080... unless your DB is so big it takes 4GB of RAM just to buffer the indexes. Do you by any chance run a quad-core Xeon and RAID in your MacBook?

1) Do you have appropriate indexes on all the columns involved in your WHERE and ORDER BY clauses? You might have accidentally knocked out a couple of indexes when you set up your production DB...

2) Have you looked at the shared buffers and other performance-related settings in your postgresql.conf file? Any major differences between your development box and your production box?
See http://www.postgresql.org/docs/8.3/inte ... onfig.html

3) Use EXPLAIN ANALYZE to discover which part of your query is taking so long. Just stick those two words in front of your usual querystring.

EXPLAIN ANALYZE SELECT a, b, c FROM table...... etc. etc. etc. 

That's what I thought too, that linode had to be faster, but it isn't.

The settings on both the production and development boxes were simply the default ones set up by a postgres install. Since then I did take the step of increasing shmmax and shmall with:
$ sysctl -w kernel.shmmax=134217728
$ sysctl -w kernel.shmall=2097152

and then increasing shared_buffers to 120M but that doesn't seem to make a bit of difference.

The database is huge, 13 million records. So it could be what you say about caching the indexes. Is there a way to determine that? I also would have thought that shared_buffers would make a difference for that.

I did confirm that the same indexes are in place in both production and server boxes.

I've done and explain analyze but I don't know how to parse all that information, and all I see is that the numbers are bigger on the linode than on my mac!

Thanks for your help.

Actually I'm looking closely at the explain analyze results on bother dev and production boxes, and on my laptop, for my left outer joins I see entries like:

Index Scan using field_instances_form_instance_id_idx on field_instances "Book_MonthConsentSent"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.035..0.230 rows=1 loops=160)
                           Index Cond: ("Book_MonthConsentSent".form_instance_id = form_instances.id)
                           Filter: (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text)

But on the linode the corresponding entries are like this:

                  ->  Bitmap Heap Scan on field_instances "Book_MonthConsentSent"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=189.458..189.627 rows=1 loops=133)
                           Recheck Cond: (("Book_MonthConsentSent".form_instance_id = form_instances.id) AND (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text))
                           ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=189.432..189.432 rows=0 loops=133)
                                 ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.076..0.076 rows=408 loops=133)
                                       Index Cond: ("Book_MonthConsentSent".form_instance_id = form_instances.id)
                                 ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=189.168..189.168 rows=34190 loops=133)
                                       Index Cond: (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text)

So is this indeed the proof that it can't fit the index into memory?

See the part where it says "actual time". There are two numbers separated by two periods. The difference between those two numbers is the actual time, in milliseconds, that it took for postgres to process that part of the query. Find the operation that takes the most time. If your query takes 200 seconds, there must be some part of the query that takes nearly 200,000 milliseconds to process.

By the way, did you run VACUUM ANALYZE on all of your tables after loading data onto your production server? Otherwise postgres has no idea how to find the best plan for a given query...

Below are the complete results of the query.

It seems like the issue is that on the development server the cost of Nested Loop Left Join after an index scan is small, I'm guessing because it did an Index Scan, whereas on the production server the cost is large because it did a Bitmap Index Scan?

I'm trying the VACUME ANALYZE to see if that will help it figure out what to do.

-e


Development box: VERY FAST!

 Unique  (cost=135668.24..135668.37 rows=3 width=52) (actual time=509.623..509.804 rows=160 loops=1)
   ->  Sort  (cost=135668.24..135668.25 rows=3 width=52) (actual time=509.620..509.644 rows=160 loops=1)
         Sort Key: "H_ReviewedBy".answer, "H_CreatedBy".answer, "H_ClaimedBy".answer, "H_Source".answer, "H_Ccode".answer, "Revised_EstimatedDueDate".answer, "Book_EstimatedDueDate".answer, "Book_ConsentSigned".an
swer, "Book_MonthConsentSent".answer, "Book_ConsentHashCode".answer, "H_Form".answer, "Book_BookingDate".answer, "Dem_MomAge".answer, form_instances.id, form_instances.workflow_state, form_instances.form_id
         Sort Method:  quicksort  Memory: 38kB
         ->  Nested Loop Left Join  (cost=775.66..135668.22 rows=3 width=52) (actual time=1.317..504.737 rows=160 loops=1)
               ->  Nested Loop Left Join  (cost=775.66..134656.45 rows=3 width=49) (actual time=1.298..471.557 rows=160 loops=1)
                     ->  Nested Loop Left Join  (cost=775.66..133644.68 rows=3 width=46) (actual time=1.279..434.334 rows=160 loops=1)
                           ->  Nested Loop Left Join  (cost=775.66..132632.91 rows=3 width=43) (actual time=1.260..398.080 rows=160 loops=1)
                                 ->  Nested Loop Left Join  (cost=775.66..131621.14 rows=3 width=40) (actual time=1.246..364.133 rows=160 loops=1)
                                       ->  Nested Loop Left Join  (cost=775.66..130609.37 rows=3 width=37) (actual time=1.228..330.402 rows=160 loops=1)
                                             ->  Nested Loop Left Join  (cost=775.66..129597.60 rows=3 width=34) (actual time=1.204..288.537 rows=160 loops=1)
                                                   Filter: (("H_Source".answer !~~ 'R%'::text) OR ("H_Source".answer IS NULL))
                                                   ->  Nested Loop Left Join  (cost=775.66..128591.35 rows=3 width=31) (actual time=1.188..255.079 rows=160 loops=1)
                                                         ->  Nested Loop Left Join  (cost=775.66..127585.19 rows=3 width=28) (actual time=0.998..219.723 rows=160 loops=1)
                                                               ->  Nested Loop Left Join  (cost=775.66..126579.03 rows=3 width=25) (actual time=0.983..183.937 rows=160 loops=1)
                                                                     ->  Nested Loop Left Join  (cost=775.66..125572.87 rows=3 width=22) (actual time=0.795..131.797 rows=160 loops=1)
                                                                           ->  Nested Loop Left Join  (cost=775.66..124566.71 rows=3 width=19) (actual time=0.777..97.992 rows=160 loops=1)
                                                                                 Filter: (CASE WHEN ((form_instances.workflow_state)::text = ANY ('{mlog,mlogLate}'::text[])) THEN "H_CreatedBy".answer WHEN ((form_i
nstances.workflow_state)::text = ANY ('{claimed,claimedLate,claimedv,claimedvLate,DRqueued,DRreviewing,done}'::text[])) THEN "H_ClaimedBy".answer WHEN ((form_instances.workflow_state)::text = ANY ('{doneLeftCareNo
Consent,doneRefused,doneX}'::text[])) THEN CASE WHEN (NOT (("H_ClaimedBy".answer = ''::text) OR ("H_ClaimedBy".answer IS NULL))) THEN "H_ClaimedBy".answer WHEN (NOT (("H_CreatedBy".answer = ''::text) OR ("H_Create
dBy".answer IS NULL))) THEN "H_CreatedBy".answer ELSE NULL::text END ELSE NULL::text END = ANY ('{49,48,50}'::text[]))
                                                                                 ->  Nested Loop Left Join  (cost=775.66..62807.41 rows=184 width=16) (actual time=0.751..43.318 rows=160 loops=1)
                                                                                       ->  Bitmap Heap Scan on form_instances  (cost=775.66..1096.19 rows=184 width=13) (actual time=0.530..0.936 rows=160 loops=1)
                                                                                             Recheck Cond: (id = ANY ('{5124,5126,5126,6296,6296,6583,6583,6746,6746,7674,7674,7676,7676,7686,7686,7728,7728,8078,807
8,8080,8080,8082,8082,8083,8083,8209,8209,8409,8409,10714,10714,10719,10719,10720,10720,10721,10721,10723,10723,14202,14203,14934,14936,14937,14938,14939,14940,14941,14942,14944,14945,14946,14947,14949,14950,14952
,14953,17959,17965,19133,19643,19648,20702,20702,20705,20705,22698,22699,22705,22707,22708,22709,22710,23042,23043,23045,23047,23048,23049,23050,23052,23053,23054,23055,23056,25343,25343,25344,25344,25345,25346,25
347,25348,25348,25350,25355,25356,25358,25359,25360,25361,25362,28910,28911,28912,28914,28915,28917,28918,28920,28921,28922,28924,28925,28927,28929,28932,28933,28934,28935,28936,28937,28939,28940,28941,28942,28944
,28945,28946,30587,30588,30589,30590,30591,30592,30593,30594,30595,30596,30597,30598,30599,30600,30601,30602,30603,30604,30605,30606,30607,30608,32439,32440,32441,32442,32443,32444,32445,32446,32447,32448,32449,32
450,32451,32452,32453,32454,32455,32456,32457,32458,33479,33480,33481,33482,33483,33484,33485,33486,33487,33488,33489,33490,33491}'::integer[]))
                                                                                             ->  Bitmap Index Scan on form_instances_pkey  (cost=0.00..775.61 rows=184 width=0) (actual time=0.520..0.520 rows=184 lo
ops=1)
                                                                                                   Index Cond: (id = ANY ('{5124,5126,5126,6296,6296,6583,6583,6746,6746,7674,7674,7676,7676,7686,7686,7728,7728,8078
,8078,8080,8080,8082,8082,8083,8083,8209,8209,8409,8409,10714,10714,10719,10719,10720,10720,10721,10721,10723,10723,14202,14203,14934,14936,14937,14938,14939,14940,14941,14942,14944,14945,14946,14947,14949,14950,1
4952,14953,17959,17965,19133,19643,19648,20702,20702,20705,20705,22698,22699,22705,22707,22708,22709,22710,23042,23043,23045,23047,23048,23049,23050,23052,23053,23054,23055,23056,25343,25343,25344,25344,25345,2534
6,25347,25348,25348,25350,25355,25356,25358,25359,25360,25361,25362,28910,28911,28912,28914,28915,28917,28918,28920,28921,28922,28924,28925,28927,28929,28932,28933,28934,28935,28936,28937,28939,28940,28941,28942,2
8944,28945,28946,30587,30588,30589,30590,30591,30592,30593,30594,30595,30596,30597,30598,30599,30600,30601,30602,30603,30604,30605,30606,30607,30608,32439,32440,32441,32442,32443,32444,32445,32446,32447,32448,3244
9,32450,32451,32452,32453,32454,32455,32456,32457,32458,33479,33480,33481,33482,33483,33484,33485,33486,33487,33488,33489,33490,33491}'::integer[]))
                                                                                       ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_ClaimedBy"  (cost=0.00..335.25 rows=11 width=7
) (actual time=0.210..0.262 rows=0 loops=160)
                                                                                             Index Cond: ("H_ClaimedBy".form_instance_id = form_instances.id)
                                                                                             Filter: (("H_ClaimedBy".field_id)::text = 'H_ClaimedBy'::text)
                                                                                 ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_CreatedBy"  (cost=0.00..335.25 rows=11 width=7) (act
ual time=0.023..0.338 rows=1 loops=160)
                                                                                       Index Cond: ("H_CreatedBy".form_instance_id = form_instances.id)
                                                                                       Filter: (("H_CreatedBy".field_id)::text = 'H_CreatedBy'::text)
                                                                           ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Book_EstimatedDueDate"  (cost=0.00..335.25 rows=11 width=7) 
(actual time=0.023..0.210 rows=1 loops=160)
                                                                                 Index Cond: ("Book_EstimatedDueDate".form_instance_id = form_instances.id)
                                                                                 Filter: (("Book_EstimatedDueDate".field_id)::text = 'Book_EstimatedDueDate'::text)
                                                                     ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Revised_EstimatedDueDate"  (cost=0.00..335.25 rows=11 width=7) (ac
tual time=0.325..0.325 rows=0 loops=160)
                                                                           Index Cond: ("Revised_EstimatedDueDate".form_instance_id = form_instances.id)
                                                                           Filter: (("Revised_EstimatedDueDate".field_id)::text = 'Revised_EstimatedDueDate'::text)
                                                               ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_Ccode"  (cost=0.00..335.25 rows=11 width=7) (actual time=0.018..0.222 
rows=1 loops=160)
                                                                     Index Cond: ("H_Ccode".form_instance_id = form_instances.id)
                                                                     Filter: (("H_Ccode".field_id)::text = 'H_Ccode'::text)
                                                         ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_ReviewedBy"  (cost=0.00..335.25 rows=11 width=7) (actual time=0.220..0.220 r
ows=0 loops=160)
                                                               Index Cond: ("H_ReviewedBy".form_instance_id = form_instances.id)
                                                               Filter: (("H_ReviewedBy".field_id)::text = 'H_ReviewedBy'::text)
                                                   ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_Source"  (cost=0.00..335.25 rows=11 width=7) (actual time=0.019..0.207 rows=1 loop
s=160)
                                                         Index Cond: ("H_Source".form_instance_id = form_instances.id)
                                                         Filter: (("H_Source".field_id)::text = 'H_Source'::text)
                                             ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Dem_MomAge"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.042..0.260 rows=1 loops=16
0)
                                                   Index Cond: ("Dem_MomAge".form_instance_id = form_instances.id)
                                                   Filter: (("Dem_MomAge".field_id)::text = 'Dem_MomAge'::text)
                                       ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Book_BookingDate"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.025..0.209 rows=1 loops=16
0)
                                             Index Cond: ("Book_BookingDate".form_instance_id = form_instances.id)
                                             Filter: (("Book_BookingDate".field_id)::text = 'Book_BookingDate'::text)
                                 ->  Index Scan using field_instances_form_instance_id_idx on field_instances "H_Form"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.019..0.211 rows=1 loops=160)
                                       Index Cond: ("H_Form".form_instance_id = form_instances.id)
                                       Filter: (("H_Form".field_id)::text = 'H_Form'::text)
                           ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Book_ConsentHashCode"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.024..0.225 rows=1 loops=160)
                                 Index Cond: ("Book_ConsentHashCode".form_instance_id = form_instances.id)
                                 Filter: (("Book_ConsentHashCode".field_id)::text = 'Book_ConsentHashCode'::text)
                     ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Book_MonthConsentSent"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.035..0.230 rows=1 loops=160)
                           Index Cond: ("Book_MonthConsentSent".form_instance_id = form_instances.id)
                           Filter: (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text)
               ->  Index Scan using field_instances_form_instance_id_idx on field_instances "Book_ConsentSigned"  (cost=0.00..337.12 rows=11 width=7) (actual time=0.023..0.206 rows=1 loops=160)
                     Index Cond: ("Book_ConsentSigned".form_instance_id = form_instances.id)
                     Filter: (("Book_ConsentSigned".field_id)::text = 'Book_ConsentSigned'::text)
 Total runtime: 510.638 ms

Production Box (virtual server) VERY SLOW

Unique  (cost=230997.30..230997.43 rows=3 width=91) (actual time=214288.333..214288.683 rows=133 loops=1)
   ->  Sort  (cost=230997.30..230997.31 rows=3 width=91) (actual time=214288.330..214288.421 rows=133 loops=1)
         Sort Key: "H_ReviewedBy".answer, "H_CreatedBy".answer, "H_ClaimedBy".answer, "H_Source".answer, "H_Ccode".answer, "Revised_EstimatedDueDate".answer, "Book_EstimatedDueDate".answer, "Book_ConsentSigned".answer, "Book_MonthConsentSent".answer, "Book_ConsentHashCode".answer, "H_Form".answer, "Book_BookingDate".answer, "Dem_MomAge".answer, form_instances.id, form_instances.workflow_state, form_instances.form_id
         Sort Method:  quicksort  Memory: 34kB
         ->  Nested Loop Left Join  (cost=202172.52..230997.28 rows=3 width=91) (actual time=3531.080..214287.098 rows=133 loops=1)
               ->  Nested Loop Left Join  (cost=200932.81..227146.03 rows=3 width=85) (actual time=3084.301..189350.573 rows=133 loops=1)
                     ->  Nested Loop Left Join  (cost=199693.10..223294.77 rows=3 width=79) (actual time=2577.310..164127.956 rows=133 loops=1)
                           ->  Nested Loop Left Join  (cost=198453.40..219443.52 rows=3 width=73) (actual time=2181.147..139519.122 rows=133 loops=1)
                                 ->  Nested Loop Left Join  (cost=197213.69..215592.27 rows=3 width=67) (actual time=2011.149..117328.373 rows=133 loops=1)
                                       ->  Nested Loop Left Join  (cost=195973.98..211741.02 rows=3 width=61) (actual time=1785.922..95024.349 rows=133 loops=1)
                                             ->  Nested Loop Left Join  (cost=194734.28..207889.76 rows=3 width=55) (actual time=1595.435..72595.850 rows=133 loops=1)
                                                   Filter: (("H_Source".answer !~~ 'R%'::text) OR ("H_Source".answer IS NULL))
                                                   ->  Nested Loop Left Join  (cost=193518.86..204111.30 rows=3 width=49) (actual time=1430.520..49304.420 rows=133 loops=1)
                                                         ->  Nested Loop Left Join  (cost=192303.44..200332.91 rows=3 width=43) (actual time=1425.161..48603.661 rows=133 loops=1)
                                                               ->  Nested Loop Left Join  (cost=191088.03..196554.53 rows=3 width=37) (actual time=1259.268..26433.264 rows=133 loops=1)
                                                                     ->  Nested Loop Left Join  (cost=189872.61..192776.15 rows=3 width=31) (actual time=1238.451..26397.772 rows=133 loops=1)
                                                                           ->  Merge Left Join  (cost=188657.19..188997.76 rows=3 width=25) (actual time=1012.071..1110.595 rows=133 loops=1)
                                                                                 Merge Cond: (form_instances.id = "H_CreatedBy".form_instance_id)
                                                                                 Filter: (CASE WHEN ((form_instances.workflow_state)::text = ANY ('{mlog,mlogLate}'::text[])) THEN "H_CreatedBy".answer WHEN ((form_instances.workflow_state)::text = ANY ('{claimed,claimedLate,claimedv,claimedvLate,DRqueued,DRreviewing,done}'::text[])) THEN "H_ClaimedBy".answer WHEN ((form_instances.workflow_state)::text = ANY ('{doneLeftCareNoConsent,doneRefused,doneX}'::text[])) THEN CASE WHEN (NOT (("H_ClaimedBy".answer = ''::text) OR ("H_ClaimedBy".answer IS NULL))) THEN "H_ClaimedBy".answer WHEN (NOT (("H_CreatedBy".answer = ''::text) OR ("H_CreatedBy".answer IS NULL))) THEN "H_CreatedBy".answer ELSE NULL::text END ELSE NULL::text END = ANY ('{49,48,50}'::text[]))
                                                                                 ->  Merge Left Join  (cost=94870.63..95039.03 rows=184 width=19) (actual time=14.487..21.046 rows=160 loops=1)
                                                                                       Merge Cond: (form_instances.id = "H_ClaimedBy".form_instance_id)
                                                                                       ->  Sort  (cost=1084.07..1084.53 rows=184 width=13) (actual time=0.830..0.996 rows=160 loops=1)
                                                                                             Sort Key: form_instances.id
                                                                                             Sort Method:  quicksort  Memory: 23kB
                                                                                             ->  Bitmap Heap Scan on form_instances  (cost=755.66..1077.14 rows=184 width=13) (actual time=0.497..0.678 rows=160 loops=1)
                                                                                                   Recheck Cond: (id = ANY ('{5124,5126,5126,6296,6296,6583,6583,6746,6746,7674,7674,7676,7676,7686,7686,7728,7728,8078,807
8,8080,8080,8082,8082,8083,8083,8209,8209,8409,8409,10714,10714,10719,10719,10720,10720,10721,10721,10723,10723,14202,14203,14934,14936,14937,14938,14939,14940,14941,14942,14944,14945,14946,14947,14949,14950,14952
,14953,17959,17965,19133,19643,19648,20702,20702,20705,20705,22698,22699,22705,22707,22708,22709,22710,23042,23043,23045,23047,23048,23049,23050,23052,23053,23054,23055,23056,25343,25343,25344,25344,25345,25346,25
347,25348,25348,25350,25355,25356,25358,25359,25360,25361,25362,28910,28911,28912,28914,28915,28917,28918,28920,28921,28922,28924,28925,28927,28929,28932,28933,28934,28935,28936,28937,28939,28940,28941,28942,28944
,28945,28946,30587,30588,30589,30590,30591,30592,30593,30594,30595,30596,30597,30598,30599,30600,30601,30602,30603,30604,30605,30606,30607,30608,32439,32440,32441,32442,32443,32444,32445,32446,32447,32448,32449,32
450,32451,32452,32453,32454,32455,32456,32457,32458,33479,33480,33481,33482,33483,33484,33485,33486,33487,33488,33489,33490,33491}'::integer[]))
                                                                                                   ->  Bitmap Index Scan on form_instances_pkey  (cost=0.00..755.61 rows=184 width=0) (actual time=0.484..0.484 rows=184 loops=1)
                                                                                                         Index Cond: (id = ANY ('{5124,5126,5126,6296,6296,6583,6583,6746,6746,7674,7674,7676,7676,7686,7686,7728,7728,8078
,8078,8080,8080,8082,8082,8083,8083,8209,8209,8409,8409,10714,10714,10719,10719,10720,10720,10721,10721,10723,10723,14202,14203,14934,14936,14937,14938,14939,14940,14941,14942,14944,14945,14946,14947,14949,14950,1
4952,14953,17959,17965,19133,19643,19648,20702,20702,20705,20705,22698,22699,22705,22707,22708,22709,22710,23042,23043,23045,23047,23048,23049,23050,23052,23053,23054,23055,23056,25343,25343,25344,25344,25345,2534
6,25347,25348,25348,25350,25355,25356,25358,25359,25360,25361,25362,28910,28911,28912,28914,28915,28917,28918,28920,28921,28922,28924,28925,28927,28929,28932,28933,28934,28935,28936,28937,28939,28940,28941,28942,2
8944,28945,28946,30587,30588,30589,30590,30591,30592,30593,30594,30595,30596,30597,30598,30599,30600,30601,30602,30603,30604,30605,30606,30607,30608,32439,32440,32441,32442,32443,32444,32445,32446,32447,32448,3244
9,32450,32451,32452,32453,32454,32455,32456,32457,32458,33479,33480,33481,33482,33483,33484,33485,33486,33487,33488,33489,33490,33491}'::integer[]))
                                                                                       ->  Materialize  (cost=93786.56..94200.93 rows=33149 width=10) (actual time=13.586..17.835 rows=2019 loops=1)
                                                                                             ->  Sort  (cost=93786.56..93869.44 rows=33149 width=10) (actual time=13.582..14.950 rows=2019 loops=1)
                                                                                                   Sort Key: "H_ClaimedBy".form_instance_id
                                                                                                   Sort Method:  quicksort  Memory: 147kB
                                                                                                   ->  Bitmap Heap Scan on field_instances "H_ClaimedBy"  (cost=1124.76..90786.62 rows=33149 width=10) (actual time=1.173..11.483 rows=2123 loops=1)
                                                                                                         Recheck Cond: ((field_id)::text = 'H_ClaimedBy'::text)
                                                                                                         ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1116.47 rows=33149 width=0) (actual time=0.778..0.778 rows=2123 loops=1)
                                                                                                               Index Cond: ((field_id)::text = 'H_ClaimedBy'::text)
                                                                                 ->  Materialize  (cost=93786.56..94200.93 rows=33149 width=10) (actual time=980.920..1062.186 rows=33310 loops=1)
                                                                                       ->  Sort  (cost=93786.56..93869.44 rows=33149 width=10) (actual time=980.915..1014.740 rows=33310 loops=1)
                                                                                             Sort Key: "H_CreatedBy".form_instance_id
                                                                                             Sort Method:  external sort  Disk: 672kB
                                                                                             ->  Bitmap Heap Scan on field_instances "H_CreatedBy"  (cost=1124.76..90786.62 rows=33149 width=10) (actual time=171.613..908.697 rows=34190 loops=1)
                                                                                                   Recheck Cond: ((field_id)::text = 'H_CreatedBy'::text)
                                                                                                   ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1116.47 rows=33149 width=0) (actual time=167.917..167.917 rows=34190 loops=1)
                                                                                                         Index Cond: ((field_id)::text = 'H_CreatedBy'::text)
                                                                           ->  Bitmap Heap Scan on field_instances "Book_EstimatedDueDate"  (cost=1215.42..1259.32 rows=11 width=10) (actual time=190.096..190.114 rows=1 loops=133)
                                                                                 Recheck Cond: (("Book_EstimatedDueDate".form_instance_id = form_instances.id) AND (("Book_EstimatedDueDate".field_id)::text = 'Book_EstimatedDueDate'::text))
                                                                                 ->  BitmapAnd  (cost=1215.42..1215.42 rows=11 width=0) (actual time=189.913..189.913 rows=0 loops=133)
                                                                                       ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..115.53 rows=4631 width=0) (actual time=22.817..22.817 rows=408 loops=133)
                                                                                             Index Cond: ("Book_EstimatedDueDate".form_instance_id = form_instances.id)
                                                                                       ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1091.34 rows=33149 width=0) (actual time=166.910..166.910 rows=34190 loops=133)
                                                                                             Index Cond: (("Book_EstimatedDueDate".field_id)::text = 'Book_EstimatedDueDate'::text)
                                                                     ->  Bitmap Heap Scan on field_instances "Revised_EstimatedDueDate"  (cost=1215.42..1259.32 rows=11 width=10) (actual time=0.253..0.253 rows=0 loops=133)
                                                                           Recheck Cond: (("Revised_EstimatedDueDate".form_instance_id = form_instances.id) AND (("Revised_EstimatedDueDate".field_id)::text = 'Revised_EstimatedDueDate'::text))
                                                                           ->  BitmapAnd  (cost=1215.42..1215.42 rows=11 width=0) (actual time=0.250..0.250 rows=0 loops=133)
                                                                                 ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..115.53 rows=4631 width=0) (actual time=0.077..0.077 rows=408 loops=133)
                                                                                       Index Cond: ("Revised_EstimatedDueDate".form_instance_id = form_instances.id)
                                                                                 ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1091.34 rows=33149 width=0) (actual time=0.170..0.170 rows=0 loops=133)
                                                                                       Index Cond: (("Revised_EstimatedDueDate".field_id)::text = 'Revised_EstimatedDueDate'::text)
                                                               ->  Bitmap Heap Scan on field_instances "H_Ccode"  (cost=1215.42..1259.32 rows=11 width=10) (actual time=166.666..166.685 rows=1 loops=133)
                                                                     Recheck Cond: (("H_Ccode".form_instance_id = form_instances.id) AND (("H_Ccode".field_id)::text = 'H_Ccode'::text))
                                                                     ->  BitmapAnd  (cost=1215.42..1215.42 rows=11 width=0) (actual time=166.644..166.644 rows=0 loops=133)
                                                                           ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..115.53 rows=4631 width=0) (actual time=0.061..0.061 rows=408 loops=133)
                                                                                 Index Cond: ("H_Ccode".form_instance_id = form_instances.id)
                                                                           ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1091.34 rows=33149 width=0) (actual time=166.395..166.395 rows=34190 loops=133)
                                                                                 Index Cond: (("H_Ccode".field_id)::text = 'H_Ccode'::text)
                                                         ->  Bitmap Heap Scan on field_instances "H_ReviewedBy"  (cost=1215.42..1259.32 rows=11 width=10) (actual time=5.254..5.254 rows=0 loops=133)
                                                               Recheck Cond: (("H_ReviewedBy".form_instance_id = form_instances.id) AND (("H_ReviewedBy".field_id)::text = 'H_ReviewedBy'::text))
                                                               ->  BitmapAnd  (cost=1215.42..1215.42 rows=11 width=0) (actual time=5.251..5.251 rows=0 loops=133)
                                                                     ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..115.53 rows=4631 width=0) (actual time=0.078..0.078 rows=408 loops=133)
                                                                           Index Cond: ("H_ReviewedBy".form_instance_id = form_instances.id)
                                                                     ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1091.34 rows=33149 width=0) (actual time=5.041..5.041 rows=16321 loops=133)
                                                                           Index Cond: (("H_ReviewedBy".field_id)::text = 'H_ReviewedBy'::text)
                                                   ->  Bitmap Heap Scan on field_instances "H_Source"  (cost=1215.42..1259.32 rows=11 width=10) (actual time=174.566..175.110 rows=1 loops=133)
                                                         Recheck Cond: (("H_Source".form_instance_id = form_instances.id) AND (("H_Source".field_id)::text = 'H_Source'::text))
                                                         ->  BitmapAnd  (cost=1215.42..1215.42 rows=11 width=0) (actual time=174.548..174.548 rows=0 loops=133)
                                                               ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..115.53 rows=4631 width=0) (actual time=0.065..0.065 rows=408 loops=133)
                                                                     Index Cond: ("H_Source".form_instance_id = form_instances.id)
                                                               ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1091.34 rows=33149 width=0) (actual time=174.301..174.301 rows=34190 loops=133)
                                                                     Index Cond: (("H_Source".field_id)::text = 'H_Source'::text)
                                             ->  Bitmap Heap Scan on field_instances "Dem_MomAge"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=168.603..168.619 rows=1 loops=133)
                                                   Recheck Cond: (("Dem_MomAge".form_instance_id = form_instances.id) AND (("Dem_MomAge".field_id)::text = 'Dem_MomAge'::text))
                                                   ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=168.497..168.497 rows=0 loops=133)
                                                         ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.076..0.076 rows=408 loops=133)
                                                               Index Cond: ("Dem_MomAge".form_instance_id = form_instances.id)
                                                         ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=168.241..168.241 rows=34190 loops=133)
                                                               Index Cond: (("Dem_MomAge".field_id)::text = 'Dem_MomAge'::text)
                                       ->  Bitmap Heap Scan on field_instances "Book_BookingDate"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=167.666..167.684 rows=1 loops=133)
                                             Recheck Cond: (("Book_BookingDate".form_instance_id = form_instances.id) AND (("Book_BookingDate".field_id)::text = 'Book_BookingDate'::text))
                                             ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=167.646..167.646 rows=0 loops=133)
                                                   ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.076..0.076 rows=408 loops=133)
                                                         Index Cond: ("Book_BookingDate".form_instance_id = form_instances.id)
                                                   ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=167.385..167.385 rows=34190 loops=133)
                                                         Index Cond: (("Book_BookingDate".field_id)::text = 'Book_BookingDate'::text)
                                 ->  Bitmap Heap Scan on field_instances "H_Form"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=166.812..166.831 rows=1 loops=133)
                                       Recheck Cond: (("H_Form".form_instance_id = form_instances.id) AND (("H_Form".field_id)::text = 'H_Form'::text))
                                       ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=166.793..166.793 rows=0 loops=133)
                                             ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.077..0.077 rows=408 loops=133)
                                                   Index Cond: ("H_Form".form_instance_id = form_instances.id)
                                             ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=166.533..166.533 rows=34190 loops=133)
                                                   Index Cond: (("H_Form".field_id)::text = 'H_Form'::text)
                           ->  Bitmap Heap Scan on field_instances "Book_ConsentHashCode"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=184.996..185.013 rows=1 loops=133)
                                 Recheck Cond: (("Book_ConsentHashCode".form_instance_id = form_instances.id) AND (("Book_ConsentHashCode".field_id)::text = 'Book_ConsentHashCode'::text))
                                 ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=184.975..184.975 rows=0 loops=133)
                                       ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.077..0.077 rows=408 loops=133)
                                             Index Cond: ("Book_ConsentHashCode".form_instance_id = form_instances.id)
                                       ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=184.713..184.713 rows=34190 loops=133)
                                             Index Cond: (("Book_ConsentHashCode".field_id)::text = 'Book_ConsentHashCode'::text)
                     ->  Bitmap Heap Scan on field_instances "Book_MonthConsentSent"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=189.458..189.627 rows=1 loops=133)
                           Recheck Cond: (("Book_MonthConsentSent".form_instance_id = form_instances.id) AND (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text))
                           ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=189.432..189.432 rows=0 loops=133)
                                 ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.076..0.076 rows=408 loops=133)
                                       Index Cond: ("Book_MonthConsentSent".form_instance_id = form_instances.id)
                                 ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=189.168..189.168 rows=34190 loops=133)
                                       Index Cond: (("Book_MonthConsentSent".field_id)::text = 'Book_MonthConsentSent'::text)
               ->  Bitmap Heap Scan on field_instances "Book_ConsentSigned"  (cost=1239.71..1283.61 rows=11 width=10) (actual time=187.452..187.476 rows=1 loops=133)
                     Recheck Cond: (("Book_ConsentSigned".form_instance_id = form_instances.id) AND (("Book_ConsentSigned".field_id)::text = 'Book_ConsentSigned'::text))
                     ->  BitmapAnd  (cost=1239.71..1239.71 rows=11 width=0) (actual time=187.432..187.432 rows=0 loops=133)
                           ->  Bitmap Index Scan on index_field_instances_on_form_instance_id  (cost=0.00..117.36 rows=4631 width=0) (actual time=0.078..0.078 rows=408 loops=133)
                                 Index Cond: ("Book_ConsentSigned".form_instance_id = form_instances.id)
                           ->  Bitmap Index Scan on field_instances_field_id_idx  (cost=0.00..1113.81 rows=33149 width=0) (actual time=187.170..187.170 rows=34190 loops=133)
                                 Index Cond: (("Book_ConsentSigned".field_id)::text = 'Book_ConsentSigned'::text)
 Total runtime: 214289.895 ms

Well, I did the VACUUM ANALYZE and it suggesting increasing max_fsm_pages which I did and then re-ran VACUUM ANALYZE and sitll no change it the time it takes to do the query.

Any thoughts?

I've done a line by line comparison of the postgres config files between the development server and the production server. See below. I can't imagine that any of these would make a difference to not allowing the production server to do an index scan.

If anything the settings on the production server seem more favorable to increased performance.

On top of this, the good folks at Linode have temporarily increased my RAM to 4Gig for testing purposes and that isn't making the difference.

Thoughts?

----

- = development server (FAST)
+ = production server (SLOW)


- client_encoding   UTF8   Sets the client's character set encoding.
+ client_encoding   SQL_ASCII   Sets the client's character set encoding.


- effective_cache_size   128MB   Sets the planner's assumption about the size of the disk cache.
+ effective_cache_size   712MB   Sets the planner's assumption about the size of the disk cache.


- integer_datetimes   off   Datetimes are integer based.
+ integer_datetimes   on   Datetimes are integer based.


- lc_collate   en_US.UTF-8   Shows the collation order locale.
- lc_ctype   en_US.UTF-8   Shows the character classification and case conversion locale.
- lc_messages   en_US.UTF-8   Sets the language in which messages are displayed.
- lc_monetary   en_US.UTF-8   Sets the locale for formatting monetary amounts.
- lc_numeric   en_US.UTF-8   Sets the locale for formatting numbers.
- lc_time   en_US.UTF-8   Sets the locale for formatting date and time values.
+ lc_collate   C   Shows the collation order locale.
+ lc_ctype   C   Shows the character classification and case conversion locale.
+ lc_messages   C   Sets the language in which messages are displayed.
+ lc_monetary   C   Sets the locale for formatting monetary amounts.
+ lc_numeric   C   Sets the locale for formatting numbers.
+ lc_time   C   Sets the locale for formatting date and time values.


- log_timezone   US/Eastern   Sets the time zone to use in log messages.
+ log_timezone   localtime   Sets the time zone to use in log messages.


- max_connections   100   Sets the maximum number of concurrent connections.
+ max_connections   25   Sets the maximum number of concurrent connections.


- max_fsm_pages   153600   Sets the maximum number of disk pages for which free space is tracked.
+ max_fsm_pages   320672   Sets the maximum number of disk pages for which free space is tracked.


- server_encoding   UTF8   Sets the server (database) character set encoding.
+ server_encoding   SQL_ASCII   Sets the server (database) character set encoding.


- shared_buffers   24MB   Sets the number of shared memory buffers used by the server.
+ shared_buffers   120MB   Sets the number of shared memory buffers used by the server.


- TimeZone   US/Eastern   Sets the time zone for displaying and interpreting time stamps.
+ TimeZone   localtime   Sets the time zone for displaying and interpreting time stamps.


- wal_sync_method   fsync   Selects the method used for forcing WAL updates to disk.
+ wal_sync_method   fdatasync   Selects the method used for forcing WAL updates to disk.

I really think you need to be more scientific about this. Are you running the same Postgres release in production and development? You should test using an identical configuration - I definitely don't think you can fairly compare when changing those cache and buffer sizes (regardless of what your intuition tells you about the effect of those changes).

Postgres releases are the same: 8.3.5.

Actually they cache sizes started out being exactly the same. The difference you see above is fixes to try and make things better. But even so, after I posted this, I went and reset the cache sizes back to being the same, and still no go.

Here's the weird thing. I went and set up a 1G slice over at slicehost.com again using ubuntu 8.04LTS, and then using the exact same install script (deprec and capistrano) that I used to install my app stack which includes postgres, and after importing my 13M database over there it works just as fast as my PowerBook development machine, and it calls the Index Scan rather than the Bitmap Heap Scan that happens on the linode box.

So I'm kind of at a loss as to why it's failing on linode! I've even reindexed the entire database.

Have you tried use UTF-8 encoding on production server?

Are you running 64 bit Ubuntu on both slicehost and linode? Of course, that wouldn't help explain the difference between your powerbook vs linode. Please keep us updated. Perhaps it would be worth asking in the postgresql irc channel or mailing list if they have any intuition into what could be causing the different query plans on slicehost vs linode.

I don't think it explains your performance problem, but you should be using exactly the same config files on both dev and test, except, maybe, for the effective_cache_size and wal_sync_method (the best option may differ between MacOS and Linux).

A few things, first, the number of records is only part of the story. pgAdmin should be able to tell you the size of both your tables and your indexes. You also need to run vmstat to see how much memory is available for caching.

Also, you should read a little about postgres tuning. Postgres relies largely on the OS to handle caching indexes and data in RAM. The effective_cache_size tells Postgres how much RAM it can expect the OS to have available for caching, so the query planner can make an informed guess about whether an index page will be in RAM or not.

One thing that's pretty clear, postgres is choosing different execution plans on the different machines. This could be because of the information about ram you've given it. It could be that the dev server has accumulated better statistics than the instance on the Linode, etc.