Thread: High CPU Usage - PostgreSQL 7.3

Hi,

I am running PostgreSQL 7.3 on a Linux box (RHEL 2.1 - Xeon 2.8GHz
with 1GB of RAM) and seeing very high CPU usage (normally over 90%)
when I am running the following queries, and the queries take a long
time to return; over an hour!

CREATE TEMPORARY TABLE fttemp1600384653 AS SELECT * FROM ftoneway LIMIT 0;

INSERT INTO fttemp1600384653 SELECT epId, TO_TIMESTAMP(start,
'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, 60 AS consolidation,
SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND start <
TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
HH24:00:00.0')::timestamp;

DELETE FROM ONLY ftone WHERE ftoneway.epId= fttemp1600384653.epId;

The only changes I've made to the default postgresql.comf file are listed below:

LC_MESSAGES = 'en_US'
LC_MONETARY = 'en_US'
LC_NUMERIC = 'en_US'
LC_TIME = 'en_US'
tcpip_socket = true
max_connections = 20
effective_cache_size = 32768
wal_buffers = 128
fsync = false
shared_buffers = 3000
max_fsm_relations = 10000
max_fsm_pages = 100000

The tables are around a million rows but when when I run against
tables of a few hundred thousand rows it still takes tens of minutes
with high CPU.  My database does have a lot of tables (can be several
thousand), can that cause performance issues?

Thanks,
    Neil

On Mon, 10 Jul 2006, Neil Hepworth wrote:

> I am running PostgreSQL 7.3 on a Linux box (RHEL 2.1 - Xeon 2.8GHz
> with 1GB of RAM) and seeing very high CPU usage (normally over 90%)
> when I am running the following queries, and the queries take a long
> time to return; over an hour!

First off, when is the last time you vacuum analyzed this DB and how often
does the vacuum analyze happen.  Please post the EXPLAIN ANALYZE output for
each of the queries below.

Also, I would strongly urge you to upgrade to a more recent version of
postgresql.  We're currently up to 8.1.4 and it has tons of excellent
performance enhancements as well as helpful features such as integrated
autovacuum, point in time recovery backups, etc.

Also, I see that you're running with fsync = false.  That's quite dangerous
especially on a production system.


>
> CREATE TEMPORARY TABLE fttemp1600384653 AS SELECT * FROM ftoneway LIMIT 0;
>
> INSERT INTO fttemp1600384653 SELECT epId, TO_TIMESTAMP(start,
> 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, 60 AS consolidation,
> SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND start <
> TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
> HH24:00:00.0')::timestamp;
>
> DELETE FROM ONLY ftone WHERE ftoneway.epId= fttemp1600384653.epId;
>
> The only changes I've made to the default postgresql.comf file are listed
> below:
>
> LC_MESSAGES = 'en_US'
> LC_MONETARY = 'en_US'
> LC_NUMERIC = 'en_US'
> LC_TIME = 'en_US'
> tcpip_socket = true
> max_connections = 20
> effective_cache_size = 32768
> wal_buffers = 128
> fsync = false
> shared_buffers = 3000
> max_fsm_relations = 10000
> max_fsm_pages = 100000
>
> The tables are around a million rows but when when I run against
> tables of a few hundred thousand rows it still takes tens of minutes
> with high CPU.  My database does have a lot of tables (can be several
> thousand), can that cause performance issues?
>
> Thanks,
>   Neil
>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: Have you checked our extensive FAQ?
>
>              http://www.postgresql.org/docs/faq
>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954

Thanks for the reply.

The database is vacuum analysed regularly and during my testing I
tried running the vacuum analyse full immediately before the running
through the set of queries (which does help a bit - reduces the time
to about 80% but is is still over an hour, with basically 100% CPU).

I'll get back to you with the full explain analyse output (I need to
re-create my test database back to its original state and that takes a
while) but I assume the part you're after is that all queries are
sequential scans, which I initially thought was the problem.  But it
is my understanding that I cannot make them index scans because a
large percentage of the table is being returned by the query
(typically 30%) so the planner will favour a sequential scan over an
index scan for such a query, correct?  If the queries had been disk
bound (due to retrieving large amounts of data) I would have
understood but I am confused as to why a sequential scan would cause
such high CPU and not high disk activity.

Yes, I wish I could upgrade to the latest version of PostgreSQL but at
the moment my hands are tied due to dependencies on other applications
running on our server (obviously we need to update certain queries,
e.g. delete .. using.. and test with 8.1 first) - I will be pushing
for an upgrade as soon as possible.  And the fsync=false is a
"compromise" to try to improve performance (moving to 8.1 would be
better compromise).

Neil


On 10/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
> On Mon, 10 Jul 2006, Neil Hepworth wrote:
>
> > I am running PostgreSQL 7.3 on a Linux box (RHEL 2.1 - Xeon 2.8GHz
> > with 1GB of RAM) and seeing very high CPU usage (normally over 90%)
> > when I am running the following queries, and the queries take a long
> > time to return; over an hour!
>
> First off, when is the last time you vacuum analyzed this DB and how often
> does the vacuum analyze happen.  Please post the EXPLAIN ANALYZE output for
> each of the queries below.
>
> Also, I would strongly urge you to upgrade to a more recent version of
> postgresql.  We're currently up to 8.1.4 and it has tons of excellent
> performance enhancements as well as helpful features such as integrated
> autovacuum, point in time recovery backups, etc.
>
> Also, I see that you're running with fsync = false.  That's quite dangerous
> especially on a production system.
>
>
> >
> > CREATE TEMPORARY TABLE fttemp1600384653 AS SELECT * FROM ftoneway LIMIT 0;
> >
> > INSERT INTO fttemp1600384653 SELECT epId, TO_TIMESTAMP(start,
> > 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, 60 AS consolidation,
> > SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND start <
> > TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
> > HH24:00:00.0')::timestamp;
> >
> > DELETE FROM ONLY ftone WHERE ftoneway.epId= fttemp1600384653.epId;
> >
> > The only changes I've made to the default postgresql.comf file are listed
> > below:
> >
> > LC_MESSAGES = 'en_US'
> > LC_MONETARY = 'en_US'
> > LC_NUMERIC = 'en_US'
> > LC_TIME = 'en_US'
> > tcpip_socket = true
> > max_connections = 20
> > effective_cache_size = 32768
> > wal_buffers = 128
> > fsync = false
> > shared_buffers = 3000
> > max_fsm_relations = 10000
> > max_fsm_pages = 100000
> >
> > The tables are around a million rows but when when I run against
> > tables of a few hundred thousand rows it still takes tens of minutes
> > with high CPU.  My database does have a lot of tables (can be several
> > thousand), can that cause performance issues?
> >
> > Thanks,
> >   Neil
> >
> > ---------------------------(end of broadcast)---------------------------
> > TIP 3: Have you checked our extensive FAQ?
> >
> >              http://www.postgresql.org/docs/faq
> >
> >
>
> --
> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
> Frost Consulting, LLC   http://www.frostconsultingllc.com/
> Phone: 650-780-7908     FAX: 650-649-1954
>

I should also explain that I run through these queries on multiple
tables and with some slightly different parameters for the
"consolidation" so I run through those 3 queries (or similar) 9 times
and this takes a total of about 2 hours, with high CPU usage.  And I
am running the queries from a remote Java application (using JDBC),
the client is using postgresql-8.0-311.jdbc3.jar.  The explain analyse
results I have provided below are from running via pgAdmin, not the
Java app (I did a vacuum analyse of the db before running them):


*** For the create ***:

-- Executing query:

BEGIN;
EXPLAIN ANALYZE CREATE TABLE fttemp1643 AS SELECT * FROM ftone LIMIT 0;
;
ROLLBACK;

ERROR:  parser: parse error at or near "CREATE" at character 25

Now that surprised me!  I hadn't done an explain on that query before
as it was so simple.  Perhaps not permitted for creates?  If I just
run the create:

-- Executing query:
CREATE TABLE fttemp1643 AS SELECT * FROM ftone LIMIT 0;


Query returned successfully with no result in 48 ms.



*** For the insert ***:

Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
  ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
time=16861.72..34243.63 rows=560094 loops=1)
        ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
(actual time=16861.62..20920.12 rows=709461 loops=1)
              ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
(actual time=16861.62..18081.07 rows=709461 loops=1)
                    Sort Key: eppairdefnid, "start"
                    ->  Seq Scan on ftone  (cost=0.00..36446.66
rows=234827 width=16) (actual time=0.45..10320.91 rows=709461 loops=1)
                          Filter: ((consolidation = 60) AND ("start" <
(to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
Total runtime: 55378.68 msec


*** For the delete ***:

Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
time=3767.47..3767.47 rows=0 loops=1)
  Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
  ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
(actual time=0.04..2299.94 rows=1286333 loops=1)
  ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
time=206.01..206.01 rows=0 loops=1)
        ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
width=4) (actual time=206.00..206.00 rows=0 loops=1)
Total runtime: 3767.52 msec


Thanks,
Neil

On 10/07/06, Neil Hepworth <nhepworth@gmail.com> wrote:
> Thanks for the reply.
>
> The database is vacuum analysed regularly and during my testing I
> tried running the vacuum analyse full immediately before the running
> through the set of queries (which does help a bit - reduces the time
> to about 80% but is is still over an hour, with basically 100% CPU).
>
> I'll get back to you with the full explain analyse output (I need to
> re-create my test database back to its original state and that takes a
> while) but I assume the part you're after is that all queries are
> sequential scans, which I initially thought was the problem.  But it
> is my understanding that I cannot make them index scans because a
> large percentage of the table is being returned by the query
> (typically 30%) so the planner will favour a sequential scan over an
> index scan for such a query, correct?  If the queries had been disk
> bound (due to retrieving large amounts of data) I would have
> understood but I am confused as to why a sequential scan would cause
> such high CPU and not high disk activity.
>
> Yes, I wish I could upgrade to the latest version of PostgreSQL but at
> the moment my hands are tied due to dependencies on other applications
> running on our server (obviously we need to update certain queries,
> e.g. delete .. using.. and test with 8.1 first) - I will be pushing
> for an upgrade as soon as possible.  And the fsync=false is a
> "compromise" to try to improve performance (moving to 8.1 would be
> better compromise).
>
> Neil
>
>
> On 10/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
> > On Mon, 10 Jul 2006, Neil Hepworth wrote:
> >
> > > I am running PostgreSQL 7.3 on a Linux box (RHEL 2.1 - Xeon 2.8GHz
> > > with 1GB of RAM) and seeing very high CPU usage (normally over 90%)
> > > when I am running the following queries, and the queries take a long
> > > time to return; over an hour!
> >
> > First off, when is the last time you vacuum analyzed this DB and how often
> > does the vacuum analyze happen.  Please post the EXPLAIN ANALYZE output for
> > each of the queries below.
> >
> > Also, I would strongly urge you to upgrade to a more recent version of
> > postgresql.  We're currently up to 8.1.4 and it has tons of excellent
> > performance enhancements as well as helpful features such as integrated
> > autovacuum, point in time recovery backups, etc.
> >
> > Also, I see that you're running with fsync = false.  That's quite dangerous
> > especially on a production system.
> >
> >
> > >
> > > CREATE TEMPORARY TABLE fttemp1600384653 AS SELECT * FROM ftoneway LIMIT 0;
> > >
> > > INSERT INTO fttemp1600384653 SELECT epId, TO_TIMESTAMP(start,
> > > 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, 60 AS consolidation,
> > > SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND start <
> > > TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
> > > HH24:00:00.0')::timestamp;
> > >
> > > DELETE FROM ONLY ftone WHERE ftoneway.epId= fttemp1600384653.epId;
> > >
> > > The only changes I've made to the default postgresql.comf file are listed
> > > below:
> > >
> > > LC_MESSAGES = 'en_US'
> > > LC_MONETARY = 'en_US'
> > > LC_NUMERIC = 'en_US'
> > > LC_TIME = 'en_US'
> > > tcpip_socket = true
> > > max_connections = 20
> > > effective_cache_size = 32768
> > > wal_buffers = 128
> > > fsync = false
> > > shared_buffers = 3000
> > > max_fsm_relations = 10000
> > > max_fsm_pages = 100000
> > >
> > > The tables are around a million rows but when when I run against
> > > tables of a few hundred thousand rows it still takes tens of minutes
> > > with high CPU.  My database does have a lot of tables (can be several
> > > thousand), can that cause performance issues?
> > >
> > > Thanks,
> > >   Neil
> > >
> > > ---------------------------(end of broadcast)---------------------------
> > > TIP 3: Have you checked our extensive FAQ?
> > >
> > >              http://www.postgresql.org/docs/faq
> > >
> > >
> >
> > --
> > Jeff Frost, Owner       <jeff@frostconsultingllc.com>
> > Frost Consulting, LLC   http://www.frostconsultingllc.com/
> > Phone: 650-780-7908     FAX: 650-649-1954
> >
>

On Mon, 10 Jul 2006, Neil Hepworth wrote:

> I should also explain that I run through these queries on multiple
> tables and with some slightly different parameters for the
> "consolidation" so I run through those 3 queries (or similar) 9 times
> and this takes a total of about 2 hours, with high CPU usage.  And I
> am running the queries from a remote Java application (using JDBC),
> the client is using postgresql-8.0-311.jdbc3.jar.  The explain analyse
> results I have provided below are from running via pgAdmin, not the
> Java app (I did a vacuum analyse of the db before running them):
>
>

Neil, did you ever answer which version of 7.3 this is?

BTW, you mentioned that this takes 2 hours, but even looping over this 9 times
seems like it would only take 9 minutes (55 seconds for the SELECT and 4
seconds for the DELETE = 59 seconds times 9).  Perhaps you should post the
explain analyze for the actual query that takes so long as the planner output
will likely be quite different.

One thing I noticed is that the planner seems quite incorrect about the number
of rows it expects in the SELECT.  If you ran vacuum analyze before this,
perhaps your fsm settings are incorrect?  What does vacuumdb -a -v output at
the end?  I'm looking for something that looks like this:

INFO:  free space map: 109 relations, 204 pages stored; 1792 total pages
needed
DETAIL:  Allocated FSM size: 1000 relations + 20000 pages = 182 kB shared
memory.

I see your fsm settings are non-default, so it's also possible I'm not used to
reading 7.3's explain analyze output. :-)

Also, what does vmstat output look like while the query is running?  Perhaps
you're running into some context switching problems.  It would be interesting
to know how the query runs on 8.1.x just to know if we're chasing an
optimization that's fixed already in a later version.


> Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
> width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
> ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
> time=16861.72..34243.63 rows=560094 loops=1)
>       ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
> (actual time=16861.62..20920.12 rows=709461 loops=1)
>             ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
> (actual time=16861.62..18081.07 rows=709461 loops=1)
>                   Sort Key: eppairdefnid, "start"
>                   ->  Seq Scan on ftone  (cost=0.00..36446.66
> rows=234827 width=16) (actual time=0.45..10320.91 rows=709461 loops=1)
>                         Filter: ((consolidation = 60) AND ("start" <
> (to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
> 'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
> Total runtime: 55378.68 msec

> *** For the delete ***:
>
> Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
> time=3767.47..3767.47 rows=0 loops=1)
> Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
> ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
> (actual time=0.04..2299.94 rows=1286333 loops=1)
> ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
> time=206.01..206.01 rows=0 loops=1)
>       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
> width=4) (actual time=206.00..206.00 rows=0 loops=1)
> Total runtime: 3767.52 msec

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954

