large postgres database
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
16 Replies
* 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.
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.
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
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.
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.
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?
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…
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
Any thoughts?
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.
@zippy:
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.
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).
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.
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 effectivecachesize 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.
I'm happy to create a new thread about PostgreSQL on Linode if here isn't the correct place.
Thanks for any information.
Database tuning is simply an inexact science -- this is an old thread, too, and the OP may have resolved his issue by now.