Re: High CPU Usage - PostgreSQL 7.3

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

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