On Sun, 2006-07-09 at 19:52, Neil Hepworth wrote:
> Hi,
>
> I am running PostgreSQL 7.3 on a Linux box (RHEL 2.1 - Xeon 2.8GHz
> with 1GB of RAM) and seeing very high CPU usage (normally over 90%)
> when I am running the following queries, and the queries take a long
> time to return; over an hour!
>
> CREATE TEMPORARY TABLE fttemp1600384653 AS SELECT * FROM ftoneway LIMIT 0;
>
> INSERT INTO fttemp1600384653 SELECT epId, TO_TIMESTAMP(start,
> 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, 60 AS consolidation,
> SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND start <
> TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
> HH24:00:00.0')::timestamp;

I don't need to see an explain analyze to make a guess here...

start < TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
HH24:00:00.0')::timestamp

is gonna be a problem because while you and I know that to_timestamp...
is gonna be a constant, pg 7.3 doesn't.  I've run into this before.

Just run a query ahead of time with a simple:

select TO_TIMESTAMP('2006-06-27 18:43:27.391103+1000', 'YYYY-MM-DD
HH24:00:00.0')::timestamp as starttime

and then pull that out and stick it into your query.  do the same for
any other parts of the query like that.

That's assuming the issue here is that you're getting seq scans cause of
that part of the query.

On Mon, Jul 10, 2006 at 17:55:38 +1000,
  Neil Hepworth <nhepworth@gmail.com> wrote:
>
> running on our server (obviously we need to update certain queries,
> e.g. delete .. using.. and test with 8.1 first) - I will be pushing
> for an upgrade as soon as possible.  And the fsync=false is a

You can set add_missing_from if you want to delay rewriting queries that
use that feature.

On Wed, 12 Jul 2006, Neil Hepworth wrote:

> I am using version PostgreSQL 7.3.10 (RPM:
> postgresql73-rhel21-7.3.10-2).  Unfortunately vacuumdb -a -v does not
> give the FSM info at the end (need a newer version of postgres for
> that).  Running the same queries on 8.1 reduces the time taken to
> about 16 minutes, though I didn't run the test on the same hardware or
> OS as I want to keep my test server as close to production as
> possible, so I ran the 8.1 server on my Windows laptop (2GHz Centrino
> Duo with 2GB of RAM, yes the laptop is brand new :).

Well, looks like you're at least fairly up to date, but there is a fix in
7.3.11 that you might want to get by upgrading to 7.3.15:

      * Fix race condition in transaction log management
        There was a narrow window in which an I/O operation could be
        initiated for the wrong page, leading to an Assert failure or data
        corruption.

It also appears that you can run autovacuum with 7.3 (I thought maybe it only
went back as far as 7.4).

So, is the 16 minutes on your laptop with 8.1 for windows vs 1hr on the server
for the whole set of loops?  If so, 4x isn't a bad improvement. :-)  So,
assuming you dumped/loaded the same DB onto your laptop's postgresql server,
what does the vacuumdb -a -v say on the laptop?  Perhaps we can use it to see
if your fsm settings are ok.

BTW, did you see Scott's posting here:

http://archives.postgresql.org/pgsql-performance/2006-07/msg00091.php

Since we didn't hear from you for a while, I thought perhaps Scott had hit on
the fix.  Have you tried that yet?  It certainly would help the planner out.

You might also want to turn on autovacuum and see if that helps.

What's your disk subsystem like?  In fact, what's the entire DB server
hardware like?

>
> I run through a loop, executing the following or similar queries 8
> times (well actually 12 but the last 4 don't do anything) - Jeff I've
> attached complete outputs as files.
>
> A debug output further below (numbers after each method call name,
> above each SQL statement, are times to run that statement in
> milliseconds, the times on the lines "" are cumulative).  So total for
> one loop is 515 seconds, multiple by 8 and that gets me to over an
> hour); it is actually the deletes that take the most time; 179 seconds
> and 185 seconds each loop.
>
>                 ----------------------------------------------------
>
> CREATE TABLE fttemp670743219 AS SELECT * FROM ftone LIMIT 0
> INSERT INTO fttemp670743219 ( epId, start, direction, classid,
> consolidation, cnt )  SELECT epId, TO_TIMESTAMP(start, 'YYYY-MM-DD
> HH24:00:00.0')::timestamp AS start, direction, classid, 60 AS
> consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND
> start < TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000', 'YYYY-MM-DD
> HH24:00:00.0')::timestamp GROUP BY epId, direction,
> TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp, classid
> DELETE FROM ONLY ftone WHERE ftone.epId = fttemp670743219.epId AND
> ftone.direction = fttemp670743219.direction AND ftone.start =
> fttemp670743219.start AND ftone.consolidation =
> fttemp670743219.consolidation AND ftone.classid =
> fttemp670743219.classid
> INSERT INTO ftone ( epId, start, consolidation, direction, classid,
> cnt ) SELECT epId, start, consolidation, direction, classid, cnt FROM
> fttemp670743219
> DROP TABLE fttemp670743219
> DELETE FROM ftone WHERE consolidation = 0 AND start <
> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000',
> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
> 'YYYY-MM-DD 00:00:00.0')::timestamp
>
>                 ----------------------------------------------------
>
> ftone: 0:
> createConsolidatedInTemporary: 188:
> CREATE TABLE fttemp678233382 AS SELECT * FROM ftone LIMIT 0
> createConsolidatedInTemporary: 76783:
> INSERT INTO fttemp678233382 ( epPairdefnid, start, direction, classid,
> consolidation, cnt )  SELECT epPairdefnid, TO_TIMESTAMP(start,
> 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, direction, classid, 60
> AS consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0
> AND start < TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
> 'YYYY-MM-DD HH24:00:00.0')::timestamp GROUP BY epPairdefnid,
> direction, TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp,
> classid
> replaceConsolidatedInMainTable: 179178:
> DELETE FROM ONLY ftone WHERE ftone.epPairdefnid =
> fttemp678233382.epPairdefnid AND ftone.direction =
> fttemp678233382.direction AND ftone.start = fttemp678233382.start AND
> ftone.consolidation = fttemp678233382.consolidation AND ftone.classid
> = fttemp678233382.classid
> replaceConsolidatedInMainTable: 61705:
> INSERT INTO ftone ( epPairdefnid, start, consolidation, direction,
> classid, cnt ) SELECT epPairdefnid, start, consolidation, direction,
> classid, cnt FROM fttemp678233382
> consolidate: 2656:
> DROP TABLE fttemp678233382
> MAIN LOOP TOTAL consolidate: 320526
> deleteOlderThan: 184616:
> DELETE FROM ftone WHERE consolidation = 0 AND start <
> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
> 'YYYY-MM-DD 00:00:00.0')::timestamp
> MAIN LOOP TOTAL deleteExpiredData: 505142
> MAIN LOOP TOTAL generateStatistics: 515611
>
>                 ----------------------------------------------------
>
> Thanks again,
>   Neil
>
>
> On 11/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
>>
>>
>> On Mon, 10 Jul 2006, Neil Hepworth wrote:
>>
>> > I should also explain that I run through these queries on multiple
>> > tables and with some slightly different parameters for the
>> > "consolidation" so I run through those 3 queries (or similar) 9 times
>> > and this takes a total of about 2 hours, with high CPU usage.  And I
>> > am running the queries from a remote Java application (using JDBC),
>> > the client is using postgresql-8.0-311.jdbc3.jar.  The explain analyse
>> > results I have provided below are from running via pgAdmin, not the
>> > Java app (I did a vacuum analyse of the db before running them):
>> >
>> >
>>
>> Neil, did you ever answer which version of 7.3 this is?
>>
>> BTW, you mentioned that this takes 2 hours, but even looping over this 9
>> times
>> seems like it would only take 9 minutes (55 seconds for the SELECT and 4
>> seconds for the DELETE = 59 seconds times 9).  Perhaps you should post the
>> explain analyze for the actual query that takes so long as the planner
>> output
>> will likely be quite different.
>>
>> One thing I noticed is that the planner seems quite incorrect about the
>> number
>> of rows it expects in the SELECT.  If you ran vacuum analyze before this,
>> perhaps your fsm settings are incorrect?  What does vacuumdb -a -v output
>> at
>> the end?  I'm looking for something that looks like this:
>>
>> INFO:  free space map: 109 relations, 204 pages stored; 1792 total pages
>> needed
>> DETAIL:  Allocated FSM size: 1000 relations + 20000 pages = 182 kB shared
>> memory.
>>
>> I see your fsm settings are non-default, so it's also possible I'm not used
>> to
>> reading 7.3's explain analyze output. :-)
>>
>> Also, what does vmstat output look like while the query is running?
>> Perhaps
>> you're running into some context switching problems.  It would be
>> interesting
>> to know how the query runs on 8.1.x just to know if we're chasing an
>> optimization that's fixed already in a later version.
>>
>>
>> > Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
>> > width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
>> > ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
>> > time=16861.72..34243.63 rows=560094 loops=1)
>> >       ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
>> > (actual time=16861.62..20920.12 rows=709461 loops=1)
>> >             ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
>> > (actual time=16861.62..18081.07 rows=709461 loops=1)
>> >                   Sort Key: eppairdefnid, "start"
>> >                   ->  Seq Scan on ftone  (cost=0.00..36446.66
>> > rows=234827 width=16) (actual time=0.45..10320.91 rows=709461 loops=1)
>> >                         Filter: ((consolidation = 60) AND ("start" <
>> > (to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
>> > 'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
>> > Total runtime: 55378.68 msec
>>
>> > *** For the delete ***:
>> >
>> > Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
>> > time=3767.47..3767.47 rows=0 loops=1)
>> > Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
>> > ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
>> > (actual time=0.04..2299.94 rows=1286333 loops=1)
>> > ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
>> > time=206.01..206.01 rows=0 loops=1)
>> >       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
>> > width=4) (actual time=206.00..206.00 rows=0 loops=1)
>> > Total runtime: 3767.52 msec
>>
>> --
>> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
>> Frost Consulting, LLC   http://www.frostconsultingllc.com/
>> Phone: 650-780-7908     FAX: 650-649-1954
>>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954

