Обсуждение: performance decrease after reboot
I tuned a query last week to obtain acceptable performance.
Here is my recorded explain analyze results:
-----
LOG: duration: 826.505 ms statement: explain analyze
SELECT
c.id AS contact_id,
sr.id AS sales_rep_id,
LTRIM(RTRIM(sr.firstname || ' ' || sr.lastname)) AS sales_rep_name,
p.id AS partner_id,
p.company AS partner_company,
coalesce(LTRIM(RTRIM(c.company)), LTRIM(RTRIM(c.firstname || ' ' || c.lastname)))
AS contact_company,
LTRIM(RTRIM(c.city || ' ' || c.state || ' ' || c.postalcode || ' ' || c.country))
AS contact_location,
c.phone AS contact_phone,
c.email AS contact_email,
co.name AS contact_country,
TO_CHAR(c.request_status_last_modified, 'mm/dd/yy hh12:mi pm')
AS request_status_last_modified,
TO_CHAR(c.request_status_last_modified, 'yyyymmddhh24miss')
AS rqst_stat_last_mdfd_sortable,
c.token_id
FROM
sales_reps sr
JOIN partners p ON (sr.id = p.sales_rep_id)
JOIN contacts c ON (p.id = c.partner_id)
JOIN countries co ON (LOWER(c.country) = LOWER(co.code))
JOIN partner_classification pc ON (p.classification_id = pc.id AND pc.classification != 'Sales Rep')
WHERE
c.lead_deleted IS NULL
AND EXISTS
(
SELECT
lr.id
FROM
lead_requests lr,
lead_request_status lrs
WHERE
c.id = lr.contact_id AND
lr.status_id = lrs.id AND
lrs.is_closed = 0
)
ORDER BY
contact_company, contact_id
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Sort (cost=18266.77..18266.80 rows=11 width=219) (actual time=795.502..795.763 rows=246 loops=1)
Sort Key: COALESCE(ltrim(rtrim((c.company)::text)), ltrim(rtrim((((c.firstname)::text || ' '::text) ||
(c.lastname)::text)))),c.id
-> Hash Join (cost=18258.48..18266.58 rows=11 width=219) (actual time=747.551..788.095 rows=246 loops=1)
Hash Cond: (lower(("outer".code)::text) = lower(("inner".country)::text))
-> Seq Scan on countries co (cost=0.00..4.42 rows=242 width=19) (actual time=0.040..2.128 rows=242 loops=1)
-> Hash (cost=18258.45..18258.45 rows=9 width=206) (actual time=746.653..746.653 rows=0 loops=1)
-> Merge Join (cost=18258.12..18258.45 rows=9 width=206) (actual time=729.412..743.691 rows=246
loops=1)
Merge Cond: ("outer".sales_rep_id = "inner".id)
-> Sort (cost=18255.70..18255.73 rows=9 width=185) (actual time=727.948..728.274 rows=249
loops=1)
Sort Key: p.sales_rep_id
-> Merge Join (cost=18255.39..18255.56 rows=9 width=185) (actual time=712.747..723.095
rows=249loops=1)
Merge Cond: ("outer".id = "inner".classification_id)
-> Sort (cost=1.05..1.05 rows=2 width=10) (actual time=0.192..0.195 rows=2 loops=1)
Sort Key: pc.id
-> Seq Scan on partner_classification pc (cost=0.00..1.04 rows=2 width=10)
(actualtime=0.100..0.142 rows=2 loops=1)
Filter: ((classification)::text <> 'Sales Rep'::text)
-> Sort (cost=18254.35..18254.38 rows=13 width=195) (actual time=712.401..712.675
rows=250loops=1)
Sort Key: p.classification_id
-> Merge Join (cost=0.00..18254.11 rows=13 width=195) (actual
time=47.844..705.517rows=448 loops=1)
Merge Cond: ("outer".id = "inner".partner_id)
-> Index Scan using partners_pkey on partners p (cost=0.00..30.80
rows=395width=53) (actual time=0.066..5.746 rows=395 loops=1)
-> Index Scan using contacts_partner_id_idx on contacts c
(cost=0.00..130358.50rows=93 width=152) (actual time=0.351..662.576 rows=452 loops=1)
Filter: ((lead_deleted IS NULL) AND (subplan))
SubPlan
-> Nested Loop (cost=0.00..6.76 rows=2 width=10) (actual
time=0.094..0.094rows=0 loops=5573)
Join Filter: ("outer".status_id = "inner".id)
-> Index Scan using lead_requests_contact_id_idx on
lead_requestslr (cost=0.00..4.23 rows=2 width=20) (actual time=0.068..0.069 rows=0 loops=5573)
Index Cond: ($0 = contact_id)
-> Seq Scan on lead_request_status lrs (cost=0.00..1.16
rows=8width=10) (actual time=0.030..0.094 rows=4 loops=519)
Filter: (is_closed = 0::numeric)
-> Sort (cost=2.42..2.52 rows=39 width=31) (actual time=1.334..1.665 rows=267 loops=1)
Sort Key: sr.id
-> Seq Scan on sales_reps sr (cost=0.00..1.39 rows=39 width=31) (actual time=0.064..0.533
rows=39loops=1)
Total runtime: 798.494 ms
(34 rows)
-----
I rebooted the database machine later that night.
Now, when I run the same query, I get the following
results:
-----
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Sort (cost=17415.32..17415.35 rows=11 width=219) (actual time=6880.583..6880.738 rows=246 loops=1)
Sort Key: COALESCE(ltrim(rtrim((c.company)::text)), ltrim(rtrim((((c.firstname)::text || ' '::text) ||
(c.lastname)::text)))),c.id
-> Merge Join (cost=17414.22..17415.13 rows=11 width=219) (actual time=6828.441..6871.894 rows=246 loops=1)
Merge Cond: ("outer".sales_rep_id = "inner".id)
-> Sort (cost=17411.80..17411.83 rows=11 width=198) (actual time=6825.227..6825.652 rows=249 loops=1)
Sort Key: p.sales_rep_id
-> Merge Join (cost=17411.42..17411.61 rows=11 width=198) (actual time=6805.894..6818.717 rows=249
loops=1)
Merge Cond: ("outer".id = "inner".classification_id)
-> Sort (cost=1.05..1.05 rows=2 width=10) (actual time=0.788..0.792 rows=2 loops=1)
Sort Key: pc.id
-> Seq Scan on partner_classification pc (cost=0.00..1.04 rows=2 width=10) (actual
time=0.094..0.554rows=2 loops=1)
Filter: ((classification)::text <> 'Sales Rep'::text)
-> Sort (cost=17410.38..17410.41 rows=15 width=208) (actual time=6804.649..6804.923 rows=250
loops=1)
Sort Key: p.classification_id
-> Merge Join (cost=4.42..17410.08 rows=15 width=208) (actual time=62.598..6795.704
rows=448loops=1)
Merge Cond: ("outer".partner_id = "inner".id)
-> Nested Loop (cost=4.42..130886.19 rows=113 width=165) (actual
time=8.807..6712.529rows=739 loops=1)
Join Filter: (lower(("outer".country)::text) = lower(("inner".code)::text))
-> Index Scan using contacts_partner_id_idx on contacts c
(cost=0.00..130206.59rows=93 width=152) (actual time=0.793..4082.343 rows=739 loops=1)
Filter: ((lead_deleted IS NULL) AND (subplan))
SubPlan
-> Nested Loop (cost=0.00..6.76 rows=2 width=10) (actual
time=0.084..0.084rows=0 loops=37077)
Join Filter: ("outer".status_id = "inner".id)
-> Index Scan using lead_requests_contact_id_idx on lead_requests
lr (cost=0.00..4.23 rows=2 width=20) (actual time=0.066..0.066 rows=0 loops=37077)
Index Cond: ($0 = contact_id)
-> Seq Scan on lead_request_status lrs (cost=0.00..1.16 rows=8
width=10)(actual time=0.031..0.140 rows=4 loops=1195)
Filter: (is_closed = 0::numeric)
-> Materialize (cost=4.42..6.84 rows=242 width=19) (actual time=0.003..0.347
rows=242loops=739)
-> Seq Scan on countries co (cost=0.00..4.42 rows=242 width=19) (actual
time=0.038..3.162rows=242 loops=1)
-> Index Scan using partners_pkey on partners p (cost=0.00..30.80 rows=395 width=53)
(actualtime=0.062..15.152 rows=787 loops=1)
-> Sort (cost=2.42..2.52 rows=39 width=31) (actual time=1.916..2.723 rows=267 loops=1)
Sort Key: sr.id
-> Seq Scan on sales_reps sr (cost=0.00..1.39 rows=39 width=31) (actual time=0.065..0.723 rows=39
loops=1)
Total runtime: 6886.307 ms
(34 rows)
-----
There is definitely a difference in the query plans.
I am guessing this difference in the performance decrease.
However, nothing was changed in the postgresql.conf file.
I may have run something in the psql explain analyze session
a week ago, but I can't figure out what I changed.
So, the bottom line is this:
What do I need to do to get back to the better performance?
Is it possible to determine what options may have changed from
the above query plan differences?
And, also,
What is the "Materialize" query plan item in the second
query plan, the slower plan?
If you need any additional configurations, please let me
know.
Thank you very much in advance for any pointers you can
provide.
JohnM
--
John Mendenhall
john@surfutopia.net
surf utopia
internet services
On Tue, 19 Jul 2005, John Mendenhall wrote: > I tuned a query last week to obtain acceptable performance. > Here is my recorded explain analyze results: > > LOG: duration: 826.505 ms statement: explain analyze > [cut for brevity] > > I rebooted the database machine later that night. > Now, when I run the same query, I get the following > results: > > LOG: duration: 6931.701 ms statement: explain analyze > [cut for brevity] I just ran my query again, no changes from yesterday and it is back to normal: LOG: duration: 795.839 ms statement: explain analyze What could have been the problem? The major differences in the query plan are as follows: (1) The one that runs faster uses a Hash Join at the very top of the query plan. It does a Hash Cond on the country and code fields. (2) The one that runs slower uses a Materialize with the subplan, with no Hash items. The Materialize does Seq Scan of the countries table, and above it, a Join Filter is run. (3) The partners_pkey index on the partners table is in a different place in the query. Does anyone know what would cause the query plan to be different like this, for the same server, same query? I run vacuum analyze every night. Is this perhaps the problem? What setting do I need to tweak to make sure the faster plan is always found? Thanks for any pointers in this dilemma. JohnM -- John Mendenhall john@surfutopia.net surf utopia internet services
pgsql performance gurus, I sent the following message earlier this week. I have continued attempting to find something on the net that would explain this strange change of query plans, but nothing seems to apply. Are there any thoughts, such as possibly tweaking the database somehow to see if I can get this to repeat consistently? Please let me know if any of you have any pointers as to the cause of the different query plans. Thank you very much in advance for any pointers you can provide. JohnM On Tue, 19 Jul 2005, John Mendenhall wrote: > I tuned a query last week to obtain acceptable performance. > Here is my recorded explain analyze results: > > LOG: duration: 826.505 ms statement: explain analyze > [cut for brevity] > > I rebooted the database machine later that night. > Now, when I run the same query, I get the following > results: > > LOG: duration: 6931.701 ms statement: explain analyze > [cut for brevity] I just ran my query again, no changes from yesterday and it is back to normal: LOG: duration: 795.839 ms statement: explain analyze What could have been the problem? The major differences in the query plan are as follows: (1) The one that runs faster uses a Hash Join at the very top of the query plan. It does a Hash Cond on the country and code fields. (2) The one that runs slower uses a Materialize with the subplan, with no Hash items. The Materialize does Seq Scan of the countries table, and above it, a Join Filter is run. (3) The partners_pkey index on the partners table is in a different place in the query. Does anyone know what would cause the query plan to be different like this, for the same server, same query? I run vacuum analyze every night. Is this perhaps the problem? What setting do I need to tweak to make sure the faster plan is always found? Thanks for any pointers in this dilemma. JohnM -- John Mendenhall john@surfutopia.net surf utopia internet services
It's likely that data is in filesystem (not database) cache the second time you run the query. See if the same thing happenswhen you stop and restart the postmaster (it likely wont), then do something like this to flush the filesystem cache(read a big file, can't give you a sample cmd because my Treo has no equal sign :-) then run the query again. - Luke -----Original Message----- From: John Mendenhall [mailto:john@surfutopia.net] Sent: Sat Jul 23 12:54:18 2005 To: pgsql-performance list Subject: [PERFORM] re: performance decrease after reboot pgsql performance gurus, I sent the following message earlier this week. I have continued attempting to find something on the net that would explain this strange change of query plans, but nothing seems to apply. Are there any thoughts, such as possibly tweaking the database somehow to see if I can get this to repeat consistently? Please let me know if any of you have any pointers as to the cause of the different query plans. Thank you very much in advance for any pointers you can provide. JohnM On Tue, 19 Jul 2005, John Mendenhall wrote: > I tuned a query last week to obtain acceptable performance. > Here is my recorded explain analyze results: > > LOG: duration: 826.505 ms statement: explain analyze > [cut for brevity] > > I rebooted the database machine later that night. > Now, when I run the same query, I get the following > results: > > LOG: duration: 6931.701 ms statement: explain analyze > [cut for brevity] I just ran my query again, no changes from yesterday and it is back to normal: LOG: duration: 795.839 ms statement: explain analyze What could have been the problem? The major differences in the query plan are as follows: (1) The one that runs faster uses a Hash Join at the very top of the query plan. It does a Hash Cond on the country and code fields. (2) The one that runs slower uses a Materialize with the subplan, with no Hash items. The Materialize does Seq Scan of the countries table, and above it, a Join Filter is run. (3) The partners_pkey index on the partners table is in a different place in the query. Does anyone know what would cause the query plan to be different like this, for the same server, same query? I run vacuum analyze every night. Is this perhaps the problem? What setting do I need to tweak to make sure the faster plan is always found? Thanks for any pointers in this dilemma. JohnM -- John Mendenhall john@surfutopia.net surf utopia internet services ---------------------------(end of broadcast)--------------------------- TIP 6: explain analyze is your friend