Large table performance and vacuum - Mailing list pgsql-general

Hi,

I'm having a performance problem with a large database table
we use with postgres 7.3.4.  The table is:

db=> \d log
       Table "public.log"
 Column  |   Type   | Modifiers
---------+----------+-----------
 hid     | integer  |
 tid     | integer  |
 aid     | integer  |
 id      | smallint |
 sid     | smallint |
 cid     | smallint |
Indexes: aid_cid_hid_idx btree (aid, cid, hid) WHERE (cid = 32),
         hid_idx btree (hid),
         tid_idx btree (tid)

The table consists of batches of rows with the same hid, and
hid comes from a sequence, so lower hid entries are older.
About 25 million rows are inserted per day, which
corresponds to about 250,000 unique hids.

In order to keep the table manageable (for things like
pg_dump and vacuum) we're copying out older log entries
(starting with the first hid in the log table) and deleting
them.

The problem is the query "SELECT * FROM log ORDER BY hid
LIMIT 1;", which both EXPLAIN and EXPLAIN ANALYZE show as
Limit / Index Scan on hid_idx.  This was very fast before we
started deleting out old log entries the table, but has
started taking an extremely long time, about 341 seconds.

However "SELECT * FROM log ORDER BY hid DESC LIMIT 1;",
which EXPLAIN shows as Limit / Index Scan Backward on
hid_idx is still extremely fast, < 1 ms.

Below I've attached the latest VACUUM ANALYZE VERBOSE output
and EXPLAIN ANALYZE results for the 2 queries mentioned
above run immediately after the vacuum.  For the heck of it
there's also a backtrace from the postgres backend that was
running the "EXPLAIN ANALYZE SELECT * FROM log ORDER BY hid
LIMIT 1;" query.

Any ideas what the problem is?  I'm guessing it has to do
with all of the unused tuples in the log table and will go
away if I do a VACUUM FULL.  Unfortunately that's not
generally an option; the log table is used 24/7 and locking
it for the several hours this would take would require
downtime on our system.

Thanks,
Gavin Scott
gavin@ipalsoftware.com

VACUUM ANALYZE VERBOSE log OUTPUT

INFO:  --Relation public.log--
INFO:  Index hid_idx: Pages 696549; Tuples 180783386: Deleted 11184600.
        CPU 41.45s/141.71u sec elapsed 2248.23 sec.
INFO:  Index tid_idx: Pages 608998; Tuples 180866770: Deleted 11184600.
        CPU 36.58s/143.80u sec elapsed 3405.02 sec.
INFO:  Index aid_cid_hid_idx: Pages 155544; Tuples 22308137: Deleted 1365950.
        CPU 10.29s/20.38u sec elapsed 1409.63 sec.
INFO:  Removed 11184600 tuples in 72368 pages.
        CPU 5.11s/5.11u sec elapsed 240.97 sec.
INFO:  Index hid_idx: Pages 697061; Tuples 169790852: Deleted 11184513.
        CPU 43.17s/139.36u sec elapsed 2213.30 sec.
INFO:  Index tid_idx: Pages 609744; Tuples 169942979: Deleted 11184513.
        CPU 35.78s/138.05u sec elapsed 3357.42 sec.
INFO:  Index aid_cid_hid_idx: Pages 155775; Tuples 20945181: Deleted 1399976.
        CPU 10.22s/19.64u sec elapsed 1408.34 sec.
INFO:  Removed 11184513 tuples in 71240 pages.
        CPU 5.11s/5.38u sec elapsed 147.56 sec.
INFO:  Index hid_idx: Pages 698247; Tuples 163654063: Deleted 6521246.
        CPU 41.11s/118.39u sec elapsed 2194.98 sec.
INFO:  Index tid_idx: Pages 610817; Tuples 163795162: Deleted 6521246.
        CPU 35.28s/117.13u sec elapsed 3170.12 sec.
INFO:  Index aid_cid_hid_idx: Pages 156031; Tuples 20172239: Deleted 820413.
        CPU 10.57s/17.95u sec elapsed 1438.76 sec.
INFO:  Removed 6521246 tuples in 42430 pages.
        CPU 3.23s/3.51u sec elapsed 162.80 sec.
INFO:  Pages 1342806: Changed 242787, Empty 0; Tup 163016168: Vac 28890359, Keep 0, UnUsed 17697429.
        Total CPU 326.60s/908.01u sec elapsed 22642.23 sec.
INFO:  Analyzing public.log

db=> EXPLAIN ANALYZE SELECT * FROM log ORDER BY hid DESC LIMIT 1;
                                                                  QUERY PLAN
                                     

----------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..0.99 rows=1 width=18) (actual time=0.05..0.06 rows=1 loops=1)
   ->  Index Scan Backward using hid_idx on log  (cost=0.00..161101169.41 rows=163016160 width=18) (actual
time=0.05..0.05rows=2 loops=1) 
 Total runtime: 0.11 msec
(3 rows)

db=> EXPLAIN ANALYZE SELECT * FROM log ORDER BY hid LIMIT 1;
                                                                  QUERY PLAN
                                     

-----------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..0.99 rows=1 width=18) (actual time=341820.90..341820.92 rows=1 loops=1)
   ->  Index Scan using hid_idx on log  (cost=0.00..161101169.41 rows=163016160 width=18) (actual
time=341820.90..341820.91rows=2 loops=1) 
 Total runtime: 341820.98 msec
(3 rows)

BACKTRACE OF POSTGRES PROCESS RUNNING
"EXPLAIN ANALYZE SELECT * FROM log ORDER BY hid LIMIT 1;"

(gdb) where
#0  0x40314714 in read () from /lib/libc.so.6
#1  0x00000300 in ?? ()
#2  0x08126ab9 in mdread ()
#3  0x081275f7 in smgrread ()
#4  0x0811cd05 in ReadBufferInternal ()
#5  0x0811cae5 in ReadBuffer ()
#6  0x080802b1 in _bt_getbuf ()
#7  0x08082c8b in _bt_step ()
#8  0x080830ae in _bt_endpoint ()
#9  0x08082b6b in _bt_first ()
#10 0x080808d1 in btgettuple ()
#11 0x08178ea9 in FunctionCall2 ()
#12 0x0807cd53 in index_getnext ()
#13 0x080dccdf in IndexNext ()
#14 0x080d8a1a in ExecScan ()
p#15 0x080dcd68 in ExecIndexScan ()
#16 0x080d663d in ExecProcNode ()
#17 0x080dfe25 in ExecLimit ()
#18 0x080d66f9 in ExecProcNode ()
#19 0x080d5454 in ExecutePlan ()
#20 0x080d4a89 in ExecutorRun ()
#21 0x0812a4ab in ProcessQuery ()
#22 0x0812896b in pg_exec_query_string ()
#23 0x08129a83 in PostgresMain ()
#24 0x0810fd54 in DoBackend ()
#25 0x0810f63d in BackendStartup ()
#26 0x0810e6d0 in ServerLoop ()
#27 0x0810e109 in PostmasterMain ()
#28 0x080e96ed in main ()
#29 0x4025c1c4 in __libc_start_main () from /lib/libc.so.6