On Tue, 11 Jul 2006, Jeff Frost wrote:

> On Wed, 12 Jul 2006, Neil Hepworth wrote:
>
> You might also want to turn on autovacuum and see if that helps.
>
> What's your disk subsystem like?  In fact, what's the entire DB server
> hardware like?

By the way, how big does the temp table get?  If it's large, it might make the
DELETE slow because it doesn't have any indexes on any of the comparison
columns.

DELETE FROM ONLY ftone WHERE ftone.epId = fttemp670743219.epId AND
ftone.direction = fttemp670743219.direction AND ftone.start =
fttemp670743219.start AND ftone.consolidation = fttemp670743219.consolidation
AND ftone.classid = fttemp670743219.classid

In your explain analyze from before, it seems that there were 0 rows in that
table:

>       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
> width=4) (actual time=206.00..206.00 rows=0 loops=1)
> Total runtime: 3767.52 msec

but that was with the smaller set size I believe.

>
>>
>> I run through a loop, executing the following or similar queries 8
>> times (well actually 12 but the last 4 don't do anything) - Jeff I've
>> attached complete outputs as files.
>>
>> A debug output further below (numbers after each method call name,
>> above each SQL statement, are times to run that statement in
>> milliseconds, the times on the lines "" are cumulative).  So total for
>> one loop is 515 seconds, multiple by 8 and that gets me to over an
>> hour); it is actually the deletes that take the most time; 179 seconds
>> and 185 seconds each loop.
>>
>>                 ----------------------------------------------------
>>
>> CREATE TABLE fttemp670743219 AS SELECT * FROM ftone LIMIT 0
>> INSERT INTO fttemp670743219 ( epId, start, direction, classid,
>> consolidation, cnt )  SELECT epId, TO_TIMESTAMP(start, 'YYYY-MM-DD
>> HH24:00:00.0')::timestamp AS start, direction, classid, 60 AS
>> consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND
>> start < TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000', 'YYYY-MM-DD
>> HH24:00:00.0')::timestamp GROUP BY epId, direction,
>> TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp, classid
>> DELETE FROM ONLY ftone WHERE ftone.epId = fttemp670743219.epId AND
>> ftone.direction = fttemp670743219.direction AND ftone.start =
>> fttemp670743219.start AND ftone.consolidation =
>> fttemp670743219.consolidation AND ftone.classid =
>> fttemp670743219.classid
>> INSERT INTO ftone ( epId, start, consolidation, direction, classid,
>> cnt ) SELECT epId, start, consolidation, direction, classid, cnt FROM
>> fttemp670743219
>> DROP TABLE fttemp670743219
>> DELETE FROM ftone WHERE consolidation = 0 AND start <
>> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000',
>> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>> 'YYYY-MM-DD 00:00:00.0')::timestamp
>>
>>                 ----------------------------------------------------
>>
>> ftone: 0:
>> createConsolidatedInTemporary: 188:
>> CREATE TABLE fttemp678233382 AS SELECT * FROM ftone LIMIT 0
>> createConsolidatedInTemporary: 76783:
>> INSERT INTO fttemp678233382 ( epPairdefnid, start, direction, classid,
>> consolidation, cnt )  SELECT epPairdefnid, TO_TIMESTAMP(start,
>> 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, direction, classid, 60
>> AS consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0
>> AND start < TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>> 'YYYY-MM-DD HH24:00:00.0')::timestamp GROUP BY epPairdefnid,
>> direction, TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp,
>> classid
>> replaceConsolidatedInMainTable: 179178:
>> DELETE FROM ONLY ftone WHERE ftone.epPairdefnid =
>> fttemp678233382.epPairdefnid AND ftone.direction =
>> fttemp678233382.direction AND ftone.start = fttemp678233382.start AND
>> ftone.consolidation = fttemp678233382.consolidation AND ftone.classid
>> = fttemp678233382.classid
>> replaceConsolidatedInMainTable: 61705:
>> INSERT INTO ftone ( epPairdefnid, start, consolidation, direction,
>> classid, cnt ) SELECT epPairdefnid, start, consolidation, direction,
>> classid, cnt FROM fttemp678233382
>> consolidate: 2656:
>> DROP TABLE fttemp678233382
>> MAIN LOOP TOTAL consolidate: 320526
>> deleteOlderThan: 184616:
>> DELETE FROM ftone WHERE consolidation = 0 AND start <
>> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>> 'YYYY-MM-DD 00:00:00.0')::timestamp
>> MAIN LOOP TOTAL deleteExpiredData: 505142
>> MAIN LOOP TOTAL generateStatistics: 515611
>>
>>                 ----------------------------------------------------
>>
>> Thanks again,
>>   Neil
>>
>>
>> On 11/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
>>>
>>>
>>> On Mon, 10 Jul 2006, Neil Hepworth wrote:
>>>
>>> > I should also explain that I run through these queries on multiple
>>> > tables and with some slightly different parameters for the
>>> > "consolidation" so I run through those 3 queries (or similar) 9 times
>>> > and this takes a total of about 2 hours, with high CPU usage.  And I
>>> > am running the queries from a remote Java application (using JDBC),
>>> > the client is using postgresql-8.0-311.jdbc3.jar.  The explain analyse
>>> > results I have provided below are from running via pgAdmin, not the
>>> > Java app (I did a vacuum analyse of the db before running them):
>>> >
>>> >
>>>
>>> Neil, did you ever answer which version of 7.3 this is?
>>>
>>> BTW, you mentioned that this takes 2 hours, but even looping over this 9
>>> times
>>> seems like it would only take 9 minutes (55 seconds for the SELECT and 4
>>> seconds for the DELETE = 59 seconds times 9).  Perhaps you should post the
>>> explain analyze for the actual query that takes so long as the planner
>>> output
>>> will likely be quite different.
>>>
>>> One thing I noticed is that the planner seems quite incorrect about the
>>> number
>>> of rows it expects in the SELECT.  If you ran vacuum analyze before this,
>>> perhaps your fsm settings are incorrect?  What does vacuumdb -a -v output
>>> at
>>> the end?  I'm looking for something that looks like this:
>>>
>>> INFO:  free space map: 109 relations, 204 pages stored; 1792 total pages
>>> needed
>>> DETAIL:  Allocated FSM size: 1000 relations + 20000 pages = 182 kB shared
>>> memory.
>>>
>>> I see your fsm settings are non-default, so it's also possible I'm not
>>> used to
>>> reading 7.3's explain analyze output. :-)
>>>
>>> Also, what does vmstat output look like while the query is running?
>>> Perhaps
>>> you're running into some context switching problems.  It would be
>>> interesting
>>> to know how the query runs on 8.1.x just to know if we're chasing an
>>> optimization that's fixed already in a later version.
>>>
>>>
>>> > Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
>>> > width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
>>> > ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
>>> > time=16861.72..34243.63 rows=560094 loops=1)
>>> >       ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
>>> > (actual time=16861.62..20920.12 rows=709461 loops=1)
>>> >             ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
>>> > (actual time=16861.62..18081.07 rows=709461 loops=1)
>>> >                   Sort Key: eppairdefnid, "start"
>>> >                   ->  Seq Scan on ftone  (cost=0.00..36446.66
>>> > rows=234827 width=16) (actual time=0.45..10320.91 rows=709461 loops=1)
>>> >                         Filter: ((consolidation = 60) AND ("start" <
>>> > (to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
>>> > 'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
>>> > Total runtime: 55378.68 msec
>>>
>>> > *** For the delete ***:
>>> >
>>> > Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
>>> > time=3767.47..3767.47 rows=0 loops=1)
>>> > Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
>>> > ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
>>> > (actual time=0.04..2299.94 rows=1286333 loops=1)
>>> > ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
>>> > time=206.01..206.01 rows=0 loops=1)
>>> >       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
>>> > width=4) (actual time=206.00..206.00 rows=0 loops=1)
>>> > Total runtime: 3767.52 msec
>>>
>>> --
>>> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
>>> Frost Consulting, LLC   http://www.frostconsultingllc.com/
>>> Phone: 650-780-7908     FAX: 650-649-1954
>>>
>>
>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954

