Re: High CPU Usage - PostgreSQL 7.3

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(at)frostconsultingllc(dot)com>
Frost Consulting, LLC http://www.frostconsultingllc.com/
Phone: 650-780-7908 FAX: 650-649-1954