On Mon, 03 Sep 2007 13:07:41 -0500
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote:

> >>> On Mon, Sep 3, 2007 at 11:15 AM, in message
> <20070903091558.0780b963@boffin.xmtservices.net> , Shawn
> <postgres@xmtservices.net> wrote:
> > On Sun, 02 Sep 2007 10:49:09 -0500 "Kevin Grittner"
> > <Kevin.Grittner@wicourts.gov> wrote:
> >
> >> >>> On Sat, Sep 1, 2007 at 12:29 PM, in message
> >> <20070901102947.0c0a50a3@boffin.xmtservices.net> , Shawn
> >> <postgres@xmtservices.net> wrote:
> >> > update shawns_data set alias = null;
> >> > Even after VACUUM this simple line takes 35 sec to complete.
> >>
> >> Would any rows already have a null alias when you run this?
> >> If so, try adding 'where alias is not null' to the query.
> >
> > This one initially added about 10sec to the run but I added a HASH
> > index on the alias field and its now about 5 sec average runtime, a
> > net improvement.
>
> Testing for null on 15,700 rows took five seconds more than the time
> saved from not updating some portion of the rows????? I've never
> seen anything remotely like that.
>
> Did you ever capture the output of VACUUM VERBOSE against this table
> (as Tom requested)?
>
> What happens if you run CLUSTER against this table before running one
> of these updates? (Be sure to do that VACUUM VERBOSE first, to see
> what the "old" state of the table was, and run it again after.)
>
> What is the row count from the second update of the table in your
> script? (An overly loose join there could bloat the table.)

here is the vacuum results:

vacuum verbose analyze shawns_data;
INFO: vacuuming "public.shawns_data"
INFO: scanned index "shawns_data_pkey" to remove 21444 row versions
DETAIL: CPU 0.24s/0.12u sec elapsed 8.35 sec.
INFO: scanned index "sd_l" to remove 21444 row versions
DETAIL: CPU 0.32s/0.16u sec elapsed 6.11 sec.
INFO: scanned index "sd_b" to remove 21444 row versions
DETAIL: CPU 0.34s/0.13u sec elapsed 10.10 sec.
INFO: scanned index "sd_s" to remove 21444 row versions
DETAIL: CPU 0.36s/0.13u sec elapsed 7.16 sec.
INFO: scanned index "sd_e" to remove 21444 row versions
DETAIL: CPU 0.40s/0.17u sec elapsed 6.71 sec.
INFO: scanned index "sd_alias_hash" to remove 21444 row versions
DETAIL: CPU 0.00s/0.01u sec elapsed 0.01 sec.
INFO: "shawns_data": removed 21444 row versions in 513 pages
DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "shawns_data_pkey" now contains 15445 row versions in
35230 pages DETAIL: 21444 index row versions were removed.
19255 index pages have been deleted, 19255 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "sd_l" now contains 15445 row versions in 32569 pages
DETAIL: 21444 index row versions were removed.
18059 index pages have been deleted, 18059 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "sd_b" now contains 15445 row versions in 34119 pages
DETAIL: 21444 index row versions were removed.
30276 index pages have been deleted, 30219 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "sd_s" now contains 15445 row versions in 35700 pages
DETAIL: 21444 index row versions were removed.
31284 index pages have been deleted, 31233 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "sd_e" now contains 15445 row versions in 42333 pages
DETAIL: 21444 index row versions were removed.
28828 index pages have been deleted, 28820 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "sd_alias_hash" now contains 10722 row versions in 298
pages DETAIL: 10722 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "shawns_data": found 21444 removable, 15445 nonremovable row
versions in 770 pages DETAIL: 0 dead row versions cannot be removed
yet. There were 5825 unused item pointers.
543 pages contain useful free space.
0 pages are entirely empty.
CPU 1.68s/0.77u sec elapsed 38.47 sec.
INFO: analyzing "public.shawns_data"
INFO: "shawns_data": scanned 770 of 770 pages, containing 15445 live
rows and 0 dead rows; 3000 rows in sample, 15445 estimated total rows
VACUUM


Shawn

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Shawn <postgres@xmtservices.net> writes:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote:
>> Did you ever capture the output of VACUUM VERBOSE against this table

> vacuum verbose analyze shawns_data;
> ...
> INFO: index "shawns_data_pkey" now contains 15445 row versions in
> 35230 pages

[ and comparably bloated sizes for other indexes ]

Ouch! The table itself doesn't look nearly as bad:

> INFO: "shawns_data": found 21444 removable, 15445 nonremovable row
> versions in 770 pages