Please Cc: the list when replying to things like this so everyone can see (and
likely help).

I'm not sure what you're response is actually regarding.  Could you give some
more detail?

On Wed, 12 Jul 2006, Rizal wrote:

> so, i must upgrade my PostgreSQL 803 which i have with a new version ?
>
> ----- Original Message -----
> From: "Jeff Frost" <jeff@frostconsultingllc.com>
> To: "Neil Hepworth" <nhepworth@gmail.com>
> Cc: <pgsql-performance@postgresql.org>
> Sent: Wednesday, July 12, 2006 10:27 AM
> Subject: Re: [PERFORM] High CPU Usage - PostgreSQL 7.3
>
>
>> On Wed, 12 Jul 2006, Neil Hepworth wrote:
>>
>>> I am using version PostgreSQL 7.3.10 (RPM:
>>> postgresql73-rhel21-7.3.10-2).  Unfortunately vacuumdb -a -v does not
>>> give the FSM info at the end (need a newer version of postgres for
>>> that).  Running the same queries on 8.1 reduces the time taken to
>>> about 16 minutes, though I didn't run the test on the same hardware or
>>> OS as I want to keep my test server as close to production as
>>> possible, so I ran the 8.1 server on my Windows laptop (2GHz Centrino
>>> Duo with 2GB of RAM, yes the laptop is brand new :).
>>
>> Well, looks like you're at least fairly up to date, but there is a fix in
>> 7.3.11 that you might want to get by upgrading to 7.3.15:
>>
>>       * Fix race condition in transaction log management
>>         There was a narrow window in which an I/O operation could be
>>         initiated for the wrong page, leading to an Assert failure or data
>>         corruption.
>>
>> It also appears that you can run autovacuum with 7.3 (I thought maybe it
> only
>> went back as far as 7.4).
>>
>> So, is the 16 minutes on your laptop with 8.1 for windows vs 1hr on the
> server
>> for the whole set of loops?  If so, 4x isn't a bad improvement. :-)  So,
>> assuming you dumped/loaded the same DB onto your laptop's postgresql
> server,
>> what does the vacuumdb -a -v say on the laptop?  Perhaps we can use it to
> see
>> if your fsm settings are ok.
>>
>> BTW, did you see Scott's posting here:
>>
>> http://archives.postgresql.org/pgsql-performance/2006-07/msg00091.php
>>
>> Since we didn't hear from you for a while, I thought perhaps Scott had hit
> on
>> the fix.  Have you tried that yet?  It certainly would help the planner
> out.
>>
>> You might also want to turn on autovacuum and see if that helps.
>>
>> What's your disk subsystem like?  In fact, what's the entire DB server
>> hardware like?
>>
>>>
>>> I run through a loop, executing the following or similar queries 8
>>> times (well actually 12 but the last 4 don't do anything) - Jeff I've
>>> attached complete outputs as files.
>>>
>>> A debug output further below (numbers after each method call name,
>>> above each SQL statement, are times to run that statement in
>>> milliseconds, the times on the lines "" are cumulative).  So total for
>>> one loop is 515 seconds, multiple by 8 and that gets me to over an
>>> hour); it is actually the deletes that take the most time; 179 seconds
>>> and 185 seconds each loop.
>>>
>>>                 ----------------------------------------------------
>>>
>>> CREATE TABLE fttemp670743219 AS SELECT * FROM ftone LIMIT 0
>>> INSERT INTO fttemp670743219 ( epId, start, direction, classid,
>>> consolidation, cnt )  SELECT epId, TO_TIMESTAMP(start, 'YYYY-MM-DD
>>> HH24:00:00.0')::timestamp AS start, direction, classid, 60 AS
>>> consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND
>>> start < TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000', 'YYYY-MM-DD
>>> HH24:00:00.0')::timestamp GROUP BY epId, direction,
>>> TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp, classid
>>> DELETE FROM ONLY ftone WHERE ftone.epId = fttemp670743219.epId AND
>>> ftone.direction = fttemp670743219.direction AND ftone.start =
>>> fttemp670743219.start AND ftone.consolidation =
>>> fttemp670743219.consolidation AND ftone.classid =
>>> fttemp670743219.classid
>>> INSERT INTO ftone ( epId, start, consolidation, direction, classid,
>>> cnt ) SELECT epId, start, consolidation, direction, classid, cnt FROM
>>> fttemp670743219
>>> DROP TABLE fttemp670743219
>>> DELETE FROM ftone WHERE consolidation = 0 AND start <
>>> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000',
>>> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>>> 'YYYY-MM-DD 00:00:00.0')::timestamp
>>>
>>>                 ----------------------------------------------------
>>>
>>> ftone: 0:
>>> createConsolidatedInTemporary: 188:
>>> CREATE TABLE fttemp678233382 AS SELECT * FROM ftone LIMIT 0
>>> createConsolidatedInTemporary: 76783:
>>> INSERT INTO fttemp678233382 ( epPairdefnid, start, direction, classid,
>>> consolidation, cnt )  SELECT epPairdefnid, TO_TIMESTAMP(start,
>>> 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, direction, classid, 60
>>> AS consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0
>>> AND start < TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>>> 'YYYY-MM-DD HH24:00:00.0')::timestamp GROUP BY epPairdefnid,
>>> direction, TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp,
>>> classid
>>> replaceConsolidatedInMainTable: 179178:
>>> DELETE FROM ONLY ftone WHERE ftone.epPairdefnid =
>>> fttemp678233382.epPairdefnid AND ftone.direction =
>>> fttemp678233382.direction AND ftone.start = fttemp678233382.start AND
>>> ftone.consolidation = fttemp678233382.consolidation AND ftone.classid
>>> = fttemp678233382.classid
>>> replaceConsolidatedInMainTable: 61705:
>>> INSERT INTO ftone ( epPairdefnid, start, consolidation, direction,
>>> classid, cnt ) SELECT epPairdefnid, start, consolidation, direction,
>>> classid, cnt FROM fttemp678233382
>>> consolidate: 2656:
>>> DROP TABLE fttemp678233382
>>> MAIN LOOP TOTAL consolidate: 320526
>>> deleteOlderThan: 184616:
>>> DELETE FROM ftone WHERE consolidation = 0 AND start <
>>> TO_TIMESTAMP((TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>>> 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>>> 'YYYY-MM-DD 00:00:00.0')::timestamp
>>> MAIN LOOP TOTAL deleteExpiredData: 505142
>>> MAIN LOOP TOTAL generateStatistics: 515611
>>>
>>>                 ----------------------------------------------------
>>>
>>> Thanks again,
>>>   Neil
>>>
>>>
>>> On 11/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
>>>>
>>>>
>>>> On Mon, 10 Jul 2006, Neil Hepworth wrote:
>>>>
>>>>> I should also explain that I run through these queries on multiple
>>>>> tables and with some slightly different parameters for the
>>>>> "consolidation" so I run through those 3 queries (or similar) 9 times
>>>>> and this takes a total of about 2 hours, with high CPU usage.  And I
>>>>> am running the queries from a remote Java application (using JDBC),
>>>>> the client is using postgresql-8.0-311.jdbc3.jar.  The explain
> analyse
>>>>> results I have provided below are from running via pgAdmin, not the
>>>>> Java app (I did a vacuum analyse of the db before running them):
>>>>>
>>>>>
>>>>
>>>> Neil, did you ever answer which version of 7.3 this is?
>>>>
>>>> BTW, you mentioned that this takes 2 hours, but even looping over this
> 9
>>>> times
>>>> seems like it would only take 9 minutes (55 seconds for the SELECT and
> 4
>>>> seconds for the DELETE = 59 seconds times 9).  Perhaps you should post
> the
>>>> explain analyze for the actual query that takes so long as the planner
>>>> output
>>>> will likely be quite different.
>>>>
>>>> One thing I noticed is that the planner seems quite incorrect about the
>>>> number
>>>> of rows it expects in the SELECT.  If you ran vacuum analyze before
> this,
>>>> perhaps your fsm settings are incorrect?  What does vacuumdb -a -v
> output
>>>> at
>>>> the end?  I'm looking for something that looks like this:
>>>>
>>>> INFO:  free space map: 109 relations, 204 pages stored; 1792 total
> pages
>>>> needed
>>>> DETAIL:  Allocated FSM size: 1000 relations + 20000 pages = 182 kB
> shared
>>>> memory.
>>>>
>>>> I see your fsm settings are non-default, so it's also possible I'm not
> used
>>>> to
>>>> reading 7.3's explain analyze output. :-)
>>>>
>>>> Also, what does vmstat output look like while the query is running?
>>>> Perhaps
>>>> you're running into some context switching problems.  It would be
>>>> interesting
>>>> to know how the query runs on 8.1.x just to know if we're chasing an
>>>> optimization that's fixed already in a later version.
>>>>
>>>>
>>>>> Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
>>>>> width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
>>>>> ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
>>>>> time=16861.72..34243.63 rows=560094 loops=1)
>>>>>       ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
>>>>> (actual time=16861.62..20920.12 rows=709461 loops=1)
>>>>>             ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
>>>>> (actual time=16861.62..18081.07 rows=709461 loops=1)
>>>>>                   Sort Key: eppairdefnid, "start"
>>>>>                   ->  Seq Scan on ftone  (cost=0.00..36446.66
>>>>> rows=234827 width=16) (actual time=0.45..10320.91 rows=709461
> loops=1)
>>>>>                         Filter: ((consolidation = 60) AND ("start" <
>>>>> (to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
>>>>> 'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
>>>>> Total runtime: 55378.68 msec
>>>>
>>>>> *** For the delete ***:
>>>>>
>>>>> Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
>>>>> time=3767.47..3767.47 rows=0 loops=1)
>>>>> Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
>>>>> ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
>>>>> (actual time=0.04..2299.94 rows=1286333 loops=1)
>>>>> ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
>>>>> time=206.01..206.01 rows=0 loops=1)
>>>>>       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
>>>>> width=4) (actual time=206.00..206.00 rows=0 loops=1)
>>>>> Total runtime: 3767.52 msec
>>>>
>>>> --
>>>> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
>>>> Frost Consulting, LLC   http://www.frostconsultingllc.com/
>>>> Phone: 650-780-7908     FAX: 650-649-1954
>>>>
>>>
>>
>> --
>> Jeff Frost, Owner <jeff@frostconsultingllc.com>
>> Frost Consulting, LLC http://www.frostconsultingllc.com/
>> Phone: 650-780-7908 FAX: 650-649-1954
>>
>> ---------------------------(end of broadcast)---------------------------
>> TIP 4: Have you searched our list archives?
>>
>>                http://archives.postgresql.org
>>
>
>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954

