Обсуждение: Index used under 7.2 slows down query?

We're trying to track down a rather large performance difference between
7.2 and 7.1.  Statistics gathered show that one query takes a lot longer
under 7.2 than under 7.1.

7.2:

SELECT oid,* FROM job_queue
WHERE daemon_id IS NULL AND method_id = ?
AND status_id = ? AND startable_time <= now()
ORDER BY startable_time
FOR UPDATE
LIMIT ? OFFSET ? => {
    'count' => '20142',
    'avg' => ' 0.862',
    'time' => '17366.107' }

--that is, we ran this query 20,142 times, it averaged about 0.862
wallclock-seconds per invocation, for a total of 17,366
wallclock-seconds.  The timing is taken at the level of the Perl DBD::Pg
interface, starting the clock just before the API is called, and stopping
it immediately after it returns.  The intervening executable code is not
identical on the two systems, but this appears to be by far the query
most affected, so I'm inclined to think it is slowdown in the database.

7.1:

SELECT oid,* FROM job_queue
WHERE daemon_id IS NULL AND method_id = ?
AND status_id = ? AND startable_time <= now()
ORDER BY startable_time
FOR UPDATE
LIMIT ? OFFSET ? => {
    'count' => '14278',
    'avg' => ' 0.014',
    'time' => '200.584' }

--a big change in the average and total time.  Here's the query plans:

7.2:

Limit  (cost=1845.99..3691.98 rows=1 width=97)
  ->  Index Scan using ix_job_queue_1 on job_queue  (cost=0.00..76419.98 rows=41 width=97)


7.1:

Limit  (cost=1.44..1.44 rows=1 width=72)
  ->  Sort  (cost=1.44..1.44 rows=1 width=72)
        ->  Seq Scan on job_queue  (cost=0.00..1.43 rows=1 width=72)

On both schemas, the table has an index (btree, non-unique) on the
TIMESTAMP column "startable_time".  (That's the "ix_job_queue_1" in the
plan above.)  There is also an index (btree, unique) on the primary key,
a sequence number.  On the 7.2 schema, I added two more indexes, but
they are not on columns used in the WHERE clause.  The table is vacuumed
once an hour on 7.2, and once a day on 7.1.  (The slowdown predates the
change to the vacuum schedule.)

The table undergoes around 15,000-20,000 inserts per day, and the column
"startable_time" is usually within a few hours (future) of the current
time at the insert.


--
Jeff Boes                                      vox 616.226.9550 ext 24
Database Engineer                                     fax 616.349.9076
Nexcerpt, Inc.                                 http://www.nexcerpt.com
           ...Nexcerpt... Extend your Expertise

Jeff Boes <jboes@nexcerpt.com> writes:
> We're trying to track down a rather large performance difference between
> 7.2 and 7.1.  Statistics gathered show that one query takes a lot longer
> under 7.2 than under 7.1.

Could we see EXPLAIN ANALYZE output from 7.2?  Also, if you force
enable_indexscan OFF, what does EXPLAIN ANALYZE say then?

            regards, tom lane

On Tue, 2002-07-09 at 10:59, Tom Lane wrote:
> Jeff Boes <jboes@nexcerpt.com> writes:
> > We're trying to track down a rather large performance difference between
> > 7.2 and 7.1.  Statistics gathered show that one query takes a lot longer
> > under 7.2 than under 7.1.
>
> Could we see EXPLAIN ANALYZE output from 7.2?  Also, if you force
> enable_indexscan OFF, what does EXPLAIN ANALYZE say then?
>

Unfortunately, no.  I've whacked the indexes that were in use on the 7.2
schema, pursuing the idea that maybe without the indexes it would run
faster.  Certainly the EXPLAIN numbers point toward that.

What I think was happening: under 7.1, the table was too small (perhaps
at the time it was vacuumed) to "qualify" for index access.  Under 7.2,
perhaps because of more numerous vacuums to solve a similar problem, the
index was deemed "good enough".  However, since this table has about 1k
new rows per hour, all with similar values for the index, and likewise
1k deletes per hour, the index distribution is off almost immediately
after the vacuum!

I'm going to run this for a day without any indexes (except for the
primary key, which is a sequence number).  Then I may try it again with
indexes and a vacuum/analyze every 10-15 minutes.


--
Jeff Boes                                      vox 616.226.9550 ext 24
Database Engineer                                     fax 616.349.9076
Nexcerpt, Inc.                                 http://www.nexcerpt.com
           ...Nexcerpt... Extend your Expertise