Thread: Help tracking down problem with inserts slowing down...
I need some help tracking down a sudden, massive slowdown
in inserts in one of our databases.
PG: 7.2.3 (RedHat 8.0)
Background. We currently run nearly identical systems
at two sites: Site A is a 'lab' site used for development,
Site B is a production site.
The databases in question have identical structure:
A simple table with 4 columns with a trigger function
on inserts (which checks to see if the entry already
exists, and if so, changes the insert into an update...)
A simple view with 4 columns into the above table.
All access is through jdbc (JDK 1.3.1, jdbc 7.1-1.3),
postgresql.conf's are identical.
The two sites were performing at comparable speeds until
a few days ago, when we deleted several million records
from each database and then did a vacuum full; analyze
on both. Now inserts at Site B are several orders of
magnitude slower than at Site A. The odd thing is that
Site B's DB now has only 60,000 records while Site A's is
up around 3 million. Inserts at A average 63ms, inserts
at B are now up at 4.5 seconds!
EXPLAIN doesn't show any difference between the two.
Can someone suggest ways to track this down? I don't know
much about postgresql internals/configuration.
Thanks!
Steve
--
Steve Wampler -- swampler@noao.edu
The gods that smiled on your birth are now laughing out loud.
Steve Wampler <swampler@noao.edu> writes:
> PG: 7.2.3 (RedHat 8.0)
You're using PG 7.2.3 with the PG 7.1 JDBC driver; FWIW, upgrading to
newer software is highly recommended.
> The two sites were performing at comparable speeds until a few days
> ago, when we deleted several million records from each database and
> then did a vacuum full; analyze on both. Now inserts at Site B are
> several orders of magnitude slower than at Site A.
Two thoughts:
(1) Can you confirm that the VACUUM FULL on site B actually
removed all the tuples you intended it to remove? Concurrent
transactions can limit the amount of data that VACUUM FULL is
able to reclaim. If you run contrib/pgstattuple (or compare
the database's disk consumption with the number of live rows
in it), you should be able to tell.
(2) Look at the EXPLAIN for the SELECTs generated by the ON INSERT
trigger -- is there any difference between site A and B?
-Neil
On Friday 05 December 2003 16:51, Steve Wampler wrote:
> I need some help tracking down a sudden, massive slowdown
> in inserts in one of our databases.
>
> PG: 7.2.3 (RedHat 8.0)
>
> Background. We currently run nearly identical systems
> at two sites: Site A is a 'lab' site used for development,
> Site B is a production site.
>
> The databases in question have identical structure:
>
> A simple table with 4 columns with a trigger function
> on inserts (which checks to see if the entry already
> exists, and if so, changes the insert into an update...)
> A simple view with 4 columns into the above table.
>
> All access is through jdbc (JDK 1.3.1, jdbc 7.1-1.3),
> postgresql.conf's are identical.
>
> The two sites were performing at comparable speeds until
> a few days ago, when we deleted several million records
> from each database and then did a vacuum full; analyze
> on both. Now inserts at Site B are several orders of
> magnitude slower than at Site A. The odd thing is that
> Site B's DB now has only 60,000 records while Site A's is
> up around 3 million. Inserts at A average 63ms, inserts
> at B are now up at 4.5 seconds!
>
> EXPLAIN doesn't show any difference between the two.
>
> Can someone suggest ways to track this down? I don't know
> much about postgresql internals/configuration.
>
What does explain analyze show for the insert query?
Are there FK and/or Indexes involved here? Did you you reindex?
A vacuum verbose could give you a good indication if you need to reindex,
compare the # of pages in the index with the # in the table.
Robert Treat
--
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL
On Fri, Dec 05, 2003 at 09:54:52PM -0500, Robert Treat wrote:
> On Friday 05 December 2003 16:51, Steve Wampler wrote:
> > I need some help tracking down a sudden, massive slowdown
> > in inserts in one of our databases.
> >
> > PG: 7.2.3 (RedHat 8.0)
> >
> > Background. We currently run nearly identical systems
> > at two sites: Site A is a 'lab' site used for development,
> > Site B is a production site.
> >
> > The databases in question have identical structure:
> >
> > A simple table with 4 columns with a trigger function
> > on inserts (which checks to see if the entry already
> > exists, and if so, changes the insert into an update...)
> > A simple view with 4 columns into the above table.
> >
> > All access is through jdbc (JDK 1.3.1, jdbc 7.1-1.3),
> > postgresql.conf's are identical.
> >
> > The two sites were performing at comparable speeds until
> > a few days ago, when we deleted several million records
> > from each database and then did a vacuum full; analyze
> > on both. Now inserts at Site B are several orders of
> > magnitude slower than at Site A. The odd thing is that
> > Site B's DB now has only 60,000 records while Site A's is
> > up around 3 million. Inserts at A average 63ms, inserts
> > at B are now up at 4.5 seconds!
> >
> > EXPLAIN doesn't show any difference between the two.
> >
> > Can someone suggest ways to track this down? I don't know
> > much about postgresql internals/configuration.
> >
>
> What does explain analyze show for the insert query?
>
> Are there FK and/or Indexes involved here? Did you you reindex?
> A vacuum verbose could give you a good indication if you need to reindex,
> compare the # of pages in the index with the # in the table.
Thanks Robert!
It looks like reindex did the trick.
Now I have a general question - what are the relationships between:
vacuum, analyze, reindex, and dropping/recreating the indices?
That is, which is the following is 'best' (or is there a different
ordering that is better)?:
(1) vacuum
analyze
reindex
(2) vacuum
reindex
analyze
(3) drop indices
vacuum
create indices
analyze
(4) drop indices
vacuum
analyze
create indices
And, is reindex equivalent to dropping, then recreating the indices?
[it appears to be "no", from what I've just seen, but I don't know...]
Thanks!
Steve
--
Steve Wampler -- swampler@noao.edu
The gods that smiled on your birth are now laughing out loud.
On Fri, Dec 05, 2003 at 09:54:52PM -0500, Robert Treat wrote:
>...
> A vacuum verbose could give you a good indication if you need to reindex,
> compare the # of pages in the index with the # in the table.
Hmmm, I have a feeling that's not as obvious as I thought... I can't
identify the index (named 'id_index') in the output of vacuum verbose.
The closest I can find is:
NOTICE: --Relation pg_index--
NOTICE: Pages 2: Changed 0, Empty 0; Tup 56: Vac 0, Keep 0, UnUsed 42.
Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
Which probably isn't correct, right (the name doesn't seem to match)?
The table's entry is:
NOTICE: --Relation attributes_table--
NOTICE: Pages 639: Changed 0, Empty 0; Tup 52846: Vac 0, Keep 0, UnUsed 48.
Total CPU 0.00s/0.01u sec elapsed 0.01 sec.
Thanks!
Steve
--
Steve Wampler -- swampler@noao.edu
The gods that smiled on your birth are now laughing out loud.
Steve Wampler <swampler@noao.edu> writes:
> Hmmm, I have a feeling that's not as obvious as I thought... I can't
> identify the index (named 'id_index') in the output of vacuum verbose.
In 7.2, the index reports look like
Index %s: Pages %u; Tuples %.0f.
and should appear in the part of the printout that deals with their
owning table.
regards, tom lane
On Fri, 2003-12-05 at 16:38, Neil Conway wrote:
>
> (1) Can you confirm that the VACUUM FULL on site B actually
> removed all the tuples you intended it to remove? Concurrent
> transactions can limit the amount of data that VACUUM FULL is
> able to reclaim. If you run contrib/pgstattuple (or compare
> the database's disk consumption with the number of live rows
> in it), you should be able to tell.
Hmmm, I installed 7.2.3 from RPMs, but the contrib package seems
to be missing the pgstattuple library code. (According to the
readme, I should do:
$ make
$ make install
$ psql -e -f /usr/local/pgsql/share/contrib/pgstattuple.sql test
but the first two lines don't make sense with the binary rpm
distribution and trying the last line as (for my world):
->psql -e -f /usr/share/pgsql/contrib/pgstattuple.sql
farm.devel.configdb
yields:
DROP FUNCTION pgstattuple(NAME);
psql:/usr/share/pgsql/contrib/pgstattuple.sql:1: ERROR:
RemoveFunction: function 'pgstattuple(name)' does not exist
CREATE FUNCTION pgstattuple(NAME) RETURNS FLOAT8
AS '$libdir/pgstattuple', 'pgstattuple'
LANGUAGE 'c' WITH (isstrict);
psql:/usr/share/pgsql/contrib/pgstattuple.sql:4: ERROR: stat failed
on file '$libdir/pgstattuple': No such file or directory
I don't need this right now (a reindex seems to have fixed
our problem for now...), but it sounds like it would be useful
in the future.
Thanks!
Steve
--
Steve Wampler -- swampler@noao.edu
The gods that smiled on your birth are now laughing out loud.
On Sun, 2003-12-07 at 09:52, Tom Lane wrote:
> Steve Wampler <swampler@noao.edu> writes:
> > Hmmm, I have a feeling that's not as obvious as I thought... I can't
> > identify the index (named 'id_index') in the output of vacuum verbose.
>
> In 7.2, the index reports look like
> Index %s: Pages %u; Tuples %.0f.
> and should appear in the part of the printout that deals with their
> owning table.
Thanks, Tom. Are there any reasons why it would not appear?:
-------------------------------------------------------------
farm.devel.configdb=# vacuum verbose attributes_table;
NOTICE: --Relation attributes_table--
NOTICE: Pages 1389: Changed 0, Empty 0; Tup 111358: Vac 0, Keep 0,
UnUsed 51.
Total CPU 0.00s/0.02u sec elapsed 0.03 sec.
NOTICE: --Relation pg_toast_1743942--
NOTICE: Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
VACUUM
farm.devel.configdb=# \d attributes_table
Table "attributes_table"
Column | Type | Modifiers
--------+--------------------------+---------------
id | character varying(64) | not null
name | character varying(64) | not null
units | character varying(32) |
value | text |
time | timestamp with time zone | default now()
Indexes: id_index
Primary key: attributes_table_pkey
Triggers: trigger_insert
---------------------------------------------------------------
The odd thing is that I could have sworn it appeared yesterday...
--
Steve Wampler -- swampler@noao.edu
The gods that smiled on your birth are now laughing out loud.
Steve Wampler <swampler@noao.edu> writes:
> Thanks, Tom. Are there any reasons why it would not appear?:
Oh, I shoulda read the code more carefully. I was looking at the bottom
of lazy_scan_index, where the printout is done, and failed to notice the
test at the top:
/*
* If the index is not partial, skip the scan, and just assume it has
* the same number of tuples as the heap.
*/
So for ordinary indexes, nothing will appear unless vacuum has actual
work to do (that is, it recycled at least one dead tuple in the table).
Short answer: update or delete some row in the table, and then try
vacuum verbose.
Alternatively, you can just look at the pg_class row for the index.
relpages and reltuples will contain the info you are after ... and
they are certainly up to date at this point ;-)
regards, tom lane