On Wed, 12 Jul 2006, Neil Hepworth wrote:

> Yes, it was the same DB so, yes 8.1 gives roughly a four fold improvement
> (assuming hardware and OS differences aren't that significant - I'd expect
> the Linux version to be faster if anything); which certainly ain't bad! :)
>
> Good idea for the vacuumdb -a -v on the laptop, I re imported the database
> and than ran it output below:
>
> INFO:  free space map contains 949 pages in 537 relations
> DETAIL:  A total of 9024 page slots are in use (including overhead).
> 9024 page slots are required to track all free space.
> Current limits are:  20000 page slots, 1000 relations, using 186 KB.
> VACUUM

Well, this looks like it's probably on track already even though it'll change
as there are updates/deletes, but I suspect you're more or less ok with the
FSM settings you have.

>
> I am about to start testing Scott's suggestion now (thanks Scott - wasn't
> ignoring you, just didn't have time yesterday), and I'll get back with the
> results.
>
> Before I posted the problem to this list I was focusing more on the settings
> in postgresql.conf than optimising the query as I thought this might be a
> general problem, for all my DB updates/queries, with the way the planner was
> optimising queries; maybe assuming CPU cost was too cheap?  Do you think I
> was off track in my initial thinking?  Optimising these queries is
> certainly beneficial but I don't want postgres to hog the CPU for any
> extended period (other apps also run on the server), so I was wondering if
> the general config settings could to be tuned to always prevent this
> (regardless of how poorly written my queries are :)?
>