but you've got a spectacularly bad case of index bloat. An index 50
times bigger than its table is Not Good. I think you'd find that
"REINDEX TABLE shawns_data" does wonders for the situation.

The next question is how it got to be that way... what is your
vacuuming policy for this database? Maybe you need to raise
max_fsm_pages?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

>>> On Mon, Sep 3, 2007 at 6:53 PM, in message
<20070903165334.0da769c1@boffin.xmtservices.net> , Shawn
<postgres@xmtservices.net> wrote:
> vacuum verbose analyze shawns_data;
> INFO: vacuuming "public.shawns_data"
> INFO: scanned index "shawns_data_pkey" to remove 21444 row versions
> DETAIL: CPU 0.24s/0.12u sec elapsed 8.35 sec.
> INFO: scanned index "sd_l" to remove 21444 row versions
> DETAIL: CPU 0.32s/0.16u sec elapsed 6.11 sec.
> INFO: scanned index "sd_b" to remove 21444 row versions
> DETAIL: CPU 0.34s/0.13u sec elapsed 10.10 sec.
> INFO: scanned index "sd_s" to remove 21444 row versions
> DETAIL: CPU 0.36s/0.13u sec elapsed 7.16 sec.
> INFO: scanned index "sd_e" to remove 21444 row versions
> DETAIL: CPU 0.40s/0.17u sec elapsed 6.71 sec.
> INFO: scanned index "sd_alias_hash" to remove 21444 row versions
> DETAIL: CPU 0.00s/0.01u sec elapsed 0.01 sec.
> INFO: "shawns_data": removed 21444 row versions in 513 pages
> DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "shawns_data_pkey" now contains 15445 row versions in
> 35230 pages DETAIL: 21444 index row versions were removed.
> 19255 index pages have been deleted, 19255 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "sd_l" now contains 15445 row versions in 32569 pages
> DETAIL: 21444 index row versions were removed.
> 18059 index pages have been deleted, 18059 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "sd_b" now contains 15445 row versions in 34119 pages
> DETAIL: 21444 index row versions were removed.
> 30276 index pages have been deleted, 30219 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "sd_s" now contains 15445 row versions in 35700 pages
> DETAIL: 21444 index row versions were removed.
> 31284 index pages have been deleted, 31233 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "sd_e" now contains 15445 row versions in 42333 pages
> DETAIL: 21444 index row versions were removed.
> 28828 index pages have been deleted, 28820 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: index "sd_alias_hash" now contains 10722 row versions in 298
> pages DETAIL: 10722 index row versions were removed.
> 0 index pages have been deleted, 0 are currently reusable.
> CPU 0.00s/0.00u sec elapsed 0.00 sec.
> INFO: "shawns_data": found 21444 removable, 15445 nonremovable row
> versions in 770 pages DETAIL: 0 dead row versions cannot be removed
> yet. There were 5825 unused item pointers.
> 543 pages contain useful free space.
> 0 pages are entirely empty.
> CPU 1.68s/0.77u sec elapsed 38.47 sec.

Those indexes are killing you. Hopefully you realize that each of those
indexes will have a new entry inserted whenever you update a row. If your
indexes are that expensive to maintain, you want to go out of your way
update rows only when something actually changes, which is not the case
for your second update statement yet.

I don't recall seeing the table definition yet. Could we see that, with
the indexes? Also, have you tried that CLUSTER yet? Syntax:

CLUSTER shawns_data_pkey ON shawns_data;
ANALYZE shawns_data;
(or VACUUM ANALYZE)

This will clean up index bloat.

-Kevin



---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

On Mon, 03 Sep 2007 21:10:06 -0400
Tom Lane <tgl@sss.pgh.pa.us> wrote:

> Shawn <postgres@xmtservices.net> writes:
> > You weren't kidding, that really made a difference. its .5 sec now
> > on the run. I think the vacuuming not running for a few weeks is
> > what got me. I caught an edit that had stopped the vacuuming
> > routine a while back. That must have been what caused the index
> > bloat.
>
> Hmm, but no vacuuming at all would have allowed the table itself to
> bloat too. Did you do a VACUUM FULL to recover after you noticed
> the size problem? The trouble with VACUUM FULL is it compresses the
> table but doesn't do a dang thing for indexes ...
>
> regards, tom lane
>

Thanks again to the list. I ran the reindex command that Tom suggested
and things seem to be holding. Even the vacuum command is running
faster. The whole script runs in about 10 seconds, far more acceptable.

Thanks Guys!

Shawn

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match