Skip site navigation (1) Skip section navigation (2)

Weird 8.2.4 performance

From: Kurt Overberg <kurt(at)hotdogrecords(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: Weird 8.2.4 performance
Date: 2007-06-06 23:27:27
Message-ID: 371D1936-E96B-4865-AEEF-C82AC41C2982@hotdogrecords.com (view raw or flat)
Thread:
Lists: pgsql-performance
Gang,

I'm running a mid-size production 8.0 environment.  I'd really like  
to upgrade to 8.2, so I've been doing some testing to make sure my  
app works well with 8.2, and I ran across this weirdness.  I set up  
and configured 8.2 in the standard way, MacOSX Tiger, current  
patches, download src, configure, make, make install, initdb, start  
the db, create a few users, dump out my 8.0 DB (its about 13 GB raw  
text), load it into 8.2.4, vacuum analyze.

This is a simple query the shows some weird behavior.  I have two  
tables, task and taskinstance.  A taskinstance is tied to a campaign  
through the task table (taskinstance points at task which points at  
campaign).  Very simple.  To select all the taskinstances associated  
with a certain campaign, I use this query:

select id from taskinstance where taskid in (select id from task  
where campaignid = 75);

Now, I know this could (and should) be rewritten to not use the WHERE  
x IN () style, but this is actually a sub-query to a larger query-  
The bigger query was acting slow, and I've narrowed it down to this  
snippet.  Task has a total of ~2000 rows, in which 11 of them belong  
to campaign 75.  TaskInstance has around 650,000 rows.

This query runs great on production under 8.0 (27ms), but under 8.2.4  
(on my mac) I'm seeing times in excess of 50,000ms.  Note that on  
8.2.4, if I run the query again, it gets successively faster  
(50,000ms->6000ms->27ms).  Is this normal?  If I change the  
campaignid from 75 to another number, it jumps back to 50,000ms,  
which leads me to believe that postgresql is somehow caching the  
results of the query and not figuring out a better way to run the query.

Indexes:
Taskinstance has "taskid_taskinstance_key" btree (taskid)
Task has "Task_campaignId_key" btree (campaignid)

Explain Outputs:

-- 8.2


explain analyze select id from taskinstance where taskid in (select  
id from task where campaignid = 75);
                                                                   
QUERY PLAN
------------------------------------------------------------------------ 
---------------------------------------------------------------------
  Nested Loop  (cost=37.65..15068.50 rows=2301 width=4) (actual  
time=99.986..50905.512 rows=881 loops=1)
    ->  HashAggregate  (cost=16.94..17.01 rows=7 width=4) (actual  
time=0.213..0.236 rows=9 loops=1)
          ->  Index Scan using "Task_campaignId_key" on task   
(cost=0.00..16.93 rows=7 width=4) (actual time=0.091..0.197 rows=9  
loops=1)
                Index Cond: (campaignid = 76)
    ->  Bitmap Heap Scan on taskinstance  (cost=20.71..2143.26  
rows=556 width=8) (actual time=421.423..5655.745 rows=98 loops=9)
          Recheck Cond: (taskinstance.taskid = task.id)
          ->  Bitmap Index Scan on taskid_taskinstance_key   
(cost=0.00..20.57 rows=556 width=0) (actual time=54.709..54.709  
rows=196 loops=9)
                Index Cond: (taskinstance.taskid = task.id)
  Total runtime: 50907.264 ms
(9 rows)



-- 8.0

  explain analyze select id from taskinstance where taskid in (select  
id from task where campaignid = 75);
                                                                       
QUERY PLAN
------------------------------------------------------------------------ 
-------------------------------------------------------------------
  Nested Loop  (cost=13.70..17288.28 rows=2640 width=4) (actual  
time=0.188..21.496 rows=1599 loops=1)
    ->  HashAggregate  (cost=13.70..13.70 rows=8 width=4) (actual  
time=0.153..0.217 rows=11 loops=1)
          ->  Index Scan using "Task_campaignId_key" on task   
(cost=0.00..13.68 rows=8 width=4) (actual time=0.026..0.082 rows=11  
loops=1)
                Index Cond: (campaignid = 75)
    ->  Index Scan using taskid_taskinstance_key on taskinstance   
(cost=0.00..2152.28 rows=563 width=8) (actual time=0.012..0.832  
rows=145 loops=11)
          Index Cond: (taskinstance.taskid = "outer".id)
  Total runtime: 27.406 ms
(7 rows)

The weird thing is that on 8.2, I don't see any sequential scans  
taking place, it seems to be properly using the indexes.

If anyone has any ideas, I'd appreciate your thoughts.  This one has  
got me boggled.  If I can provide any more information that would  
helpful, please let me know.

Thanks for any light you could shed on my situation!

/kurt


Responses

pgsql-performance by date

Next:From: Mark KirkwoodDate: 2007-06-07 00:01:51
Subject: Re: Weird 8.2.4 performance
Previous:From: James MansionDate: 2007-06-06 22:23:13
Subject: Re: LIKE search and performance

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group