I guess you could nice the postmaster, on startup or renice after startup but
I'm not aware of any conf settings that would tune postgres to avoid using the
CPU.

> Neil
>
>
> On 12/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
>>
>> On Wed, 12 Jul 2006, Neil Hepworth wrote:
>>
>> > I am using version PostgreSQL 7.3.10 (RPM:
>> > postgresql73-rhel21-7.3.10-2).  Unfortunately vacuumdb -a -v does not
>> > give the FSM info at the end (need a newer version of postgres for
>> > that).  Running the same queries on 8.1 reduces the time taken to
>> > about 16 minutes, though I didn't run the test on the same hardware or
>> > OS as I want to keep my test server as close to production as
>> > possible, so I ran the 8.1 server on my Windows laptop (2GHz Centrino
>> > Duo with 2GB of RAM, yes the laptop is brand new :).
>>
>> Well, looks like you're at least fairly up to date, but there is a fix in
>> 7.3.11 that you might want to get by upgrading to 7.3.15:
>>
>>      * Fix race condition in transaction log management
>>        There was a narrow window in which an I/O operation could be
>>        initiated for the wrong page, leading to an Assert failure or data
>>        corruption.
>>
>> It also appears that you can run autovacuum with 7.3 (I thought maybe it
>> only
>> went back as far as 7.4).
>>
>> So, is the 16 minutes on your laptop with 8.1 for windows vs 1hr on the
>> server
>> for the whole set of loops?  If so, 4x isn't a bad improvement. :-)  So,
>> assuming you dumped/loaded the same DB onto your laptop's postgresql
>> server,
>> what does the vacuumdb -a -v say on the laptop?  Perhaps we can use it to
>> see
>> if your fsm settings are ok.
>>
>> BTW, did you see Scott's posting here:
>>
>> http://archives.postgresql.org/pgsql-performance/2006-07/msg00091.php
>>
>> Since we didn't hear from you for a while, I thought perhaps Scott had hit
>> on
>> the fix.  Have you tried that yet?  It certainly would help the planner
>> out.
>>
>> You might also want to turn on autovacuum and see if that helps.
>>
>> What's your disk subsystem like?  In fact, what's the entire DB server
>> hardware like?
>>
>> >
>> > I run through a loop, executing the following or similar queries 8
>> > times (well actually 12 but the last 4 don't do anything) - Jeff I've
>> > attached complete outputs as files.
>> >
>> > A debug output further below (numbers after each method call name,
>> > above each SQL statement, are times to run that statement in
>> > milliseconds, the times on the lines "" are cumulative).  So total for
>> > one loop is 515 seconds, multiple by 8 and that gets me to over an
>> > hour); it is actually the deletes that take the most time; 179 seconds
>> > and 185 seconds each loop.
>> >
>> >                 ----------------------------------------------------
>> >
>> > CREATE TABLE fttemp670743219 AS SELECT * FROM ftone LIMIT 0
>> > INSERT INTO fttemp670743219 ( epId, start, direction, classid,
>> > consolidation, cnt )  SELECT epId, TO_TIMESTAMP(start, 'YYYY-MM-DD
>> > HH24:00:00.0')::timestamp AS start, direction, classid, 60 AS
>> > consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0 AND
>> > start < TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000', 'YYYY-MM-DD
>> > HH24:00:00.0')::timestamp GROUP BY epId, direction,
>> > TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp, classid
>> > DELETE FROM ONLY ftone WHERE ftone.epId = fttemp670743219.epId AND
>> > ftone.direction = fttemp670743219.direction AND ftone.start =
>> > fttemp670743219.start AND ftone.consolidation =
>> > fttemp670743219.consolidation AND ftone.classid =
>> > fttemp670743219.classid
>> > INSERT INTO ftone ( epId, start, consolidation, direction, classid,
>> > cnt ) SELECT epId, start, consolidation, direction, classid, cnt FROM
>> > fttemp670743219
>> > DROP TABLE fttemp670743219
>> > DELETE FROM ftone WHERE consolidation = 0 AND start <
>> > TO_TIMESTAMP((TO_TIMESTAMP('2006-07-11 14:04:34.156433+1000',
>> > 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>> > 'YYYY-MM-DD 00:00:00.0')::timestamp
>> >
>> >                 ----------------------------------------------------
>> >
>> > ftone: 0:
>> > createConsolidatedInTemporary: 188:
>> > CREATE TABLE fttemp678233382 AS SELECT * FROM ftone LIMIT 0
>> > createConsolidatedInTemporary: 76783:
>> > INSERT INTO fttemp678233382 ( epPairdefnid, start, direction, classid,
>> > consolidation, cnt )  SELECT epPairdefnid, TO_TIMESTAMP(start,
>> > 'YYYY-MM-DD HH24:00:00.0')::timestamp AS start, direction, classid, 60
>> > AS consolidation, SUM(cnt) AS cnt FROM ftone WHERE consolidation = 0
>> > AND start < TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>> > 'YYYY-MM-DD HH24:00:00.0')::timestamp GROUP BY epPairdefnid,
>> > direction, TO_TIMESTAMP(start, 'YYYY-MM-DD HH24:00:00.0')::timestamp,
>> > classid
>> > replaceConsolidatedInMainTable: 179178:
>> > DELETE FROM ONLY ftone WHERE ftone.epPairdefnid =
>> > fttemp678233382.epPairdefnid AND ftone.direction =
>> > fttemp678233382.direction AND ftone.start = fttemp678233382.start AND
>> > ftone.consolidation = fttemp678233382.consolidation AND ftone.classid
>> > = fttemp678233382.classid
>> > replaceConsolidatedInMainTable: 61705:
>> > INSERT INTO ftone ( epPairdefnid, start, consolidation, direction,
>> > classid, cnt ) SELECT epPairdefnid, start, consolidation, direction,
>> > classid, cnt FROM fttemp678233382
>> > consolidate: 2656:
>> > DROP TABLE fttemp678233382
>> > MAIN LOOP TOTAL consolidate: 320526
>> > deleteOlderThan: 184616:
>> > DELETE FROM ftone WHERE consolidation = 0 AND start <
>> > TO_TIMESTAMP((TO_TIMESTAMP('2006-07-12 11:02:13.865444+1000',
>> > 'YYYY-MM-DD 00:00:00.0')::timestamp - INTERVAL '10080 MINUTE'),
>> > 'YYYY-MM-DD 00:00:00.0')::timestamp
>> > MAIN LOOP TOTAL deleteExpiredData: 505142
>> > MAIN LOOP TOTAL generateStatistics: 515611
>> >
>> >                 ----------------------------------------------------
>> >
>> > Thanks again,
>> >   Neil
>> >
>> >
>> > On 11/07/06, Jeff Frost <jeff@frostconsultingllc.com> wrote:
>> >>
>> >>
>> >> On Mon, 10 Jul 2006, Neil Hepworth wrote:
>> >>
>> >> > I should also explain that I run through these queries on multiple
>> >> > tables and with some slightly different parameters for the
>> >> > "consolidation" so I run through those 3 queries (or similar) 9 times
>> >> > and this takes a total of about 2 hours, with high CPU usage.  And I
>> >> > am running the queries from a remote Java application (using JDBC),
>> >> > the client is using postgresql-8.0-311.jdbc3.jar.  The explain
>> analyse
>> >> > results I have provided below are from running via pgAdmin, not the
>> >> > Java app (I did a vacuum analyse of the db before running them):
>> >> >
>> >> >
>> >>
>> >> Neil, did you ever answer which version of 7.3 this is?
>> >>
>> >> BTW, you mentioned that this takes 2 hours, but even looping over this
>> 9
>> >> times
>> >> seems like it would only take 9 minutes (55 seconds for the SELECT and
>> 4
>> >> seconds for the DELETE = 59 seconds times 9).  Perhaps you should post
>> the
>> >> explain analyze for the actual query that takes so long as the planner
>> >> output
>> >> will likely be quite different.
>> >>
>> >> One thing I noticed is that the planner seems quite incorrect about the
>> >> number
>> >> of rows it expects in the SELECT.  If you ran vacuum analyze before
>> this,
>> >> perhaps your fsm settings are incorrect?  What does vacuumdb -a -v
>> output
>> >> at
>> >> the end?  I'm looking for something that looks like this:
>> >>
>> >> INFO:  free space map: 109 relations, 204 pages stored; 1792 total
>> pages
>> >> needed
>> >> DETAIL:  Allocated FSM size: 1000 relations + 20000 pages = 182 kB
>> shared
>> >> memory.
>> >>
>> >> I see your fsm settings are non-default, so it's also possible I'm not
>> used
>> >> to
>> >> reading 7.3's explain analyze output. :-)
>> >>
>> >> Also, what does vmstat output look like while the query is running?
>> >> Perhaps
>> >> you're running into some context switching problems.  It would be
>> >> interesting
>> >> to know how the query runs on 8.1.x just to know if we're chasing an
>> >> optimization that's fixed already in a later version.
>> >>
>> >>
>> >> > Subquery Scan "*SELECT*"  (cost=59690.11..62038.38 rows=23483
>> >> > width=16) (actual time=16861.73..36473.12 rows=560094 loops=1)
>> >> > ->  Aggregate  (cost=59690.11..62038.38 rows=23483 width=16) (actual
>> >> > time=16861.72..34243.63 rows=560094 loops=1)
>> >> >       ->  Group  (cost=59690.11..61451.32 rows=234827 width=16)
>> >> > (actual time=16861.62..20920.12 rows=709461 loops=1)
>> >> >             ->  Sort  (cost=59690.11..60277.18 rows=234827 width=16)
>> >> > (actual time=16861.62..18081.07 rows=709461 loops=1)
>> >> >                   Sort Key: eppairdefnid, "start"
>> >> >                   ->  Seq Scan on ftone  (cost=0.00..36446.66
>> >> > rows=234827 width=16) (actual time=0.45..10320.91 rows=709461
>> loops=1)
>> >> >                         Filter: ((consolidation = 60) AND ("start" <
>> >> > (to_timestamp('2006-07-10 18:43:27.391103+1000'::text,
>> >> > 'YYYY-MM-DDHH24:00:00.0'::text))::timestamp without time zone))
>> >> > Total runtime: 55378.68 msec
>> >>
>> >> > *** For the delete ***:
>> >> >
>> >> > Hash Join  (cost=0.00..30020.31 rows=425 width=14) (actual
>> >> > time=3767.47..3767.47 rows=0 loops=1)
>> >> > Hash Cond: ("outer".eppairdefnid = "inner".eppairdefnid)
>> >> > ->  Seq Scan on ftone  (cost=0.00..23583.33 rows=1286333 width=10)
>> >> > (actual time=0.04..2299.94 rows=1286333 loops=1)
>> >> > ->  Hash  (cost=0.00..0.00 rows=1 width=4) (actual
>> >> > time=206.01..206.01 rows=0 loops=1)
>> >> >       ->  Seq Scan on fttemp1600384653  (cost=0.00..0.00 rows=1
>> >> > width=4) (actual time=206.00..206.00 rows=0 loops=1)
>> >> > Total runtime: 3767.52 msec
>> >>
>> >> --
>> >> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
>> >> Frost Consulting, LLC   http://www.frostconsultingllc.com/
>> >> Phone: 650-780-7908     FAX: 650-649-1954
>> >>
>> >
>>
>> --
>> Jeff Frost, Owner       <jeff@frostconsultingllc.com>
>> Frost Consulting, LLC   http://www.frostconsultingllc.com/
>> Phone: 650-780-7908     FAX: 650-649-1954
>>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954